.. _installation_observability_logging:

=======
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 :ref:`module <developers_backend_modules_index>`
    (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.

1. ``submission_completed`` - the user confirmed the submission data on the final
   screen. This initiates background processing.
2. ``generate_submission_reference`` - emitted when there is no registration plugin for
   the submission.
3. ``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.
4. ``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).
5. ``registration_completed`` - emitted when there is no work to do (i.e. there is no
   plugin configured).
6. ``registration_failure`` - emitted in a number of failure situations, check the
   ``reason`` or exception information for more information.
7. ``registration_success`` - the plugin got a positive confirmation of the registration
   actions.
8. ``marked_payments_registered`` - in the event that we're updating the payment status,
   this event will be emitted.
9. ``done`` - the main registration flow completed successfully.

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