Text vs JSON and File vs CLI logs

[nathaniel-may]

Is there an existing feature request for this?

• I have searched the existing issues

Describe the Feature

re this comment, text log lines might want to be different per destination. We may want text log lines to filter from json log lines, but I'm not sure about that. Just something to consider.

Describe alternatives you've considered

No response

Who will this benefit?

No response

Are you interested in contributing this feature?

No response

Anything else?

No response

[jtcohen6]

To summarize myself over in #4293:

Broadly, I find that I want:

• color, concision, clean spacing on the CLI
• colorless + compact verbosity in the File + JSON-formatted

Edit since then: Let's let users determine whether to use color or not based on the colorizing configs. There's good reasons to preserve color in JSON-formatted log messages, if they're going to be eventually displayed in a CLI-like setting.

[jtcohen6]

@gshank This is the issue we can use for the last bit of cosmetic work.

Let's keep JSON-formatted logs as they are. They include everything, as they should. The intended consumer of these is a machine, and users can spin up their own scripts (or even just jq) to modify/filter down what's shown.

From my perspective, the big idea is differentiating between standard text formatted logs for the CLI (info-level) and File (debug-level). These are both intended for use by human beings, and for fundamentally different purposes:

• CLI logs are interactive. They should show what's happening, while it's happening, and not too much more. (Conversely, we should avoid extended periods where we show nothing—this adds to frustration when things are slow, such as full re-parses of big projects.) CLI logs should also surface warnings and errors in a way that makes them easy to spot, and easy to take further action.
• Sometimes, that further action should look like diving into more detailed logs, stored in logs/dbt.log. These should have everything that a human being might need to debug what went wrong with a dbt project. If we've failed to include useful information, it's lost to the sands of time—or until they re-run / reproduce the error with JSON-formatted logging.

So my inclination is that, relative to how this works presently (in main):

• CLI: Text-formatted log lines should include short timestamps and messages — that's all
• File: Text-formatted messages should include longer timestamps, log level (info/warn/error), thread name, and a way to visually see where one run stopped and the next one started. (Would it make sense to include invocation_id too, or would that add too much clutter?)

2021-12-01 15:55:36.159022 | info  | MainThread | Running with dbt=1.0.0-rc3
2021-12-01 15:55:36.159022 | debug | MainThread |

======================================

Running dbt with arguments:
- ...

======================================

2021-12-01 15:55:37.432664 | debug  | Thread-3  | Using postgres connection "model.testy.my_view"

Or something like that.

In practice, I think this will look like splitting up create_text_log_line into two functions (one for CLI and one for File), adding an arg to create_log_line for CLI/File, and passing that arg from these two sites accordingly.

Tricky things:

• I think we're going to struggle to get MainReportVersion + MainReportArgs into the File, because they're currently fired before we've parsed dbt_project.yml, i.e. before we know the log_path (in case it's user-configured).
• We do have the ability to construct different messages whether an event is firing to the CLI or the File, by using/overriding the file_msg and cli_msg methods. (The base types are implemented to use the same message for both by default.)

More things to think about:

• Some logs are so verbose that we shouldn't include them by default, e.g. adapter cache events. Today, we turn those off by default, and allow users to turn them on with the --log-cache-events config. (In practice, we only do this to debug very specific errors.) In the future, we could think about encoding these as "trace"-level, and allowing users to opt in.
• We should enable users to opt into / relevel logs from dependencies. This is especially important to see "trace-level" details of connection errors for specific database clients. We support this in a pretty janky way today (hard-coded in dbt-core, ugh).

Open to hearing thoughts from everyone!