[ADAP-1047] [CT-3420] [Bug] Snowflake SAML authentication flow doesn't fully respect --quiet command

[joellabes]

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

I was testing dbt-labs/dbt-codegen#86 and ran the following command locally:

(dbt-prod) joel@Joel-Labes joel-sandbox % dbt --quiet run-operation generate_model_yaml --args '{"model_name": "first_model"}' > models/something.yml

I wound up with this in something.yml:

Initiating login request with your identity provider. A browser window should have opened for you to complete the login. If you can't see it, check existing browser windows, or your OS settings. Press CTRL+C to abort and try again...
Going to open: https://dbtlabs.okta.com/app/snowflake/exkc5f49sIXGnu9Zk4x6/sso/saml?SAMLRequest=[...] to authenticate...
version: 2

models:
  - name: first_model
    description: ""
    columns:
    [...]

Expected Behavior

Not to have the two logs from the Snowflake auth flow included:

version: 2

models:
  - name: first_model
    description: ""
    columns:

Steps To Reproduce

With dbt-labs/dbt-codegen#86 checked out:

packages:
  - local: ../dbt-codegen

Run dbt deps

Run dbt --quiet run-operation generate_model_yaml --args '{"model_name": "first_model"}' > models/something.yml

Relevant log output

============================== 13:48:52.514016 | 5cd94ee2-67f1-40b7-80aa-921813e0c939 ==============================
�[0m13:48:52.514016 [info ] [MainThread]: Running with dbt=1.7.0
�[0m13:48:52.515234 [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/joel/.dbt', 'debug': 'False', 'version_check': 'True', 'log_path': '/Users/joel/Documents/GitHub/joel-sandbox/logs', 'warn_error': 'None', 'fail_fast': 'False', 'use_colors': 'True', 'use_experimental_parser': 'False', 'no_print': 'None', 'quiet': 'True', 'log_format': 'default', 'invocation_command': 'dbt --quiet run-operation generate_model_yaml --args {"model_name": "first_model"}', 'introspect': 'True', 'static_parser': 'True', 'target_path': 'None', 'warn_error_options': 'WarnErrorOptions(include=[], exclude=[])', 'send_anonymous_usage_stats': 'True'}
�[0m13:48:54.864641 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'project_id', 'label': '5cd94ee2-67f1-40b7-80aa-921813e0c939', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a6599fbe0>]}
�[0m13:48:55.005593 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'adapter_info', 'label': '5cd94ee2-67f1-40b7-80aa-921813e0c939', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a66673820>]}
�[0m13:48:55.006873 [info ] [MainThread]: Registered adapter: snowflake=1.7.0
�[0m13:48:55.068266 [debug] [MainThread]: checksum: 8434eacd4ffdf0ca3ab22bf0e2d55b45306c9599613e842b959405abc489e606, vars: {}, profile: , target: , version: 1.7.0
�[0m13:48:55.091058 [info ] [MainThread]: Unable to do partial parsing because profile has changed
�[0m13:48:55.091699 [info ] [MainThread]: Unable to do partial parsing because a project dependency has been added
�[0m13:48:55.092210 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'partial_parser', 'label': '5cd94ee2-67f1-40b7-80aa-921813e0c939', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a6683f7f0>]}
�[0m13:48:57.205207 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label': '5cd94ee2-67f1-40b7-80aa-921813e0c939', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a678a5a90>]}
�[0m13:48:57.226119 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': '5cd94ee2-67f1-40b7-80aa-921813e0c939', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a666a5310>]}
�[0m13:48:57.226924 [info ] [MainThread]: Found 1 model, 1 snapshot, 1 test, 1 seed, 0 sources, 0 exposures, 0 metrics, 558 macros, 0 groups, 0 semantic models
�[0m13:48:57.227444 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': '5cd94ee2-67f1-40b7-80aa-921813e0c939', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a66819d30>]}
�[0m13:48:57.228341 [debug] [MainThread]: Acquiring new snowflake connection 'macro_generate_model_yaml'
�[0m13:48:57.255025 [debug] [MainThread]: Using snowflake connection "macro_generate_model_yaml"
�[0m13:48:57.255597 [debug] [MainThread]: On macro_generate_model_yaml: /* {"app": "dbt", "dbt_version": "1.7.0", "profile_name": "joel_sandbox", "target_name": "dev", "connection_name": "macro_generate_model_yaml"} */
describe table ANALYTICS_DEV.dbt_jlabes.first_model
�[0m13:48:57.256020 [debug] [MainThread]: Opening a new connection, currently in state init
�[0m13:49:10.124304 [debug] [MainThread]: Snowflake adapter: Snowflake query id: 01b09931-0607-3d6e-0000-0e694dd98ba6
�[0m13:49:10.139748 [debug] [MainThread]: Snowflake adapter: Snowflake error: 002003 (02000): SQL compilation error:
Schema 'ANALYTICS_DEV.DBT_JLABES' does not exist or not authorized.
�[0m13:49:10.141688 [debug] [MainThread]: Snowflake adapter: Error running SQL: macro get_columns_in_relation
�[0m13:49:10.142831 [debug] [MainThread]: Snowflake adapter: Rolling back transaction.
�[0m13:49:10.143973 [debug] [MainThread]: On macro_generate_model_yaml: Close
�[0m13:49:10.590602 [debug] [MainThread]: Resource report: {"command_name": "run-operation", "command_success": true, "command_wall_clock_time": 18.186037, "process_user_time": 6.177684, "process_kernel_time": 0.797498, "process_mem_max_rss": "142532608", "process_in_blocks": "0", "process_out_blocks": "0"}
�[0m13:49:10.592349 [debug] [MainThread]: Command `dbt run-operation` succeeded at 13:49:10.592004 after 18.19 seconds
�[0m13:49:10.593255 [debug] [MainThread]: Connection 'macro_generate_model_yaml' was properly closed.
�[0m13:49:10.594174 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a627b3cd0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a66d2de50>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f9a66d03a90>]}
�[0m13:49:10.595214 [debug] [MainThread]: Flushing usage events
�[0m13:55:16.164616 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fd62e7e1c70>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fd630064d00>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fd630088c10>]}

Environment

- OS: macOS 14.1.1
- Python: Python 3.8.10
- dbt: 1.7.0

Which database adapter are you using with dbt?

snowflake

Additional Context

No response

[dbeatty10]

Thanks for reporting this @joellabes !

Suppressing the auth related text like you expected seems perfectly in alignment with the documentation for --quiet.

Root cause and potential implementation

That text looks like it is coming from print() statements from the snowflake-connector-python library here.

Since they are going to standard out, we'd need to do some fancy footwork in order to silence them.

For example, we could use a context manager like the following whenever we know there's a library like this has print() statements:

import sys
import io
from contextlib import contextmanager

@contextmanager
def suppress_stdout():
    original_stdout = sys.stdout
    sys.stdout = io.StringIO()
    try:
        yield
    finally:
        sys.stdout = original_stdout

with suppress_stdout():
    # snowflake.connector.auth_method_that_eventually_prints_to_standard_out()

[nathaniel-may]

I'm inclined to open a ticket with them to not use print rather than twist our code around it. @joellabes what are the biggest impacts this behavior with the --quiet command could cause?

[joellabes]

The point of adding --quiet and print() was to facilitate piping the output to another file. This will impact anyone who's trying to do codegen-y activities, but I can't imagine anyone is doing it on-demand in a production context so it's more annoying than disastrous.

It also depends how long the company's policies allow the snowflake token to be stored - on subsequent runs, I don't get the same problem because I auth once and then stay authed for a while.

[nathaniel-may]

I talked with the team about what should happen here- and this kind of stdout catching is something we'd like to add, but a better place for it would be in core's event system. I'm closing this ticket in favor of dbt-labs/dbt-core#9174.