Plugin logging and loading

A provider logs a message and nothing else. xcl adds the plugin, the entity and the step, the same for in-process and external plugins, and loads plugins only when they are first needed.

Plugins never write output. Everything a plugin logs becomes an event on the same stream as xcl’s own, delivered to the application’s receiver, so a plugin’s messages sit between the lifecycle events of the call they were logged in. How that stream works is covered in Events and logging. This page is for plugin authors, and for the applications that register their plugins.

Plugins are written in Go for now. A plugin that logs this way works from both Go and Python applications, and its log messages reach a Python on_event handler as the same events.

Logging from a provider

A provider logs through plugins.Logger(ctx), the logger in the context of the call it is handling. It has the familiar Debug, Info, Warn and Error methods, each taking a message and key/value details:

example/plugin/plugins/docker/providers/network.go
// Create asks Docker for a labelled bridge network named after the block, and
// records the ID Docker gives it
func (p *networkProvider) Create(ctx context.Context, n *entities.Network) (*entities.Network, error) {
  id, err := p.tasks.CreateNetwork(ctx, n.Meta.Name, containers.NetworkSpec{
    Subnet: n.Subnet,
    Labels: labels(n.Meta),
  })
  if err != nil {
    return nil, fmt.Errorf("unable to create network %s: %w", n.Meta.Name, err)
  }


  n.DockerID = id
  plugins.Logger(ctx).Info("created network", "name", n.Meta.Name, "id", n.DockerID)


  return n, nil
}

Keep no logger on the provider. Providers are called concurrently for different entities, and each call carries its own logger in its context. Outside a provider call, plugins.Logger(ctx) returns a logger that emits nothing.

What a provider does keep is what every call shares. The Docker plugin builds one Docker client in Init, wraps it once in its container task layer and gives that to its providers, so networkProvider holds that containers.Tasks and takes only the logger from the call’s context. The message it logs is its own: the network’s name and the ID Docker gave it.

The same care applies to any value a provider logs. Logging a types.Sensitive field is safe, it writes (sensitive), but a value unwrapped with Reveal() is no longer protected and must never be logged. See Sensitive values.

The entity and step come for free

Before each call, xcl binds the context’s logger to the entity being worked on, its type, the file it was declared in and the step, create, read, changed, update or destroy. It also names the plugin as the event’s source: the Go type name of an in-process plugin, or the file name of an external plugin’s binary. The provider passes none of it.

So the one-line Info above arrives between the call’s start and its success, carrying everything a reader needs to place it. Through the examples’ receiver it looks like this:

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

The message is in the event’s Meta under message, its level under level, and the provider’s own details under their own names.

In-process and external plugins

A provider logs the same way whether its plugin is compiled into the program or runs as a separate binary over gRPC. The network provider above is in the example’s Docker plugin, an external plugin running in its own process. Inside an external plugin, plugins.Logger(ctx) sends each message back to the host, tagged with the call it belongs to, and the host gives it that call’s entity, step and receiver, so it arrives exactly where an in-process message would.

The example’s template plugin, TemplatePlugin, is compiled into the program, and its provider logs in exactly the same way:

example/plugin/plugins/template/template.go
// Create renders the template with its variables and writes the result to the
// destination
func (p *provider) Create(ctx context.Context, t *Template) (*Template, error) {
  err := render(t)
  if err != nil {
    return nil, err
  }


  plugins.Logger(ctx).Info("rendered template", "destination", t.Destination)


  return t, nil
}

The two messages arrive alike, each with its call’s entity, type, file and step, and only the source tells them apart: docker-plugin, the file name of the external binary, and TemplatePlugin, the Go type name of the in-process plugin:

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 rendered template source=TemplatePlugin operation=create phase=log resource=template.welcome type=template.welcome file=config/full/main.xcl destination=./build/rendered/welcome.txt

One difference to know about: details cross the process boundary as text. The host turns them back into integers, floats and booleans where they parse as one, so a detail logged by an external plugin may not keep its original Go type. A receiver that needs an exact type should not rely on it for external plugins.

The Init logger

Init runs when the plugin loads, before any provider call, so it has no call context. The logger it receives is plugin scoped instead: its messages carry the plugin as their source and load as their operation, and no entity. Use it for messages written outside a call, and pass it on to RegisterResourceProvider, which hands it to each provider’s Init. For an in-process plugin, that copy adds a provider detail to what the provider logs, naming the block subtype, or the block type when it has no subtype, as template has none.

example/plugin/plugins/template/plugin.go
func (p *TemplatePlugin) Init(logger logger.Logger, state plugins.State) error {
  logger.Debug("registering block types", "block_types", "template")
example/plugin/plugins/template/template.go
// Init logs that the provider is ready, it needs nothing else
func (p *provider) Init(state plugins.State, functions plugins.ProviderFunctions, log logger.Logger) error {
  log.Debug("provider ready")
  return nil
}

At debug, the in-process template plugin shows both, between its load start and load success:

3:53PM INFO load start source=core operation=load phase=start plugin=TemplatePlugin
3:53PM DEBU registering block types source=TemplatePlugin operation=load phase=log block_types=template
3:53PM DEBU provider ready source=TemplatePlugin operation=load phase=log provider=template
3:53PM INFO load success source=core operation=load phase=success block_types=template plugin=TemplatePlugin

In an external plugin, Init runs before the host has connected, so the plugin scoped logger sends each message once the connection is there. Those messages may arrive out of order, and are dropped if the host can not be reached. Logging never changes the outcome of a call. The Docker plugin’s Init logs the same two kinds of message, and in the same run they arrive after its load success, among the parse events, with the providers’ provider ready before the plugin’s own message. They carry no provider= detail, which is only added in-process (trimmed to the plugin’s messages):

3:53PM DEBU provider ready source=docker-plugin operation=load phase=log
3:53PM DEBU provider ready source=docker-plugin operation=load phase=log
3:53PM DEBU registering block types source=docker-plugin operation=load phase=log block_types="docker.network, docker.container"

Registering plugins

Plugins come from registries. The local registry holds the plugins an application supplies itself, and registering a plugin only records it:

main.go
local := registry.NewLocal()
local.RegisterPlugin(&MyPlugin{})                 // an in-process plugin
local.RegisterExternalPlugin("./bin/xcl-plugin-x") // an external plugin binary
local.RegisterPluginDirectory("~/.xcl/plugins")    // a directory to search


c, err := xcl.NewConfig(xcl.WithRegistry(local))
main.py
# an in-process plugin has no Python form: Python loads Go plugins as external binaries
local = xcl.LocalRegistry()
local.register_external_plugin("./bin/xcl-plugin-x")  # an external plugin binary
local.register_plugin_directory("~/.xcl/plugins")     # a directory to search


cfg = xcl.Config(registries=[local])

None of them starts, checks or searches anything, and none returns an error. Several registries, the order they load in, and writing a registry of your own are covered in Registries.

Loading when first needed

Plugins load at the start of the first Validate, Apply, Destroy, Diff or Load, and only once per Config. An external plugin’s process runs only while an operation is using it: xcl starts it for each operation and stops it when the operation is done. Searching a plugin directory is reported as discover events, and each plugin starting and being checked as load events naming the plugin and its registry, before the operation parses anything:

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=docker-plugin registry=local
3:53PM INFO load success source=core operation=load phase=success block_types="docker.network, docker.container" plugin=docker-plugin registry=local

When a plugin fails to load

Any plugin that fails to load fails that first operation, whether it was registered by name or found in a plugin directory. A path with no binary behind it, or a discovered file that is not a plugin, both fail the load with an error matching xcl.ErrPluginLoad. Its detail, *xcl.PluginLoadError, names the plugin in Plugin, the registry it came from in Registry, and the reason in Err. Plugin is empty when the registry itself could not provide its plugins, such as a plugin directory that could not be read. In Python the same failure raises xcl.PluginLoadError, whose details carry plugin and registry.

example/plugin/main.go
func explainPluginLoad(err error) error {
  if errors.Is(err, xcl.ErrPluginLoad) {
    return fmt.Errorf("%w, build it with `make build` in example/plugin", err)
  }


  return err
}
try:
    cfg.apply(path)
except xcl.PluginLoadError as err:
    raise SystemExit(f"{err}, build it with `make build` in example/plugin")

Run as xcl-docker apply --plugin ./build/missing ./config/full, a Docker plugin path with no binary behind it, the example reports:

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, build it with `make build` in example/plugin

Type name clashes

Every block type name is unique across xcl’s builtins, the Go types registries declare and the types plugins provide. When a clash is found depends on what can be known at the time:

  • Declared types are known when the Config is created, so a declared type that clashes is an error returned by NewConfig. Declaring the same type twice, in one registry or across two, or a builtin’s name, is a *xcl.TypeNameClashError naming both Go types and their registries.
  • A plugin’s types are only known once it loads, so a plugin type whose name clashes fails the load, and the operation that loaded it, with a *xcl.TypeNameClashError. It names both providers and the registries they came from. There is no precedence between plugins or registries, whichever order they were given in.

See it run

The plugins example logs from an in-process template plugin and an external Docker plugin, through one pretty receiver.

Plugins example →Events and logging →