Events and logging

A library that prints is a library you have to fight. xcl never writes to standard output or standard error, and never touches the standard library’s global logger. Instead, everything it and its plugins report, each step of the entity lifecycle, plugin discovery and loading, warnings, errors and the messages plugins log, is one stream of events delivered to the receiver set with xcl.WithEventHandler. With no receiver, xcl is silent.

Connecting to slog in one line

xcl ships an adapter to the standard library’s log/slog, so the quickest way to see the stream is one option:

c, err := xcl.NewConfig(
  xcl.WithEventHandler(events.SlogHandler(slog.Default())),
)
if err != nil {
  return err
}

import logging

import xcl

log = logging.getLogger("xcl")


def handler(event: xcl.Event) -> None:
    if event.error is not None:
        log.error("%s %s %s: %s", event.operation, event.phase, event.resource_id, event.error)
    else:
        log.info("%s %s %s", event.operation, event.phase, event.resource_id)


cfg = xcl.Config(on_event=handler)

In Python the handler is any callable taking an xcl.Event, passed as on_event; xcl.aio.Config accepts an async def handler as well, see the Python package.

events.SlogHandler takes any *slog.Logger, so the stream goes wherever the rest of your program’s logs go, in whatever format its handler writes. Log messages are written at their own level, with their own text. Lifecycle, discovery and load events are written at info, as <operation> <phase>, failures at error, and a blocked announcement at warn. Filtering is left to the slog handler’s level, so a logger at info writes no debug messages.

Each event’s fields become the attributes source, operation, phase, resource, type, file, duration and error, when they are set, followed by its details in key order.

The event

Every event is an xcl.Event, an alias of events.Event. There is one flat shape for all of them, whether it is xcl creating an entity or a plugin logging a message:

A log message’s level and text are in Meta, under the reserved keys events.KeyLevel (level) and events.KeyMessage (message). The level is one of debug, info, warn or error. The details a caller passes with a message are the other keys, under their own names, and never overwrite the reserved two.

To handle events yourself, EventHandler is a function that takes an event:

var failures []error

c, err := xcl.NewConfig(
  xcl.WithEventHandler(func(e xcl.Event) {
    if e.Phase == events.PhaseError {
      failures = append(failures, e.Error)
    }
  }),
)
if err != nil {
  return err
}

failures: list[xcl.Error] = []


def handler(event: xcl.Event) -> None:
    if event.phase == "error":
        failures.append(event.error)


cfg = xcl.Config(on_event=handler)

The Python xcl.Event carries the same fields as time, source, operation, phase, resource_type, resource_id, file, duration, error, data and meta, with a log message’s level and text as event.level and event.message.

Sensitive values in event data

Lifecycle events carry entity data only when you ask for it with xcl.WithEventData. When they do, every sensitive value in Data is written through the event masker. The default is mask.Redact(), which shows the marker inside an envelope naming the masker that produced it:

"password": {"xcl_masked": "redact", "value": "(sensitive)"}

Choose another masker with xcl.WithEventMask. A keyed hash lets a receiver tell whether two events carry the same value without ever seeing it:

eventMask, err := mask.HashHMACSHA256(correlationKey)
if err != nil {
  return err
}

c, err := xcl.NewConfig(
  xcl.WithEventHandler(handler),
  xcl.WithEventData(xcl.EventDataProcessed),
  xcl.WithEventMask(eventMask),
)

event_mask = xcl.mask.hmac_sha256(correlation_key)

cfg = xcl.Config(
    on_event=handler,
    event_data="processed",
    event_mask=event_mask,
)

Any masker works here, including the built-ins mask.Omit(), which writes no value, mask.EncryptAES256GCM(key) and your own. When every receiver is trusted with secrets, xcl.WithNoEventMask() turns masking off and event data carries the real values. When both options are given, the last one wins. In Python the options are event_data="none", "raw" or "processed", event_mask= with one of the xcl.mask built-ins, and no_event_mask=True.

Event masking changes only Data. Errors and log details always show (sensitive), whatever the event masker, because the sensitive type formats itself as the marker. A receiver holding a reversible masker can open a masked value with mask.Unmask(data, m); anything it cannot open faithfully, such as a hash, data from a different masker or data under a different key, fails with xcl.ErrUnrecoverable and returns no value. Event.Entity() and c.EncodeSavedEntity, event.entity() and cfg.encode_saved_entity in Python, show every masked value as (sensitive). In Python, cfg.encode_entity(event.entity()) turns the entity an event carries into configuration text directly; with reveal_sensitive=True it shows the engine’s current value, not the masked one, once the operation has finished.

To keep secrets out of the state file as well, see State masking.

Operations and phases

The operations and phases are defined as constants in the events package.

Each Validate, Apply and Destroy starts with its own start event and ends with a success, or an error carrying the error it returns. In between come the load events for any plugins loading, the parse events, and for each entity a start before each provider call, then any messages the provider logs during that call, with the call’s step as their operation, then the call’s success or error. Every failure that is returned is also emitted as an error event, including each problem validation finds.

This is how one entity looks through the example’s receiver, the plugin example creating a Docker network:

3:53PM INFO create start source=core operation=create phase=start resource=docker.network.app type=network.app file=config/full/main.xcl
3:53PM INFO created network source=docker-plugin operation=create phase=log resource=docker.network.app type=network.app file=config/full/main.xcl id=2f783968958bf8d9ee7914b98f809c0ced9b93509ad59946d0ff1f250f0c3764 name=app
3:53PM INFO create success source=core operation=create phase=success resource=docker.network.app type=network.app file=config/full/main.xcl duration=3.469262ms

Sources

Source says who is reporting. It is core, events.SourceCore, for everything xcl reports itself: the operations, parsing, loading and the lifecycle steps. A message a plugin logs carries the plugin’s name instead: the Go type name of an in-process plugin, such as TemplatePlugin, or the file name of an external plugin’s binary, such as docker-plugin. The messages go-plugin writes while it starts an external plugin carry that plugin’s name too, with the detail component=go-plugin so a receiver can tell them apart from the plugin’s own.

A plugin never sets these itself. How a plugin logs, and how its messages get their entity and step, is covered in Plugin logging and loading.

Delivery guarantees

• Ordered, one at a time. The receiver is called with one event at a time, in the order the events were emitted, never concurrently, on the goroutine that called Validate, Apply or Destroy. It needs no locking of its own.
• Never dropped. Emitting never waits for the receiver. Undelivered events are held in a bounded buffer, set with xcl.WithEventBufferSize (default xcl.DefaultEventBufferSize, 1024). When the buffer is full, emitting waits for the receiver to catch up rather than dropping an event.
• Blocking is announced. Once emitting can continue after waiting, the receiver is sent one event with the operation events and the phase blocked, whose Duration says how long it waited. A receiver that sees these is slower than the work it is watching.
• Delivered before return. Every event of a call has been delivered before Validate, Apply or Destroy returns, whether it succeeds or fails.

c, err := xcl.NewConfig(
  xcl.WithEventHandler(handler),
  // hold more undelivered events before emitting waits
  xcl.WithEventBufferSize(4096),
)
if err != nil {
  return err
}

cfg = xcl.Config(
    on_event=handler,
    # hold more undelivered events before emitting waits
    event_buffer_size=4096,
)

Errors and panics in the receiver

A receiver returns nothing, so it can not fail an operation, and the failures an operation returns reach it as error events as well as the returned error.

A panic in the receiver is not recovered. xcl starts no new provider call, lets the calls already in progress finish, and saves state, so nothing that was created is forgotten. Then the panic continues from Validate, Apply or Destroy with its original value and stack.

A pretty receiver

The examples share a receiver, example/prettylog, which shows how little an application needs. It is events.SlogHandler wrapped around a slog handler from charmbracelet/log, chosen for its readable, coloured terminal output. It is an example, not part of xcl, so it never becomes a dependency of an application that uses xcl. The Python tab shows the same receiver written with the standard library alone, colouring its lines with ANSI escapes.

func Handler(w io.Writer, level slog.Level) xcl.EventHandler {
  logger := charmlog.NewWithOptions(w, charmlog.Options{
    Level:           charmlog.Level(level),
    ReportTimestamp: true,
    TimeFormat:      time.Kitchen,
  })

  logger.SetStyles(styles())

  delegate := events.SlogHandler(slog.New(logger))
  // ...
}

import os
from typing import Callable, TextIO

import xcl

RANK = {"debug": 0, "info": 1, "warn": 2, "error": 3}
COLOUR = {"debug": "\033[90m", "info": "\033[36m", "warn": "\033[33m", "error": "\033[31m"}
RESET = "\033[0m"


def level_from_env() -> str:
    return os.environ.get("XCL_LOG_LEVEL", "info")


def handler(out: TextIO, level: str) -> Callable[[xcl.Event], None]:
    def handle(event: xcl.Event) -> None:
        if event.phase == "log":
            event_level, text = event.level, event.message
        elif event.phase == "error":
            event_level, text = "error", f"{event.operation} {event.phase}"
        else:
            event_level, text = "info", f"{event.operation} {event.phase}"
        if RANK.get(event_level, 1) < RANK.get(level, 1):
            return
        colour, reset = (COLOUR[event_level], RESET) if out.isatty() else ("", "")
        stamp = event.time.strftime("%I:%M%p").lstrip("0")
        out.write(f"{stamp} {colour}{event_level.upper()[:4]}{reset} {text} source={event.source}")
        # ...

    return handle

It also writes the configuration of each entity it sees created beneath the line reporting it. The event itself returns that entity, as the Go type registered for its block type, with Event.Entity(), and the receiver turns it back into configuration text with xcl.EncodeEntity, so it needs nothing from the application but event data at xcl.EventDataProcessed. When its writer shows colour it has xcl colour that configuration, rendering its highlight.Pieces with the terminal renderer highlight.ANSI, so the example has no highlighting code of its own. See Configuration text.

Every example sets it up in one line, writing to standard error at the level named by XCL_LOG_LEVEL, one of debug, info, warn or error, and info when it is unset:

  return prettylog.Handler(out, prettylog.LevelFromEnv())

    return prettylog.handler(out, prettylog.level_from_env())

A plugin that fails to load, here a Docker plugin path with no binary behind it, shows up as a load error and then fails the apply, while the in-process template plugin loads as usual:

3:53PM INFO apply start source=core operation=apply phase=start
3:53PM INFO load start source=core operation=load phase=start plugin=TemplatePlugin registry=local
3:53PM INFO load success source=core operation=load phase=success block_types=template plugin=TemplatePlugin registry=local
3:53PM INFO load start source=core operation=load phase=start plugin=missing registry=local
3:53PM ERRO load error source=core operation=load phase=error error="plugin missing from registry local failed to load: unable to start plugin binary ./build/missing: failed to get plugin client: fork/exec ./build/missing: no such file or directory" plugin=missing registry=local
3:53PM ERRO apply error source=core operation=apply phase=error duration=411.673µs error="plugin missing from registry local failed to load: unable to start plugin binary ./build/missing: failed to get plugin client: fork/exec ./build/missing: no such file or directory"

The one exception

xcl runs external plugins with HashiCorp’s go-plugin, and one message escapes the stream. When an external plugin is stopped within milliseconds of starting, go-plugin v1.6.3 writes this to standard error through the standard library’s global logger:

[ERR] plugin: plugin acceptAndServe error: broker closed

It is outside xcl’s control, and xcl deliberately does not change the global logger to hide it. The rest of what go-plugin reports reaches the stream as log events with component=go-plugin: its info and debug messages at debug, its warnings and errors at their own level.