Add Structured Logging #4055

nathaniel-may · 2021-10-13T20:17:52Z

resolves #3359

Description

The structured-logging branch is a feature branch and small incremental changes should be merged via PR into this branch. Tests need to pass for each merge into this feature branch. There are many integration tests that rely on certain wording of log messages, and it is important that these tests remain intact by converting them to use codes incrementally.

Phase 1:

merge initial framework design
- Initial structured logging work with fire_event #4137
add adapter interface
- ~~Adapter logging interface #4161~~ Structlog #4176
change every single callsite to the existing logger in the app and tests
plumb the cli color flag so structlog respects it
- Structlog #4176
secret scrubbing
- scrub the secrets #4203
send all logs to stdout and dbt.log through some logger
- ~~Structlog #4176~~ std logger for structured logging #4231
hook in the option for json logs
- ~~Structlog #4176~~ std logger for structured logging #4231
update tests
- configure event logger for integration tests #4257
update adapter repos: (requires this PR to be merged first)
- redshift
- snowflake
- bigquery
- spark

Phase 2:

add additional log lines for node status reporting
create scalable in-memory event history
improve message wording
fine tune structlog configs including look and feel
add codes to each event
add thread id to each event
make sure we can distinguish logs from different runs (preserve process id like it is today, or allow some sort of user markers)
upgrade rpc backdoor away from env vars ala Add Structured Logging #4055

Checklist

I have signed the CLA
I have run this code in development and it appears to resolve the stated issue
This PR includes tests, or tests are not required/relevant for this PR
I have updated the CHANGELOG.md and added information about my change

kwigley

woo! left some questions for anyone who is familiar 😄

core/dbt/events/functions.py

kwigley · 2021-11-09T01:16:16Z

core/dbt/events/functions.py

@@ -0,0 +1,213 @@
+
+from colorama import Style
+import dbt.events.functions as this  # don't worry I hate it too.


Why is this needed?

Maybe it's not needed! But I couldn't get the my functions to set the global variables without it. Without this it created a new locally scoped variable which is obviously not what I want. Idk why but I have a lot of trouble with Python's variable scoping so there's probably a better way to do this.

yeah I just tried deleting all the this calls, and flake8 gives me F841 local variable 'format_json' is assigned to but never used 🤷‍♂️

core/dbt/events/functions.py

add event type modeling and fire_event calls

* updated context dir to new structured logging

handle exec info

update log call sites with new event system

graph call sites for structured logging

* first pass adding structured logging

* use __post_init__() instead of fake dataclass member vars

* update config use structured logging * WIP * minor cleanup * fixed merge error * added in ShowException * added todo to remove defaults after dropping 3.6 * removed todo that is obsolete

* convert generic_test to structured logging * convert macros to structured logging * add struc logging to most of manifest.py * add struct logging to models.py * added struct logging to partial.py * finished conversion of manifest * fixing errors * fixed 1 todo and added another * fixed bugs from merge

* add struct logging to base.py * struct logging in run_operation * add struct logging to base * add struct logging to clean * add struct logging to debug * add struct logging to deps * fix errors * add struct logging to run.py * fixed flake error * add struct logging to geneerate * added debug level stack trace * fixed flake error * added struct logging to compile * added struct logging to freshness * cleaned up errors * resolved bug that broke everything * removed accidental import * fixed bug with unused args

scrub secrets in event module

* add struct logging to docs serve * remove merge fluff * struct logging to seed command * converting print to use structured logging * more structured logging print conversion * pulling apart formatting more * added struct logging by disecting printer.py * add struct logging to runnable * add struct logging to task init * fixed formatting * more formatting and moving things around

* add struct logging to base * add struct logging to git * add struct logging to deps * remove blank line * fixed stray merge error

* add struct logging to compilation * add struct logging to tracking * add struct logging to utils * add struct logging to exceptions * fixed some misc errors * updated to send raw ex, removed resulting circ dep

* added struct logging to base * fixed merge wierdness * convert to use single type for integration tests * converted to 3 reusable test types in sep module * tweak message * clean up and making test_types complete for future * fix missed import

* switches on debug level to guard against expensive messages * adds memoization to msg construction

- removed 3 new log call sites and replaced with structured logs - removed 2 unused struc logs

graph call sites for structured logging Co-authored-by: Nathaniel May <nathaniel.may@fishtownanalytics.com> Co-authored-by: Emily Rockman <emily.rockman@dbtlabs.com>

structured logging powered by the stdlib logger Co-authored-by: Emily Rockman <emily.rockman@dbtlabs.com> Co-authored-by: Ian Knox <81931810+iknox-fa@users.noreply.github.com>

* apply test fixes * remove presto test

* Env var shim to reenable logbook * Rename to ENABLE_LEGACY_LOGGER

jtcohen6

One failing test, test_postgres_debug_with_profiles_separate_from_project_dir, that only fails on Windows. It's definitely related to changes here, but I don't think it's worth holding off on this PR any longer. @nathaniel-may and I have a hunch that it's more likely a symptom of our testing scaffold than it is representative of an actual issue in dbt-core.

Let's open a new issue to investigate further, and add to the phase 2 to-do list. In the meantime, let's move ahead with this change.

Amazing work @nathaniel-may @iknox-fa @emmyoop, and to everyone who helped along the way :)

cla-bot bot added the cla:yes label Oct 13, 2021

nathaniel-may force-pushed the feature/structured-logging branch 2 times, most recently from 496f54e to 5c9fd07 Compare October 26, 2021 17:57

jtcohen6 mentioned this pull request Nov 3, 2021

Structured Logging (for JSON) #2915

Closed

emmyoop mentioned this pull request Nov 8, 2021

[#3885] Skip partial parsing if project env vars change #4212

Merged

4 tasks

emmyoop force-pushed the feature/structured-logging branch from 89e478f to 66cece0 Compare November 8, 2021 20:32

kwigley reviewed Nov 9, 2021

View reviewed changes

jtcohen6 reviewed Nov 9, 2021

View reviewed changes

core/dbt/events/functions.py Outdated Show resolved Hide resolved

Nathaniel May and others added 22 commits November 9, 2021 11:26

init

57ae918

Initial structured logging work with fire_event (#4137)

f9ef9da

add event type modeling and fire_event calls

context call sites (#4164)

69aa6bf

* updated context dir to new structured logging

Handle exec info (#4168)

44a9da6

handle exec info

Client call sites (#4163)

5b2562a

update log call sites with new event system

Change Graph logger call sites (#4165)

51d8440

graph call sites for structured logging

contracts call sites (#4166)

b141620

* first pass adding structured logging

Dataclass compatibility (#4180)

d8868c5

* use __post_init__() instead of fake dataclass member vars

config call sites (#4169)

6b36b18

* update config use structured logging * WIP * minor cleanup * fixed merge error * added in ShowException * added todo to remove defaults after dropping 3.6 * removed todo that is obsolete

Show Exception should trigger a stack trace (#4190)

d513491

scrub the secrets (#4203)

13f31ae

scrub secrets in event module

deps call sites (#4199)

e0b0eda

* add struct logging to base * add struct logging to git * add struct logging to deps * remove blank line * fixed stray merge error

call sites in core/dbt (excluding main.py) (#4202)

d8b97c1

* add struct logging to compilation * add struct logging to tracking * add struct logging to utils * add struct logging to exceptions * fixed some misc errors * updated to send raw ex, removed resulting circ dep

trivial logger removal (#4216)

6334365

test/integration call sites (#4209)

bd3e623

* added struct logging to base * fixed merge wierdness * convert to use single type for integration tests * converted to 3 reusable test types in sep module * tweak message * clean up and making test_types complete for future * fix missed import

remove unused import (#4217)

b5c6f09

lazy logging in event module (#4210)

25c974a

* switches on debug level to guard against expensive messages * adds memoization to msg construction

use event types in main even before the logger is set up. (#4219)

f95e9ef

updates associated with merging main

5cc8626

- removed 3 new log call sites and replaced with structured logs - removed 2 unused struc logs

emmyoop and others added 7 commits November 9, 2021 11:26

removed redundant timestamp (#4239)

43b39fd

Struct log for adapter call sites (#4189)

b2aea11

graph call sites for structured logging Co-authored-by: Nathaniel May <nathaniel.may@fishtownanalytics.com> Co-authored-by: Emily Rockman <emily.rockman@dbtlabs.com>

std logger for structured logging (#4231)

a40550b

structured logging powered by the stdlib logger Co-authored-by: Emily Rockman <emily.rockman@dbtlabs.com> Co-authored-by: Ian Knox <81931810+iknox-fa@users.noreply.github.com>

whitespace change

2ca6ce6

postgres adapter to use new logger

ebb84c4

fixes

683190b

rebased on main and added new partial parsing event

31acb95

nathaniel-may force-pushed the feature/structured-logging branch from 3684a5f to 31acb95 Compare November 9, 2021 16:40

nathaniel-may marked this pull request as ready for review November 9, 2021 16:42

nathaniel-may requested review from iknox-fa, emmyoop and leahwicz November 9, 2021 16:43

nathaniel-may mentioned this pull request Nov 9, 2021

Structured Logging Phase 2 #4260

Closed

26 tasks

configure event logger for integration tests (#4257)

5e6be16

* apply test fixes * remove presto test

jtcohen6 mentioned this pull request Nov 9, 2021

Compatibility with new core logging via env var dbt-labs/dbt-rpc#61

Merged

2 tasks

jtcohen6 added test macos test windows labels Nov 9, 2021

Env var shim to enable legacy logger (#4255)

6dd9c2c

* Env var shim to reenable logbook * Rename to ENABLE_LEGACY_LOGGER

jtcohen6 approved these changes Nov 9, 2021

View reviewed changes

nathaniel-may merged commit 434f3d2 into main Nov 9, 2021

nathaniel-may deleted the feature/structured-logging branch November 9, 2021 22:42

nathaniel-may mentioned this pull request Nov 9, 2021

Investigate thread contention on windows logfiles #4261

Closed

1 task

ciklista mentioned this pull request Dec 8, 2021

Bug: changed log output of dbt-core v1.0.0 causes log parsing to fail. Dashlane/dbt-invoke#13

Closed

TohnJhomas mentioned this pull request Nov 14, 2022

[INTEGRATION][DBT] Update DBT integration to use Streaming Metadata OpenLineage/OpenLineage#1297

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add Structured Logging #4055

Add Structured Logging #4055

nathaniel-may commented Oct 13, 2021 •

edited

kwigley left a comment

kwigley Nov 9, 2021

nathaniel-may Nov 9, 2021

nathaniel-may Nov 9, 2021

jtcohen6 left a comment

		@@ -0,0 +1,213 @@

		from colorama import Style
		import dbt.events.functions as this # don't worry I hate it too.

Add Structured Logging #4055

Add Structured Logging #4055

Conversation

nathaniel-may commented Oct 13, 2021 • edited

Description

Phase 1:

Phase 2:

Checklist

kwigley left a comment

Choose a reason for hiding this comment

kwigley Nov 9, 2021

Choose a reason for hiding this comment

nathaniel-may Nov 9, 2021

Choose a reason for hiding this comment

nathaniel-may Nov 9, 2021

Choose a reason for hiding this comment

jtcohen6 left a comment

Choose a reason for hiding this comment

nathaniel-may commented Oct 13, 2021 •

edited