[#4354] Different output for console and file logs #4379

gshank · 2021-12-01T19:31:30Z

resolves #4354

Description

Create a different format for file logs than for console logs.

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

jtcohen6

took for a quick spin, I like the way it's looking!

jtcohen6 · 2021-12-01T20:59:10Z

core/dbt/main.py

+ fire_event(MainReportVersion(v=str(dbt.version.installed)))
+ fire_event(MainReportArgs(args=parsed))


Tricky thing about this reordering: We're going to raise deprecation warnings (due to dbt_project.yml config renaming) before we fire MainReportVersion. Those are raised during task = parsed.cls.from_args(args=parsed) above:

$ dbt run 21:56:50 | [ warn ] | * Deprecation Warning: The `source-paths` config has been deprecated in favor of `model-paths`. Please update your `dbt_project.yml` configuration to reflect this change. 21:56:50 | [ warn ] | * Deprecation Warning: The `data-paths` config has been deprecated in favor of `seed-paths`. Please update your `dbt_project.yml` configuration to reflect this change. 21:56:50 | [ info ] | Running with dbt=1.0.0-rc3 21:56:50 | [ info ] | Found 2 models, 0 tests, 0 snapshots, 0 analyses, 168 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics

Maybe that's not a big deal, since hopefully users resolve the deprecations by renaming quickly. It feels like a small price to pay, if what it gets us is a fully configured event logger before we actually fire any events...

Yeah. I personally kind of prefer to have the 'Running with' message right above 'Found...' message, but it's certainly a matter of opinion.

That's a fair point!

jtcohen6 · 2021-12-01T20:59:48Z

core/dbt/events/functions.py

@@ -162,7 +163,7 @@ def event_to_serializable_dict(
 # translates an Event to a completely formatted text-based log line
 # you have to specify which message you want. (i.e. - e.message, e.cli_msg(), e.file_msg())
 # type hinting everything as strings so we don't get any unintentional string conversions via str()
-def create_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
+def create_stdout_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:


Let's cut level from stdout logger, so that it's just timestamp + message

Ok. When I did that the pipe between timestamp and message didn't seem necessary, so I made it two spaces.

Two spaces looks clean! I like it:

$ dbt run 12:00:00 Running with dbt=1.0.0-rc3 12:00:00 Found 2 models, 0 tests, 0 snapshots, 0 analyses, 168 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics 12:00:00 12:00:00 Concurrency: 5 threads (target='dev') 12:00:00 12:00:00 1 of 2 START table model dbt_jcohen.my_table.................................... [RUN] 12:00:00 1 of 2 OK created table model dbt_jcohen.my_table............................... [SELECT 1 in 0.06s] 12:00:00 2 of 2 START view model dbt_jcohen.my_view...................................... [RUN] 12:00:00 2 of 2 OK created view model dbt_jcohen.my_view................................. [CREATE VIEW in 0.03s] 12:00:00 12:00:00 Finished running 1 table model, 1 view model in 0.26s. 12:00:00 12:00:00 Completed successfully 12:00:00 Done. PASS=2 WARN=0 ERROR=0 SKIP=0 TOTAL=2

Previous versions of dbt used a pipe for messages that had timestamps. I think this is a good change.

jtcohen6 · 2021-12-01T21:01:52Z

core/dbt/events/functions.py

@@ -171,6 +172,22 @@ def create_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
 return log_line


+def create_file_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:


What do you think about:

padding all thread names to be equal width (up to 10 characters, the length of MainThread)

including level in the file logger — I imagine it might be helpful to scan/search for error + warn messages

I empathize with the desire to make them even. It would be slightly better to read. But there is also a thread name ThreadPoolExecutor-0_0. Should I just truncate that one?

I truncated ThreadPoolExecutor-0_0 to ThreadPool, and changed to the square brackets. Making the prefix consistent does help with the reading. Still not entirely happy with the padded spaces in the thread name. We could translate MainThread to 'Thread-0' and ThreadPool to 'Thread-P'. Is it possible for the thread number to go higher than 9?

Anyway, take a look and see what you think

I definitely like this more than the current version!

Switch to square brackets is good. Spacing is a teensy bit awkward, but I do think it makes it easier to read.

Is it possible for the thread number to go higher than 9?

In theory, users can set it as high as they want, but I don't think we should worry about it being 3+ digits, let alone >4

jtcohen6 · 2021-12-01T21:04:07Z

core/dbt/events/functions.py

+ # Create a separator if this is the beginning of an invocation
+ if type(e) == MainReportVersion:
+ separator = 30 * '='
+ log_line = f'\n\n{separator} {e.get_ts()} | {get_invocation_id()} {separator}\n'


yes!! with the invocation_id too!! I really like this

@nathaniel-may may have thoughts about implementation. Given that MainReportVersion really truly is a one-of-a-kind event, and ought to be the very first one fired, this approach makes some sense to me

yeah if it's truly one of a kind and only happens in this text-file combo, this approach looks like the right way to do it.

jtcohen6

I'm a fan of these changes

jtcohen6 · 2021-12-02T11:04:52Z

core/dbt/events/functions.py

@@ -171,6 +172,22 @@ def create_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
 return log_line


+def create_file_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:


I definitely like this more than the current version!

Switch to square brackets is good. Spacing is a teensy bit awkward, but I do think it makes it easier to read.

Is it possible for the thread number to go higher than 9?

In theory, users can set it as high as they want, but I don't think we should worry about it being 3+ digits, let alone >4

jtcohen6 · 2021-12-02T11:05:37Z

core/dbt/main.py

+ fire_event(MainReportVersion(v=str(dbt.version.installed)))
+ fire_event(MainReportArgs(args=parsed))


That's a fair point!

jtcohen6 · 2021-12-02T11:06:39Z

core/dbt/events/functions.py

@@ -162,7 +163,7 @@ def event_to_serializable_dict(
 # translates an Event to a completely formatted text-based log line
 # you have to specify which message you want. (i.e. - e.message, e.cli_msg(), e.file_msg())
 # type hinting everything as strings so we don't get any unintentional string conversions via str()
-def create_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
+def create_stdout_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:


Two spaces looks clean! I like it:

$ dbt run 12:00:00 Running with dbt=1.0.0-rc3 12:00:00 Found 2 models, 0 tests, 0 snapshots, 0 analyses, 168 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics 12:00:00 12:00:00 Concurrency: 5 threads (target='dev') 12:00:00 12:00:00 1 of 2 START table model dbt_jcohen.my_table.................................... [RUN] 12:00:00 1 of 2 OK created table model dbt_jcohen.my_table............................... [SELECT 1 in 0.06s] 12:00:00 2 of 2 START view model dbt_jcohen.my_view...................................... [RUN] 12:00:00 2 of 2 OK created view model dbt_jcohen.my_view................................. [CREATE VIEW in 0.03s] 12:00:00 12:00:00 Finished running 1 table model, 1 view model in 0.26s. 12:00:00 12:00:00 Completed successfully 12:00:00 Done. PASS=2 WARN=0 ERROR=0 SKIP=0 TOTAL=2

Previous versions of dbt used a pipe for messages that had timestamps. I think this is a good change.

* [#4354] Different output for console and file logs * Tweak some log formats * Change loging of thread names

* [#4354] Different output for console and file logs * Tweak some log formats * Change loging of thread names Co-authored-by: Gerda Shank <gerda@fishtownanalytics.com>

* [#4354] Different output for console and file logs * Tweak some log formats * Change loging of thread names automatic commit by git-black, original commits: c220b1e

[#4354] Different output for console and file logs

0ccdef7

cla-bot bot added the cla:yes label Dec 1, 2021

jtcohen6 reviewed Dec 1, 2021

View reviewed changes

gshank added 2 commits December 1, 2021 16:38

Tweak some log formats

aea60b7

Change loging of thread names

8534c72

gshank requested a review from jtcohen6 December 2, 2021 00:05

jtcohen6 approved these changes Dec 2, 2021

View reviewed changes

gshank merged commit c220b1e into main Dec 2, 2021

gshank deleted the log_file_tweaks branch December 2, 2021 13:23

jtcohen6 mentioned this pull request Dec 2, 2021

A few final logging touch-ups #4388

Merged

2 tasks

leahwicz pushed a commit that referenced this pull request Dec 2, 2021

[#4354] Different output for console and file logs (#4379)

8587325

* [#4354] Different output for console and file logs * Tweak some log formats * Change loging of thread names

leahwicz mentioned this pull request Dec 2, 2021

[Backport] Different output for console and file logs #4399

Merged

4 tasks

varun-dc mentioned this pull request Dec 7, 2021

[CORE-16] [Bug] Uncolored stdout when using the --use-colors flag #4443

Closed

1 task

aranke mentioned this pull request May 20, 2024

[Backport 1.0.latest] Fix #9907: Add retry to tox to reduce flaky tests due to network failures #10178

Merged

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[#4354] Different output for console and file logs #4379

[#4354] Different output for console and file logs #4379

gshank commented Dec 1, 2021

jtcohen6 left a comment

jtcohen6 Dec 1, 2021

gshank Dec 1, 2021

jtcohen6 Dec 2, 2021

jtcohen6 Dec 1, 2021

gshank Dec 1, 2021

jtcohen6 Dec 2, 2021

jtcohen6 Dec 1, 2021

gshank Dec 1, 2021

gshank Dec 1, 2021

jtcohen6 Dec 2, 2021

jtcohen6 Dec 1, 2021

nathaniel-may Dec 1, 2021

jtcohen6 left a comment

jtcohen6 Dec 2, 2021

jtcohen6 Dec 2, 2021

jtcohen6 Dec 2, 2021

		fire_event(MainReportVersion(v=str(dbt.version.installed)))
		fire_event(MainReportArgs(args=parsed))

		@@ -171,6 +172,22 @@ def create_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
		return log_line


		def create_file_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:

[#4354] Different output for console and file logs #4379

[#4354] Different output for console and file logs #4379

Conversation

gshank commented Dec 1, 2021

Description

Checklist

jtcohen6 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jtcohen6 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment