Improving Dagster's logging

[sryza]

The Problem

Dagster expects developers to go to the structured log viewer to see logs for the code that executes inside their solids. If a developer wants to get a record to show up in the structured log viewer, they need to invoke context.log. This causes some problems:

• Output from libraries that use the Python logging system is difficult to find in Dagit.
• Code that wasn't originally written for Dagster needs to be modified to be "Dagster-compatible" by replacing all log statements with context.log.
• The context object needs to be threaded to every function that wants to be able to log.
• It’s kind of annoying to need to type an extra eight characters (context.) every time you want to log something.

Use the Python logging API instead of our custom context loggers is our 7th-most upvoted Github issue.

Potential Solutions

So what do we do? Ultimately a logging system needs to answer two questions:

• Where do I go to find my logs?
• How do I log?

Option: Raw Logs

In this world, logs are unstructured text, captured per process. Users log by writing to stdout, and they access their logs from an interface that looks like the current “Raw Step Logs” interface.

Pros

• Automatically works for any logs written by any logging framework in any language.

Cons

• No easy way to visually see where logs occur in time - e.g. to line up log statements with positions in the gantt chart.
• No easy way to tie logs to particular substages in the step (load_input, solid body, type check, handle_output).
• No clear place to include structured metadata.
• Ultimately it's a regression in log readability for users who were comfortable using context.log for all their logs.

Required Changes

• Update all examples to use Python logging or print statements, instead of context.log.
• Deprecate context.log.
• Default to the raw log instead of the event log in the Dagit runs view.

Option: Independent Raw and Structured Logs - Python Logging Integration

In this world, some logs have structure. We have separate views for the structured logs and the unstructured logs. Users are encouraged to log by using the Python logging library, which will result in entries in the structured log.

Pros:

• For users who can do all their logging from the Python logging library, a nicer user experience than raw logs.
  • Can see the boundaries between log statements
  • Can tie logs to particular substages in the step (load_input, solid body, type check, handle_output).
  • Can line up log statements with positions in the gantt chart.

Cons

• If user code logs to stdout instead of using the logging library, there is no clear answer to where they should go to view their logs. The structured log will be incomplete, and the unstructured log will be a worse experience. We won’t even have enough information to tell them whether the structured log contains all their logs.

Required Changes:

• Find a way to capture Python logging and direct it to the Dagster structured log.
• Find a way to make it scalable to capture all Python logging logs - eventually will probably mean storing logs outside of the DB.

Option: Interleaved Raw and Structured Logs

In this world, some logs have structure. We provide a single Dagit view that interleaves the structured logs and the unstructured logs.

Pros

• Can tie logs to particular substages in the step (load_input, solid body, type check, handle_output).
• Can line up log statements with positions in the gantt chart.
• Can sometimes see the boundaries between log statements.
• No ambiguity about which view the user should use.

Cons

• Race conditions can make it difficult to reliably order logs - e.g. if load_input returns in between when a user writes to stdout and when stdout is flushed, then we could misattribute a print statement to the solid body instead of load_input. Placing markers in the raw logs could potentially address this issue.

Required Changes

• Find some way to determine a correct and consistent ordering between raw logs and structured logs. This could require:
  • Placing markers in the raw logs that allow us to tie them to structured logs. This is brittle to users inadvertently logging those markers.
  • Taking the timestamp that we receive user logs at face value. This could result in incorrect orderings.
  • Redirecting stdout/stderr after each structured log. Maybe expensive? Maybe impossible?

[j-hulbert]

I lean towards the option "Option: Independent Raw and Structured Logs - Python Logging Integration" - we use the standard python logging so either option 2 or 3 would work. I'm not sure how prevalent logging to standard out is (not via a logging handler)
I think the structured log is one of the really nice features that Dagster has just needs an easier path to tap into for other python code so option 1 isn't very appealing.

[NicolasPA]

I'm highly in favor of enforcing the Python logging standard with option 2. Option 3 seems to add implementation complexity for a feature that will not be very used.

This feature is important to make it easy to port existing Python projects to Dagster. Having to rewrite or duplicate your logging to be able to see it in Dagit worsens the experience of a new user.

[sryza]

Hey @NicolasPA - glad you see it that way. Option 2 is the direction we're pursuing. We should have this working in a few weeks.

[NicolasPA]

Great to hear!