Logging

Logging is the practice of emitting log messages that describe what is happening in the system, or “events” in short. Log events can have varying degrees of severity, such as debug, info, warning, error or even critical. By default, Open Forms emits logs with level info and higher.

A collection of log events with a correlation ID (like a request or trace ID) allow one to reconstruct the chain of events that took place which lead to a particular outcome.

Open Forms emits structured logs in JSON format (unless explicitly configured otherwise), which should make log aggregation and analysis easier.

We try to keep a consistent log message structure, where the following keys are (usually) present:

source: The component in the application stack that produced the log entry. Typical values are uwsgi and app.
level: The severity level of the log message. One of debug, info, warning, error or critical.
timestamp: The moment when the log entry was produced, a string in ISO-8601 format. Most of the logs have microsecond precision, but some of them are limited to second precision.
event: The event that occurred, e.g. request_started or spawned worker (PID 123). This gives the semantic meaning to the log entry.

Other keys that frequently occur are:

request_id: Present for application logs emitted during an HTTP request, makes it possible to correlate multiple log entries for a single request. Not available in logs emitted by background tasks or logs emitted before/after the Open Forms app.
submission_uuid: If/when actions take place on or for a particular form submission, the UUID of that submission will be present in the metadata. Not available when there is no submission context.
module: An identifier for the module (feature-set) in Open Forms. Often used in conjunction with plugin.
plugin: When something happens in an Open Forms subsystem like authentication, prefill, registraton or appointments, the plugin instance responsible for the actual implementation will be present in the structured data.
action: Often present to group a set of log entries for a particular routine that’s being executed.
reason: Certain events like registration_skipped require more context to understand why the event occurred. We often include a key reason for this. Additionally, you may often find a key outcome.

Tip

Certain log aggregation solutions require you to configure “labels” to extract for efficient querying. You can use the above summary of log context keys to configure this according to your needs.

Note

We can not 100% guarantee that every log message will always be JSON due to limitations in third party software/packages that we use. Most (if not all) log aggregation technologies support handling both structured and unstructured logs.

Monitoring submission processing

We emit a number of events (values for the event key) that make it possible to monitor the processing of form submission. You can use this to build (Grafana) dashboards to support operations. The events are listed in chronological order as they’re normally emitted by the application. For each of these events, the submission_uuid log context key is guaranteed to be present. For most of the events (as soon as it’s available), we also provide the public_reference context key, which is the reference number communicated to the end-user.

submission_completed - the user confirmed the submission data on the final screen. This initiates background processing.
generate_submission_reference - emitted when there is no registration plugin for the submission.
completed, combined with action="registrations.pre_registration" - this marks the initial registration’s phase end. After this, we either obtained a public reference or one was generated by us.
registration_start - the main processing started. Log entries have the additional action="registrations.main_registration" context key, enriched with form (the display name of the form) and plugin (the programmatic registration plugin identifier).
registration_completed - emitted when there is no work to do (i.e. there is no plugin configured).
registration_failure - emitted in a number of failure situations, check the reason or exception information for more information.
registration_success - the plugin got a positive confirmation of the registration actions.
marked_payments_registered - in the event that we’re updating the payment status, this event will be emitted.
done - the main registration flow completed successfully.

At any stage, an unexpected crash may emit the registrations.error event.