Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug] Debug logs for batches are printing out reference to function instead of description details #11111

Closed
2 tasks done
QMalcolm opened this issue Dec 9, 2024 · 1 comment · Fixed by #11071
Closed
2 tasks done
Assignees
Labels
bug Something isn't working microbatch Issues related to the microbatch incremental strategy

Comments

@QMalcolm
Copy link
Contributor

QMalcolm commented Dec 9, 2024

Is this a new bug in dbt-core?

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

Current Behavior

Debug logging around how microbatch batches are being run currently log the pointer to the describe_batch method instead of the result of the method. Looks something like

11:01:11.306014 [debug] [MainThread]: <bound method MicrobatchModelRunner.describe_batch of <dbt.task.run.MicrobatchModelRunner object at 0x105e93e20>> is being run sequentially

Expected Behavior

Debug logging around how microbatch batches are being run should log information about the batch, e.g.

11:01:11.306014 [debug] [MainThread]: batch 2024-12-08 of microbatch_demo.microbatch_model is being run sequentially

Steps To Reproduce

  1. Ensure you're running on dbt-core 1.9.0rc2 via pip install dbt-core==1.9.0rc2
  2. Create a dbt project with an microbatch incremental model
  3. Run the project via dbt run
  4. grep the logs cat logs/dbt.log | grep "is being run"
  5. Observe the log weirdness

Relevant log output

(venv) quigleymalcolm@Quigley-Malcolm microbatch_demo % dbt run
17:01:08  Running with dbt=1.9.0-rc2
17:01:10  Registered adapter: postgres=1.9.0-b1
17:01:10  Unable to do partial parsing because of a version mismatch
17:01:10  Found 3 models, 429 macros
17:01:10  
17:01:10  Concurrency: 1 threads (target='dev')
17:01:10  
17:01:11  1 of 3 START sql table model microbatch_demo.input_model ....................... [RUN]
17:01:11  1 of 3 OK created sql table model microbatch_demo.input_model .................. [SELECT 4 in 0.10s]
17:01:11  2 of 3 START sql microbatch model microbatch_demo.microbatch_model ............. [RUN]
17:01:11  1 of 4 START batch 2024-12-06 of microbatch_demo.microbatch_model .............. [RUN]
17:01:11  1 of 4 OK created batch 2024-12-06 of microbatch_demo.microbatch_model ......... [MERGE 0 in 0.10s]
17:01:11  2 of 4 START batch 2024-12-07 of microbatch_demo.microbatch_model .............. [RUN]
17:01:11  2 of 4 OK created batch 2024-12-07 of microbatch_demo.microbatch_model ......... [MERGE 0 in 0.04s]
17:01:11  3 of 4 START batch 2024-12-08 of microbatch_demo.microbatch_model .............. [RUN]
17:01:11  3 of 4 OK created batch 2024-12-08 of microbatch_demo.microbatch_model ......... [MERGE 0 in 0.04s]
17:01:11  4 of 4 START batch 2024-12-09 of microbatch_demo.microbatch_model .............. [RUN]
17:01:11  4 of 4 OK created batch 2024-12-09 of microbatch_demo.microbatch_model ......... [MERGE 0 in 0.03s]
17:01:11  2 of 3 OK created sql microbatch model microbatch_demo.microbatch_model ........ [SUCCESS in 0.21s]
17:01:11  3 of 3 START sql view model microbatch_demo.dependent_model .................... [RUN]
17:01:11  3 of 3 OK created sql view model microbatch_demo.dependent_model ............... [CREATE VIEW in 0.07s]
17:01:11  
17:01:11  Finished running 1 incremental model, 1 table model, 1 view model in 0 hours 0 minutes and 0.66 seconds (0.66s).
17:01:11  
17:01:11  Completed successfully
17:01:11  
17:01:11  Done. PASS=3 WARN=0 ERROR=0 SKIP=0 TOTAL=3
(venv) quigleymalcolm@Quigley-Malcolm microbatch_demo % cat logs/dbt.log | grep "is being run"
11:01:11.306014 [debug] [MainThread]: <bound method MicrobatchModelRunner.describe_batch of <dbt.task.run.MicrobatchModelRunner object at 0x105e93e20>> is being run sequentially
11:01:11.408218 [debug] [MainThread]: <bound method MicrobatchModelRunner.describe_batch of <dbt.task.run.MicrobatchModelRunner object at 0x105e96f80>> is being run sequentially
11:01:11.446819 [debug] [MainThread]: <bound method MicrobatchModelRunner.describe_batch of <dbt.task.run.MicrobatchModelRunner object at 0x104bae470>> is being run sequentially
11:01:11.485696 [debug] [MainThread]: <bound method MicrobatchModelRunner.describe_batch of <dbt.task.run.MicrobatchModelRunner object at 0x105fc28f0>> is being run sequentially

Environment

- OS: macOS 15.1
- Python: 3.10.15
- dbt: 1.9.0rc2

Which database adapter are you using with dbt?

postgres

Additional Context

Screenshot 2024-12-09 at 11 02 14 (2)

@QMalcolm QMalcolm added bug Something isn't working triage microbatch Issues related to the microbatch incremental strategy and removed triage labels Dec 9, 2024
@QMalcolm
Copy link
Contributor Author

QMalcolm commented Dec 9, 2024

I should have waited two extra minutes so that this issue could have been created at 11:11AM CST 🫠

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working microbatch Issues related to the microbatch incremental strategy
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants