Observability Python Library

Currently a POC in the Wilson team. Python library to aid consistent configuration of logging, metrics (future) and tracing (further in future). Packaging and wiring existing open tooling to work effortlessly on UIS DevOps managed cloud infrastructure.

ucam_observe integrates with gunicorn, django and plain Python projects. It expects that gunicorn is used to serve both Django and plain-python web app projects.

• Install this module
• Usage
  • Logging
    • Reserved log fields
  • Metrics and Tracing
• Environment Configuration
  • Log Level
  • Console Logging
  • Cloud Provider
  • Example Docker Compose Configuration
• Gunicorn setup
  • Adapt Gunicorn configuration
• Django project setup
  • Django Settings
  • Console Logging and DEBUG
  • External Settings and Environment Variables
• Testing your application's logging
  • Pytest support
    • Fixture structcaplog: ucam_observe.testing.StructuredLogCapturer
    • Fixture disabled_log_output: ucam_observe.testing.LogOutputDisabler
  • Testing APIs
    • ucam_observe.testing.capture_logs
    • ucam_observe.testing.disable_log_output
    • ucam_observe.testing.StructuredLogCapturer
  • Advice on testing logging
• Developing ucam_observe
  • Developer quickstart
  • Optional extras

Install this module

pip install ucam-observe          # For any python project
pip install ucam-observe[django]  # for django projects

Once installed:

• Web apps running in gunicorn must configure gunicorn
• Django projects must configure django

Usage

Logging

Usage is similar to using structlog directly with the function get_structlog_logger returning an object compatible with that returned by structlog's get_logger function. No further configuration is needed.

logger = get_structlog_logger(__name__)

logger.info("some_event")

logger.info("some_other_event", foo=bar)

Reserved log fields

ucam_observe sets a number of log fields itself, and it overwrites any data you log under the same names, so avoid using them for your own data:

Reserved field	Used for	What happens to your data
event	the event you log	It becomes the event
level	the log level	Always overwritten; removed in GCP
timestamp	the time you logged	Always overwritten; removed in GCP
filename, lineno, func_name	where you logged from	Always overwritten; removed in GCP
logger	the name of the logger you logged with	Always overwritten
process, thread	the process and thread you logged from	Always overwritten
exception	the traceback, when logging with .exception() or exc_info	Overwritten only when logging an exception
stack	the stack, when logging with stack_info=True	Overwritten only when logging a stack
severity	the log level, replacing level	Overwritten in GCP only
time	the time you logged, replacing timestamp	Overwritten in GCP only
logging.googleapis.com/sourceLocation	where you logged from, replacing the callsite fields	Overwritten in GCP only
httpRequest	the request being handled, replacing the request fields	Overwritten in GCP only, on request logs

"Removed in GCP" means the field isn't in the record at all when deployed in a GCP environment, because the GCP field that replaces it is built from ucam_observe's value. "Overwritten in GCP only" means the field is one of those replacements, so it's only set when deployed in GCP. See Cloud Provider.

Metrics and Tracing

raise NotImplemented

Environment Configuration

Log Level

Set the LOG_LEVEL environment variable to control the logging level (e.g., DEBUG, INFO, WARNING, ERROR, CRITICAL). This setting adjusts the verbosity of the log outputs:

export LOG_LEVEL=DEBUG

Console Logging

Set the CONSOLE_LOGGING environment variable to control whether logs should be output in a console-friendly or JSON format. JSON is used in production.

If it's not set, the default behaviour auto-selects (human-readable) console logging when running in an interactive console, and JSON when it's not. As a result, you shouldn't need to set CONSOLE_LOGGING, other than in specific situations, like when testing different outputs.

Set it to True to force console-friendly formatting, or False to force JSON output:

export CONSOLE_LOGGING=True

Cloud Provider

Set the CLOUD_PROVIDER environment variable to control which cloud provider's log format the log fields are tailored to. Currently gcp is the only supported provider.

If it's not set, the provider is detected from the environment variables that cloud providers set automatically. As a result you shouldn't need to set CLOUD_PROVIDER, other than when running somewhere the provider can't be detected — notably GKE, where it needs setting to gcp explicitly.

When no provider is set or detected, the log fields are not tailored to any provider. Set CLOUD_PROVIDER=none to force this, e.g. when logs are not being ingested by the provider's logging:

export CLOUD_PROVIDER=none

When deployed in GCP, the log records use the field names that GCP's logging recognises, so that they're presented as fields of the log entry in the Log Explorer rather than as part of the log entry's jsonPayload:

Default field	Field when deployed in GCP
level	severity, one of GCP's severities, which it matches case-insensitively
timestamp	time
filename, lineno, func_name	logging.googleapis.com/sourceLocation, an object of file, line and function
request, status/code, size, host/ip, agent/user_agent, referer, request_time_ms	httpRequest, an object describing the request

The remaining fields — including event, logger, process and thread — have no GCP equivalent, so they're unchanged and GCP reports them in the log entry's jsonPayload.

Only the log messages that contain a request field, and only from known request loggers, add an httpRequest field. Known loggers include gunicorn.access and django_structlog's django_structlog.middlewares.request. Other loggers are left unchanged.

Example Docker Compose Configuration

When using Docker Compose for local development, you can set the environment variables in your docker-compose.yml file:

services:
  your_service:
    build: .
    environment:
      LOG_LEVEL: "DEBUG"
      # Or, to allow the calling environment to override LOG_LEVEL:
      # LOG_LEVEL: "${LOG_LEVEL:-DEBUG}"

Gunicorn setup

Adapt Gunicorn configuration

In the root of your project, create/amend a gunicorn.conf.py. Add the following code to the file.

logger_class = "ucam_observe.gunicorn.UcamObserveLogger"

You don't have to set any other logging configuration options.

If you want to adjust the logging config, you can extend the default config like this:

import ucam_observe.gunicorn

logger_class = "ucam_observe.gunicorn.UcamObserveLogger"
logconfig_dict = {
    **(default_config := ucam_observe.gunicorn.get_gunicorn_dict_config()),
    "loggers": {
        **default_config["loggers"],
        "custom": {
            "level": "ERROR",
        },
    },
}

Django project setup

Django Settings

1. Include "ucam_observe" and "django_structlog" in INSTALLED_APPS
2. Include "django_structlog.middlewares.RequestMiddleware" in MIDDLEWARE
3. Set LOGGING_CONFIG to None (this disables django's builtin logging initialisation)
4. (Optional) modify LOGGING to extend ucam_observe's default logging config

LOGGING_CONFIG = None  # disable Django logging configuration in favour of ucam-observe

INSTALLED_APPS = [
    ...,
    "ucam_observe",
    "django_structlog",
]

MIDDLEWARE = [
    ...,
    "django_structlog.middlewares.RequestMiddleware",
]

Or if you want to modify the logging config:

from ucam_observe.django import get_django_dict_config

# use the `LOGGING` setting as normal, but extend the default config:
LOGGING = get_django_dict_config()
LOGGING["loggers"]["foo.bar"] = {"level": "ERROR"}

This disables Django default logging configuration behaviour and defers all logging configuration to ucam-observe. This ensures logging configuration is only configured once and the surplus default Django loggers are not added.

Console Logging and DEBUG

The Django convention is to log to the console when DEBUG=True. ucam_observe always logs to stdout/stderr and detects whether its running in an interactive console to switch between human-readable or JSON structured log output. See the Console logging section for details.

External Settings and Environment Variables

ucam_observe does not support environment variables from externalsettings, for example EXTERNAL_SETTING_LOG_LEVEL will not configure the logging level. Environment variables must be as documented above.

Testing your application's logging

ucam_observe can help you test the log output generated by your application. It allows tests to capture logs generated by application code, with access to the same structured data that gets emitted as JSON in production.

Pytest support

ucam_observe contains a pytest plugin that automatically provides:

Fixture structcaplog: ucam_observe.testing.StructuredLogCapturer

Provides log capturing tailored to ucam_observe, much like pytest's caplog. It holds lists of log records in three format variations on properties event_dicts, rendered_events and records. See StructuredLogCapturer for details.

Fixture disabled_log_output: ucam_observe.testing.LogOutputDisabler

This fixture is auto-used by tests, unless they are marked with pytest.mark.log_output_enabled. It prevents logs being written to stderr, in order to reduce noise in pytest's output when tests fail.

It doesn't prevent pytest's own log capturing or structcaplog from capturing, and pytest will still print details of logs emitted by a test if one fails. Without this, pytest's test failure details would contain each log message twice — once when showing the text written to stdout and once to show the logs pytest captured during a test.

To disable this per-test, mark the test with @pytest.mark.log_output_enabled. To disable for all tests in a module, assign the module global pytestmark = [pytest.mark.log_output_enabled]. To disable for all tests, use the same pytestmark assignment in a top-level conftest.py file.

Testing APIs

ucam_observe.testing.capture_logs

A context manager that captures the logs emitted while it's active. It holds lists of log records in three format variations on properties event_dicts, rendered_events and records. See StructuredLogCapturer for details.

ucam_observe.testing.disable_log_output

A context manager that stops ucam_observe writing logs to stdout while active. It doesn't prevent logs being captured by capture_logs().

ucam_observe.testing.StructuredLogCapturer

The type returned by capture_logs() and the structcaplog fixture.

It holds lists of log records in thee format variations that populate automatically as logs are emitted:

• event_dicts: A list ofdict objects containing the structured log events that will be formatted as JSON objects.
• rendered_events: A list of str containing the formatted event dicts as they will be written to stdout. These will either be in JSON or console format, depending on the CONSOLE_LOGGING envar.
• records: A list oflogging.LogRecord objects.

Advice on testing logging

• Focus on testing your own application's logging behaviour, don't slip into testing behaviour that ucam_observe is responsible for (in the same way you wouldn't test the correctness of your HTTP client library).
• Use event_dicts to make assertions about logged events. They are consistent for logs emitted by structlog and by stdlib logging.
  • Whereas the records list's logging.LogRecord.msg values hold str for stdlib and dict for structlog logs.
• Asserting about event dicts can be verbose and overly-specific, which can result in tests that are hard to maintain, understand and prone to breaking.
  • Consider using an assertion/matcher library to reduce boilerplate code and avoid brittle assertions about unimportant log event details.
  • ucam_observe itself uses the pychoir matcher library for this purpose, see the django tests for an example.

---

Developing ucam_observe

Everything below is for developers working on ucam_observe itself, people using the library can ignore this.

Developer quickstart

Firstly, install docker-compose.

Install poethepoet

pip install poethepoet

Then, most tasks can be performed via the poe command.

E.g.

# Build the containers
$ poe build

Run the follow command to see available commands:

$ poe

Optional extras

This library includes optional extras, e.g. ucam-observe[django]. Some tests will require these optional dependencies to pass. The following command will install all optional dependencies.

$ poetry install --all-extras --with django-dev

Some tests require the absence of dependencies and these are excluded by default. See the tox.ini file for how these tests are run.