[CT-2063] [Regression] Console Logging in dbt 1.4.1 is not interactive

[ajbosco]

Is this a regression in a recent version of dbt-core?

• I believe this is a regression in dbt-core functionality
• I have searched the existing issues, and I could not find an existing issue for this regression

Current Behavior

We recently upgraded to dbt 1.4.1 and noticed the console logging (both locally and when we run commands via Airflow) is not interactive/real-time anymore.

Notice the dbt command started running at 8:01 but didn't log until 9:27 when it was fully complete.

2023-02-08, 08:01:12 UTC] {dbt_hook.py:137} INFO - dbt run --project-dir /tmp/dbt --profiles-dir /tmp/dbt/profile --target prod --models analytics_tables
[2023-02-08, 08:01:12 UTC] {dbt_hook.py:150} INFO - Output:
[2023-02-08, 09:27:22 UTC] {dbt_hook.py:154} INFO - [0m08:01:15  Running with dbt=1.4.1
[2023-02-08, 09:27:22 UTC] {dbt_hook.py:154} INFO - [0m08:03:56  Found 100 models, 100 tests, 26 snapshots, 0 analyses, 100 macros, 4 operations, 90 seed files, 100 sources, 0 exposures, 0 metrics
[2023-02-08, 09:27:22 UTC] {dbt_hook.py:154} INFO - [0m08:07:14  Running 1 on-run-start hook
[2023-02-08, 09:27:22 UTC] {dbt_hook.py:154} INFO - [0m08:07:14  1 of 1 START hook: elementary.on-run-start.0 ................................... [RUN]
[2023-02-08, 09:27:22 UTC] {dbt_hook.py:154} INFO - [0m08:07:14  1 of 1 OK hook: elementary.on-run-start.0 ...................................... [[32mOK[0m in 0.00s]
[2023-02-08, 09:27:22 UTC] {dbt_hook.py:154} INFO - [0m08:07:14  Concurrency: 16 threads (target='prod')
[2023-02-08, 09:27:22 UTC] {dbt_hook.py:154} INFO - [0m08:07:14  1 of 27 START sql table model transform.table [RUN]

Expected/Previous Behavior

This is how it logged previously in real-time

[2023-02-07, 08:02:32 UTC] {dbt_hook.py:137} INFO - dbt run --project-dir /tmp/dbt --profiles-dir /tmp/dbt/profile --target prod --models analytics_tables
[2023-02-07, 08:02:32 UTC] {dbt_hook.py:150} INFO - Output:
[2023-02-07, 08:02:35 UTC] {dbt_hook.py:154} INFO - �[0m08:02:35  Running with dbt=1.3.1
[2023-02-07, 08:05:27 UTC] {dbt_hook.py:154} INFO - �[0m08:05:27  Found 100 models, 100 tests, 26 snapshots, 0 analyses, 100 macros, 4 operations, 90 seed files, 100 sources, 0 exposures, 0 metrics
[2023-02-07, 08:09:23 UTC] {dbt_hook.py:154} INFO - �[0m08:09:23  Running 1 on-run-start hook
[2023-02-07, 08:09:23 UTC] {dbt_hook.py:154} INFO - �[0m08:09:23  1 of 1 START hook: elementary.on-run-start.0 ................................... [RUN]
[2023-02-07, 08:09:23 UTC] {dbt_hook.py:154} INFO - �[0m08:09:23  1 of 1 OK hook: elementary.on-run-start.0 ...................................... [�[32mOK�[0m in 0.00s]
[2023-02-07, 08:09:23 UTC] {dbt_hook.py:154} INFO - �[0m08:09:23  Concurrency: 16 threads (target='prod')
[2023-02-07, 08:09:23 UTC] {dbt_hook.py:154} INFO - �[0m08:09:23  1 of 27 START sql table model transform.table .... [RUN]

### Steps To Reproduce

All we did was upgrade `dbt-core` and `dbt-snowflake` to the latest versions

### Relevant log output

_No response_

### Environment

```markdown
- OS:
- Python:
- dbt (working version): 1.3.1
- dbt (regression version): 1.4.1

Which database adapter are you using with dbt?

snowflake

Additional Context

No response

[peterallenwebb]

There were significant revisions to dbt's logging infrastructure in 1.4, including to the mechanism for writing to stdout. We previously used Python's logging.StreamHandler class, but now we're writing to stdout directly. Unlike the StreamHandler implementation, we do not call flush() after every log entry is written.

So we have a strong lead on he root cause, however I have not been able to reproduce the behavior.

@ajbosco Could you let us know what OS you are on, and the nature of the dbt_hook.py wrapper it looks like you are using?

In the meantime, I will prepare a changeset which adds the flush() after every write. Not flushing between writes was definitely an oversight.

[peterallenwebb]

@jtcohen6 Does that sound like the right approach to you?

[jtcohen6]

@peterallenwebb That sounds like a good approach to me! Thanks for digging into this, and coming up with a probable lead.

[peterallenwebb]

This was closed because of the merge to main, but I am still working on the backport to 1.4.latest.

[peterallenwebb]

This fix will ship with dbt-core 1.4.2.

[ajbosco]

Thanks @peterallenwebb is there a timeline for when 1.4.2 might ship?

[jtcohen6]

@ajbosco We cut a release candidate of v1.4.2 yesterday:

• https://github.com/dbt-labs/dbt-core/releases/tag/v1.4.2rc1
• https://pypi.org/project/dbt-core/1.4.2rc1/

Should be picked up by:

pip install dbt-core==1.4.2rc1 dbt-snowflake

Could you take it for a spin, and confirm that it fixes your issue?

[ajbosco]

@jtcohen6 Just confirmed this fix worked for our issue.

[karthikchowkula]

Hello Guys,
Using Python DBT Core model with Snowflake profile,i'm not able to print dataframe object to terminal!