Logs, the Prefect Way

Introducing Orion logging: A Pythonic logging system designed to maximize observability with a minimum of effort.

Simple logging that makes your application even more observable

We’ve released a new logging system for Prefect Orion, our second-generation workflow engine. We designed logging to be easy to use while allowing the customization that power users expect.

Read on to learn how to quickly add logging to your Orion flows! And for more details, check out our documentation.

Getting Started With Logging

As with all Python applications, logging in Orion starts with a logger. Specifically, you use the Orion run logger to log messages in a flow or task.

To get started, create a new run logger instance within your flow or task function and call it like a regular Python logger. Check out this example flow that tells the story of a dangerous moment in the life of a fictional starship. We’ll call it the Warp 9 flow.

https://gist.github.com/abrookins/98c4b3556098d93d065d6cf646fb2554

This flow only logs messages. The messages describe a series of events:

1. The starship prepares its warp drive.
2. An enemy vessel is detected.
3. The enemy vessel fires a torpedo.
4. The starship begins evasive maneuvers, but they fail, and the torpedo hits the ship.
5. Despite this, the warp drive engages, transporting the ship to safety (but is anywhere in the galaxy really safe?).

If you run this flow from a command line where you’ve installed Orion, you’ll see the following output:

$ python logging_flow.py
08:06:28.002 | INFO    | prefect.engine - Created flow run 'white-lyrebird' for flow 'warp-flow'
08:06:28.002 | INFO    | Flow run 'white-lyrebird' - Using task runner 'SequentialTaskRunner'
08:06:28.013 | INFO    | Flow run 'white-lyrebird' - Preparing for warp 9
08:06:28.013 | WARNING | Flow run 'white-lyrebird' - Enemy vessel detected
08:06:28.013 | WARNING | Flow run 'white-lyrebird' - Incoming photon torpedo
08:06:28.013 | ERROR   | Flow run 'white-lyrebird' - Evasive maneuvers failed!
08:06:28.013 | CRITICAL | Flow run 'white-lyrebird' - Fire detected in engine room!
08:06:28.013 | INFO    | Flow run 'white-lyrebird' - Warp drive engaged
08:06:28.013 | INFO    | Flow run 'white-lyrebird' - Traveled 1,442,442 km at warp 9
08:06:28.013 | INFO    | Flow run 'white-lyrebird' - Warp drive disengaged
08:06:28.025 | INFO    | Flow run 'white-lyrebird' - Finished in state Completed(None)

Let’s break down the parts of the Orion logging system that this output demonstrates.

• The standard Orion logging configuration emits log messages on the console and persists them so you can view them in the UI.
• The first log message is from Orion itself. Orion emits logs at various points, such as when Orion creates a flow run and when a flow run completes.
• Messages that the flow emitted using the run logger appear in the output alongside Orion’s flow run logs, using the same formatting.

Did you notice that the logging output does not include our DEBUG messages? That’s because Orion logs INFO level messages and above with the default logging configuration. However, the minimum log level is configurable, and we’ll describe exactly how to change it later in this post when we talk about configuration options.

Next, we’ll log messages from a more complex flow that uses tasks.

Logging in Tasks

Logging in tasks works the same way as logging in flows. Specifically, you create an instance of the run logger in the body of the task and use it as a standard Python logger.

To demonstrate, we’ll split apart the previous Warp 9 example into a flow that calls multiple tasks.

https://gist.github.com/abrookins/347228a4f59a5464c54d5f16c756b2a5

This example defines a flow with the function warp_flow(). When this flow executes, it calls three tasks:

1. Warm up warp drive
2. Evasive maneuvers
3. Engage warp 9

These tasks perform the same actions as our previous Warp 9 flow, but this time, an Orion task logs the messages instead of the flow.

Let’s see what the logging output looks like when we run this flow.

$ python logging_flow_with_tasks.py          
17:07:58.840 | INFO    | prefect.engine - Created flow run 'sticky-beluga' for flow 'Engage!'
17:07:58.840 | INFO    | Flow run 'sticky-beluga' - Using task runner 'SequentialTaskRunner'
17:07:58.874 | INFO    | Flow run 'sticky-beluga' - Created task run 'Warm up warp drive-8cd712e8-0' for task 'Warm up warp drive'
17:07:58.888 | INFO    | Task run 'Warm up warp drive-8cd712e8-0' - Preparing for warp 9
17:07:58.901 | INFO    | Task run 'Warm up warp drive-8cd712e8-0' - Finished in state Completed(None)
17:07:58.914 | INFO    | Flow run 'sticky-beluga' - Created task run 'Evasive maneuvers-9f194000-0' for task 'Evasive maneuvers'
17:07:58.924 | WARNING | Task run 'Evasive maneuvers-9f194000-0' - Enemy vessel detected
17:07:58.924 | WARNING | Task run 'Evasive maneuvers-9f194000-0' - Incoming photon torpedo
17:07:58.924 | ERROR   | Task run 'Evasive maneuvers-9f194000-0' - Evasive maneuvers failed!
17:07:58.924 | CRITICAL | Task run 'Evasive maneuvers-9f194000-0' - Fire detected in engine room!
17:07:58.937 | INFO    | Task run 'Evasive maneuvers-9f194000-0' - Finished in state Completed(None)
17:07:58.949 | INFO    | Flow run 'sticky-beluga' - Created task run 'Engage warp 9-a357c269-0' for task 'Engage warp 9'
17:07:58.965 | INFO    | Task run 'Engage warp 9-a357c269-0' - Warp drive engaged
17:07:58.965 | INFO    | Task run 'Engage warp 9-a357c269-0' - Traveled 1,442,442 km at warp 9
17:07:58.965 | INFO    | Task run 'Engage warp 9-a357c269-0' - Warp drive disengaged
17:07:58.977 | INFO    | Task run 'Engage warp 9-a357c269-0' - Finished in state Completed(None)
17:07:58.988 | INFO    | Flow run 'sticky-beluga' - Finished in state Completed('All states completed.')

You can see that this output now contains logs prefaced with “Task run” that use the same logging format as the flow run logs in our previous example.

Now that we’ve run a couple of flows let’s hop over to a browser to see how these logs show up in the Orion UI.

Viewing Logs in the Orion UI

Any logs that your flow runs and task runs emit will appear in the Orion UI. To view them, visit the page for a flow or task run and click the Logs button.

Log messages appear in a table that displays either the task run or flow run name, the logging level (e.g., INFO, WARNING), the time the flow emitted the log, and the log message.

Here are the logs for our fictional starship flow run with tasks.

You can filter logs by choosing the lowest logging level display. Filtering by log level lets you quickly see, for example, only WARNING logs and higher.

Next, let’s talk about how to configure Orion logging — we made sure you can customize everything about this system!

Powerful Customization

What if you want to configure the format of logged messages, or capture logging statements from libraries your flows and tasks use, like Dask? We have you covered. Anything you can configure with standard Python logging works for Orion logging.

You can accomplish most logging customizations with environment variables. For example, if you want to make sure Orion captures Dask logging statements with your flow and task run logs, use the PREFECT_LOGGING_EXTRA_LOGGERS environment variable.

You can specify one or more Python library names to include, separated by commas, like this:

$ export PREFECT_LOGGING_EXTRA_LOGGERS=dask,scipy

Another example: if you wanted to change the format of flow run logs, you could use the PREFECT_LOGGING_FORMATTERS_FLOW_RUNS variable, and pass it a Python logging format string.

But that’s not all! We’ve included a default logging configuration and exposed environment variables to tweak every logging setting. However, users who want to customize logging completely can do so by creating a custom logging configuration YAML file. Check our logging docs to see what’s possible.

Stay Tuned

We have a lot more features in the works for Orion, so stay tuned for more feature announcements. Follow us on Twitter, subscribe to our newsletter, or stop by our community Slack.

Happy engineering!