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

[CT-3286] [Bug] quiet setting is ignored for multiple programmatic invocations #8938

Closed
2 tasks done
dbeatty10 opened this issue Oct 28, 2023 · 2 comments · Fixed by #9809
Closed
2 tasks done

[CT-3286] [Bug] quiet setting is ignored for multiple programmatic invocations #8938

dbeatty10 opened this issue Oct 28, 2023 · 2 comments · Fixed by #9809
Labels
bug Something isn't working logging python_api Issues related to dbtRunner Python entry point

Comments

@dbeatty10
Copy link
Contributor

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

When running multiple programmatic invocations with the quiet flag, the 1st invocation honors a --quiet flag, but subsequent ones do not.

The net effect is not having all the JSON event logs that were expected.

Expected Behavior

I expected the flag to be recognized and applied.

Steps To Reproduce

1. Create this Python script:

# runner.py

from dbt.cli.main import dbtRunner


def main():
    dbt = dbtRunner()

    cmd = [
        "--quiet",
        "--log-format=json",
        "--log-level=debug",
        "list",
    ]

    # ✅ First run (with JSON logs)
    dbt.invoke(cmd)

    # ❌ Second run (without JSON logs! 💥)
    dbt.invoke(cmd)


if __name__ == "__main__":
    main()

2. Then execute it:

python runner.py

3. Examine your logs in logs/dbt.log

Relevant log output

{"data": {"log_version": 3, "version": "=1.6.6"}, "info": {"category": "", "code": "A001", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "info", "msg": "Running with dbt=1.6.6", "name": "MainReportVersion", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.052859Z"}}
{"data": {"args": {"cache_selected_only": "False", "debug": "False", "fail_fast": "False", "indirect_selection": "eager", "introspect": "True", "invocation_command": "dbt ", "log_cache_events": "False", "log_format": "json", "log_path": "/Users/dbeatty/projects/copier-templates/duckdb-core-8866/logs", "no_print": "None", "partial_parse": "True", "printer_width": "80", "profiles_dir": "/Users/dbeatty/projects/copier-templates/duckdb-core-8866", "quiet": "True", "send_anonymous_usage_stats": "False", "static_parser": "True", "target_path": "None", "use_colors": "True", "use_experimental_parser": "False", "version_check": "True", "warn_error": "None", "warn_error_options": "WarnErrorOptions(include=[], exclude=[])", "write_json": "True"}}, "info": {"category": "", "code": "A002", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "debug", "msg": "running dbt with arguments {'printer_width': '80', 'indirect_selection': 'eager', 'write_json': 'True', 'log_cache_events': 'False', 'partial_parse': 'True', 'cache_selected_only': 'False', 'profiles_dir': '/Users/dbeatty/projects/copier-templates/duckdb-core-8866', 'debug': 'False', 'warn_error': 'None', 'log_path': '/Users/dbeatty/projects/copier-templates/duckdb-core-8866/logs', 'fail_fast': 'False', 'version_check': 'True', 'use_colors': 'True', 'use_experimental_parser': 'False', 'no_print': 'None', 'quiet': 'True', 'log_format': 'json', 'static_parser': 'True', 'invocation_command': 'dbt ', 'introspect': 'True', 'target_path': 'None', 'warn_error_options': 'WarnErrorOptions(include=[], exclude=[])', 'send_anonymous_usage_stats': 'False'}", "name": "MainReportArgs", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.057979Z"}}
{"data": {"adapter_name": "postgres", "adapter_version": "=1.6.6"}, "info": {"category": "", "code": "E034", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "info", "msg": "Registered adapter: postgres=1.6.6", "name": "AdapterRegistered", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.498103Z"}}
{"data": {"checksum": "546b81fb56652c304d87abd676e84d4737d8a0c6b62160f4a6e79dcddbc842bb", "profile": "", "target": "", "vars": "{}", "version": "1.6.6"}, "info": {"category": "", "code": "I025", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "debug", "msg": "checksum: 546b81fb56652c304d87abd676e84d4737d8a0c6b62160f4a6e79dcddbc842bb, vars: {}, profile: , target: , version: 1.6.6", "name": "StateCheckVarsHash", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.522303Z"}}
{"data": {"added": 0, "changed": 0, "deleted": 0}, "info": {"category": "", "code": "I040", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "debug", "msg": "Partial parsing enabled: 0 files deleted, 0 files added, 0 files changed.", "name": "PartialParsingEnabled", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.552597Z"}}
{"data": {}, "info": {"category": "", "code": "I017", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "debug", "msg": "Partial parsing enabled, no changes found, skipping parsing", "name": "PartialParsingSkipParsing", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.553238Z"}}
{"data": {"stat_line": "1 model, 1 operation, 0 sources, 0 exposures, 0 metrics, 352 macros, 0 groups, 0 semantic models"}, "info": {"category": "", "code": "W006", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "info", "msg": "Found 1 model, 1 operation, 0 sources, 0 exposures, 0 metrics, 352 macros, 0 groups, 0 semantic models", "name": "FoundStats", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.571Z"}}
{"data": {"msg": "jaffle_shop.stg_customers"}, "info": {"category": "", "code": "Z049", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "info", "msg": "jaffle_shop.stg_customers", "name": "ListCmdOut", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.572052Z"}}
{"data": {"command": "cli list", "completed_at": "2023-10-27T23:56:48.572743Z", "elapsed": 0.58580655, "success": true}, "info": {"category": "", "code": "Q039", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "debug", "msg": "Command `cli list` succeeded at 17:56:48.572743 after 0.59 seconds", "name": "CommandCompleted", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.572907Z"}}
{"data": {}, "info": {"category": "", "code": "Z042", "extra": {}, "invocation_id": "61a47a33-93c4-429c-ac68-805ae4387ca1", "level": "debug", "msg": "Flushing usage events", "name": "FlushEvents", "pid": 81376, "thread": "MainThread", "ts": "2023-10-27T23:56:48.573596Z"}}


============================== 17:56:48.577706 | 0a581ebd-f0be-45dc-958b-126b31605363 ==============================
�[0m17:56:48.577706 [info ] [MainThread]: Running with dbt=1.6.6
�[0m17:56:48.578356 [debug] [MainThread]: running dbt with arguments {'printer_width': '80', 'indirect_selection': 'eager', 'write_json': 'True', 'log_cache_events': 'False', 'partial_parse': 'True', 'cache_selected_only': 'False', 'profiles_dir': '/Users/dbeatty/projects/copier-templates/duckdb-core-8866', 'debug': 'False', 'warn_error': 'None', 'log_path': '/Users/dbeatty/projects/copier-templates/duckdb-core-8866/logs', 'fail_fast': 'False', 'version_check': 'True', 'use_colors': 'True', 'use_experimental_parser': 'False', 'no_print': 'None', 'quiet': 'False', 'log_format': 'default', 'static_parser': 'True', 'invocation_command': 'dbt ', 'introspect': 'True', 'target_path': 'None', 'warn_error_options': 'WarnErrorOptions(include=[], exclude=[])', 'send_anonymous_usage_stats': 'False'}
�[0m17:56:48.593345 [info ] [MainThread]: Registered adapter: postgres=1.6.6
�[0m17:56:48.598946 [debug] [MainThread]: checksum: 546b81fb56652c304d87abd676e84d4737d8a0c6b62160f4a6e79dcddbc842bb, vars: {}, profile: , target: , version: 1.6.6
�[0m17:56:48.620370 [debug] [MainThread]: Partial parsing enabled: 0 files deleted, 0 files added, 0 files changed.
�[0m17:56:48.620905 [debug] [MainThread]: Partial parsing enabled, no changes found, skipping parsing
�[0m17:56:48.633025 [info ] [MainThread]: Found 1 model, 1 operation, 0 sources, 0 exposures, 0 metrics, 352 macros, 0 groups, 0 semantic models
�[0m17:56:48.633983 [debug] [MainThread]: Command `cli list` succeeded at 17:56:48.633887 after 0.06 seconds
�[0m17:56:48.634389 [debug] [MainThread]: Flushing usage events

Environment

- OS:
- Python:
- dbt: 1.6.6

Which database adapter are you using with dbt?

postgres

Additional Context

Found this issue when trying to reproduce a bug report: #8866 (comment).

@dbeatty10 dbeatty10 added bug Something isn't working triage labels Oct 28, 2023
@github-actions github-actions bot changed the title [Bug] quiet setting is ignored for multiple programmatic invocations [CT-3286] [Bug] quiet setting is ignored for multiple programmatic invocations Oct 28, 2023
@dbeatty10 dbeatty10 added python_api Issues related to dbtRunner Python entry point and removed triage labels Oct 28, 2023
@dbeatty10
Copy link
Contributor Author

Looks like it has the same underlying cause as #9787.

Problem goes away for me if I update this:

dbt_ctx = cli.make_context(cli.name, args)

to be this instead:

            dbt_ctx = cli.make_context(cli.name, args.copy())

We can see a similar approach in the click source code here.

@dbeatty10
Copy link
Contributor Author

Workaround

The workaround in the meantime is to do this whenever calling dbt.invoke() multiple times with the same input list during programmatic invocations:

dbt.invoke(cmd.copy())

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working logging python_api Issues related to dbtRunner Python entry point
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants