Structured Logging Phase 2

[nathaniel-may]

Describe the Feature

Individual tasks are ordered by expected release with high priority unfinished items at the top of the list.

1.0.0-RC2 (released 11/22)

• (size: M) (@nathaniel-may) cleanup code Minor Cleanup of Structured Logging Module #4266
• (size: XL) (@iknox-fa) add codes to each event add codes to log events #4268 Add codes to all log events (re-work of PR #4268) #4319
• (size: S) (@nathaniel-may) add versioning Version structured logging #4272 version logging #4289
• (size: M) (@nathaniel-may) fix adapter interface Minor Cleanup of Structured Logging Module #4266
• (size: S) (@emmyoop) include event dataclass attributes in json-formatted logs {code: ..., msg: ... data:{<goes here>}} structured logging: add data attributes to json log output #4301
• (size: S) (@jtcohen6) fix log duplication in subsequent tests Remove duplicate logging during integration tests #4275

1.0.0-RC3 (released 11/30)

• (size: XXL) (@emmyoop) add additional log lines for node status reporting (details) add node_info to relevant logs #4336
• (size: M) (@iknox-fa) Does something graceful when it runs out of memory (small machines shouldn't explode because of logging), is queryable by a potential future server-wrapper Event buffer for structlog #4358
• (size: S) (@nathaniel-may) add thread name to each event (cheap way to distinguish dbt runs from each other, tracks dbt threads when we go multithreaded) (make sure windows is handled) add thread_name to structured logging #4353
• (size: XL) (@nathaniel-may) stabilize JSON serialization.
• (size: M) (@gshank) make sure we can distinguish logs from different runs Impl - Existing InvocationID. If tracking is off, it isn't created today so we would need to create it. (to add it to logging, add it as a class property on the superclass) (previously considered: preserve process id like it is today, global run_id reported at start, or allow some sort of user markers) [#4337] Always create an invocation_id, even when not tracking #4340

1.0.0 (goal: merge by Fri 12/03)

Cleanup:

• (size: S) (@jtcohen6) Find a way to configure logger before firing any events, e.g. avoid text logs preceding JSON logs Logging: restore previous (small) behaviors #4341
• (size: S) (@emmyoop) turn on verbose cache logging (every event fired by cache.py) if and only if the --log-cache-events flag is turned on only log events in cache.py when --log-cache-events is set #4369
• (size: S) (@jtcohen6) include snowplow tracking events in file logging (not cli) when available (i.e. without breaking dbt clean) Logging: restore previous (small) behaviors #4341
• (size: L?) (@iknox-fa) fix failing Windows test (Investigate thread contention on windows logfiles #4261)
• (size: S) (@jtcohen6) feature parity for dbt ls + workflow automation: set stdout logger to WARN level instead of INFO (see here + here), or better yet replace print() here with an actual fired event that can be filtered on + piped out (??) Logging: restore previous (small) behaviors #4341
• (size XL) (@nathaniel-may) black-box schema testing of all possible log events. add new interop tests for black-box json log schema testing #4327
• (size S) (@emmyoop) update README to reflect current logging state
• (size M?) (@gshank ) make sure logs go to stdout not stderr Make sure stdout logger goes to stdout. #4367
• (size S) (@iknox-fa) make event history size configurable Add --event-buffer-size flag, recreate EVENT_HISTORY once configured #4416
• (size XS) (@emmyoop) log_format in UserConfig should be str, not bool #4391
• (size M) (@nathaniel-may) json serialization needs structural tweak Cannot serialize _CachedRelation #4392
• (size S) (@jtcohen6 @nathaniel-may) Don't fire EmptyLine events to json A few final logging touch-ups #4388
• (size XS) (@jtcohen6) dbt.log should rollover at 10 mb, as before #4404 - Rollover + backup for dbt.log #4405
• (size XS) (@emmyoop) rename dbt.log.old to dbt.log.legacy update file name #4402
• (size S) (@jtcohen6) sketch out/create user facing docs (data, system for codes, etc) - possibly its own page Final touches for v1.0 docs.getdbt.com#938

[jtcohen6]

From my point of view, extra.run_state was pretty unintuitive, and it was the best we had to offer! I bet we can do something much better with node status reporting :) excited for us to take a more holistic view, and add in more events to fill in the gaps

[joellabes]

It's unclear to me if this is already covered by "improve look and feel", but the new logs are much less visually parsable in some cases.

e.g. this output from dbt deps:

(dbt-dev) joel@Joel-Labes internal-analytics % dbt deps 
{"level": "info ", "msg": "Running with dbt=1.0.0-rc1", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing dbt-labs/dbt_utils@0.7.4-b1", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.7.4-b1", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Updated version available: 0.7.4", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing dbt-labs/snowplow@0.13.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.13.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Updated version available: 0.13.1", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing dbt-labs/codegen@0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Up to date!", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing tailsdotcom/dbt_artifacts@0.5.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.5.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Up to date!", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing fivetran/hubspot@0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Updated version available: 0.4.1", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing fivetran/zendesk_source@0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Updated version available: 0.4.1", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing dbt-labs/audit_helper@0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.4.0", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Up to date!", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing fivetran/hubspot_source@0.4.3", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.4.3", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Up to date!", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "Installing fivetran/fivetran_utils@0.2.9", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Installed from version 0.2.9", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "  Up to date!", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}
{"level": "info ", "msg": "\nUpdates available for packages: ['dbt-labs/dbt_utils', 'dbt-labs/snowplow', 'fivetran/hubspot', 'fivetran/zendesk_source']                 \nUpdate your versions in packages.yml, then run dbt deps", "pid": 38573, "ts": "2021-11-17T22:31:48.762544"}

The old version:

(dbt-prod) joel@Joel-Labes internal-analytics % dbt deps
Running with dbt=0.21.0
Installing dbt-labs/dbt_utils@0.7.4
  Installed from version 0.7.4
  Up to date!
Installing dbt-labs/snowplow@0.13.0
  Installed from version 0.13.0
  Updated version available: 0.13.2
Installing dbt-labs/codegen@0.4.0
  Installed from version 0.4.0
  Up to date!
Installing tailsdotcom/dbt_artifacts@0.5.0
  Installed from version 0.5.0
  Up to date!
Installing fivetran/hubspot@0.4.0
  Installed from version 0.4.0
  Updated version available: 0.4.1
Installing fivetran/zendesk_source@0.4.0
  Installed from version 0.4.0
  Updated version available: 0.4.1
Installing dbt-labs/audit_helper@0.4.0
  Installed from version 0.4.0
  Up to date!
Installing fivetran/hubspot_source@0.4.3
  Installed from version 0.4.3
  Up to date!
Installing fivetran/fivetran_utils@0.2.9
  Installed from version 0.2.9
  Up to date!

Updates available for packages: ['dbt-labs/snowplow', 'fivetran/hubspot', 'fivetran/zendesk_source']                 
Update your versions in packages.yml, then run dbt deps

[emmyoop]

@joellabes This was a bug. #4302 will resolve it.

[joellabes]

Phenomenal 😍 thank you!