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.

Sign up for GitHub

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

Jump to bottom

SNOW-1178890: When using externalbrowser printing to STDOUT breaks pipelining #1892

Open
invisiblethreat opened this issue Feb 29, 2024 · 7 comments · May be fixed by #1893
Open

SNOW-1178890: When using externalbrowser printing to STDOUT breaks pipelining #1892

invisiblethreat opened this issue Feb 29, 2024 · 7 comments · May be fixed by #1893
Assignees
@sfc-gh-aalam
Labels
enhancement The issue is a request for improvement or a new feature status-pr_pending_merge A PR is made and is under review triaged

Comments

@invisiblethreat
Copy link

Python version

$ python --version --version Python 3.11.7 (main, Dec 4 2023, 18:10:11) [Clang 15.0.0 (clang-1500.1.0.2.5)]

Operating system and processor architecture

macOS-14.3-arm64-arm-64bit

Installed packages

$ pip freeze
annotated-types==0.6.0
asn1crypto==1.5.1
atpublic==4.0
certifi==2024.2.2
cffi==1.16.0
charset-normalizer==3.3.2
cloudpickle==2.2.1
cryptography==42.0.5
filelock==3.13.1
idna==3.6
packaging==23.2
platformdirs==3.11.0
pycparser==2.21
pydantic==2.6.3
pydantic_core==2.16.3
PyJWT==2.8.0
pyOpenSSL==24.0.0
python-dateutil==2.8.2
python-dotenv==1.0.1
pytz==2024.1
PyYAML==6.0.1
requests==2.31.0
six==1.16.0
snowflake==0.6.0
snowflake-connector-python==3.7.1
snowflake-snowpark-python==1.13.0
snowflake._legacy==0.5.0
snowflake.core==0.6.0
snowflake_auth @ file:///Users/**** #syntactic sugar for connections
sortedcontainers==2.4.0
tomlkit==0.12.4
typing_extensions==4.10.0
urllib3==2.2.1

What did you do?

Tried to pipeline output from a script using `externalbrowser` authentication. https://github.com/snowflakedb/snowflake-connector-python/blob/main/src/snowflake/connector/auth/webbrowser.py#L169-L183 should NOT be printing to STDOUT. There are suitable logging facilities for each of these conditions.

What did you expect to see?

Only things that I print to the screen being printed to the screen.

Can you set logging to DEBUG and collect the logs?

$ ./example.py
DEBUG:snowflake-auth:building snowflake auth
2024-02-29 16:49:40,283 - MainThread connection.py:386 - __init__() - INFO - Snowflake Connector for Python Version: 3.7.1, Python Version: 3.11.7, Platform: macOS-14.3-arm64-arm-64bit
INFO:snowflake.connector.connection:Snowflake Connector for Python Version: 3.7.1, Python Version: 3.11.7, Platform: macOS-14.3-arm64-arm-64bit
2024-02-29 16:49:40,283 - MainThread connection.py:681 - connect() - DEBUG - connect
DEBUG:snowflake.connector.connection:connect
2024-02-29 16:49:40,283 - MainThread connection.py:1060 - __config() - DEBUG - __config
DEBUG:snowflake.connector.connection:__config
2024-02-29 16:49:40,283 - MainThread connection.py:1211 - __config() - INFO - This connection is in OCSP Fail Open Mode. TLS Certificates would be checked for validity and revocation status. Any other Certificate Revocation related exceptions or OCSP Responder failures would be disregarded in favor of connectivity.
INFO:snowflake.connector.connection:This connection is in OCSP Fail Open Mode. TLS Certificates would be checked for validity and revocation status. Any other Certificate Revocation related exceptions or OCSP Responder failures would be disregarded in favor of connectivity.
2024-02-29 16:49:40,283 - MainThread converter.py:159 - __init__() - DEBUG - use_numpy: False
DEBUG:snowflake.connector.converter:use_numpy: False
2024-02-29 16:49:40,283 - MainThread connection.py:887 - __open_connection() - DEBUG - REST API object was created: ys91781.snowflakecomputing.com:443
DEBUG:snowflake.connector.connection:REST API object was created: ys91781.snowflakecomputing.com:443
2024-02-29 16:49:40,300 - MainThread webbrowser.py:116 - prepare() - DEBUG - authenticating by Web Browser
DEBUG:snowflake.connector.auth.webbrowser:authenticating by Web Browser
2024-02-29 16:49:40,300 - MainThread webbrowser.py:140 - prepare() - DEBUG - step 1: query GS to obtain SSO url
DEBUG:snowflake.connector.auth.webbrowser:step 1: query GS to obtain SSO url
2024-02-29 16:49:40,300 - MainThread webbrowser.py:406 - _get_sso_url() - DEBUG - account=ys91781, authenticator=EXTERNALBROWSER, user=****
DEBUG:snowflake.connector.auth.webbrowser:account=ys91781, authenticator=EXTERNALBROWSER, user=****
2024-02-29 16:49:40,301 - MainThread retry.py:351 - from_int() - DEBUG - Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
DEBUG:snowflake.connector.vendored.urllib3.util.retry:Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
2024-02-29 16:49:40,301 - MainThread retry.py:351 - from_int() - DEBUG - Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
DEBUG:snowflake.connector.vendored.urllib3.util.retry:Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
2024-02-29 16:49:40,301 - MainThread network.py:1224 - _use_requests_session() - DEBUG - Session status for SessionPool '****.snowflakecomputing.com', SessionPool 1/1 active sessions
DEBUG:snowflake.connector.network:Session status for SessionPool 'ys91781.snowflakecomputing.com', SessionPool 1/1 active sessions
2024-02-29 16:49:40,301 - MainThread network.py:875 - _request_exec_wrapper() - DEBUG - remaining request timeout: N/A ms, retry cnt: 1
DEBUG:snowflake.connector.network:remaining request timeout: N/A ms, retry cnt: 1
2024-02-29 16:49:40,301 - MainThread network.py:857 - add_request_guid() - DEBUG - Request guid: befab440-c588-40da-b98d-23849e9bf089
DEBUG:snowflake.connector.network:Request guid: befab440-c588-40da-b98d-23849e9bf089
2024-02-29 16:49:40,301 - MainThread network.py:1065 - _request_exec() - DEBUG - socket timeout: 60
DEBUG:snowflake.connector.network:socket timeout: 60
2024-02-29 16:49:40,303 - MainThread connectionpool.py:1019 - _new_conn() - DEBUG - Starting new HTTPS connection (1): ****.snowflakecomputing.com:443
DEBUG:snowflake.connector.vendored.urllib3.connectionpool:Starting new HTTPS connection (1): ****.snowflakecomputing.com:443
2024-02-29 16:49:40,593 - MainThread ssl_wrap_socket.py:79 - ssl_wrap_socket_with_ocsp() - DEBUG - OCSP Mode: FAIL_OPEN, OCSP response cache file name: None
DEBUG:snowflake.connector.ssl_wrap_socket:OCSP Mode: FAIL_OPEN, OCSP response cache file name: None
2024-02-29 16:49:40,623 - MainThread ocsp_snowflake.py:492 - reset_cache_dir() - DEBUG - cache directory: /Users/****/Library/Caches/Snowflake
DEBUG:snowflake.connector.ocsp_snowflake:cache directory: /Users/****/Library/Caches/Snowflake
2024-02-29 16:49:40,624 - MainThread ocsp_snowflake.py:530 - reset_ocsp_response_cache_uri() - DEBUG - ocsp_response_cache_uri: file:///Users/****/Library/Caches/Snowflake/ocsp_response_cache.json
DEBUG:snowflake.connector.ocsp_snowflake:ocsp_response_cache_uri: file:///Users/****/Library/Caches/Snowflake/ocsp_response_cache.json
2024-02-29 16:49:40,624 - MainThread ocsp_snowflake.py:533 - reset_ocsp_response_cache_uri() - DEBUG - OCSP_VALIDATION_CACHE size: 209
DEBUG:snowflake.connector.ocsp_snowflake:OCSP_VALIDATION_CACHE size: 209
2024-02-29 16:49:40,624 - MainThread ocsp_snowflake.py:332 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP response cache server is enabled: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json
DEBUG:snowflake.connector.ocsp_snowflake:OCSP response cache server is enabled: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json
2024-02-29 16:49:40,624 - MainThread ocsp_snowflake.py:345 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP dynamic cache server RETRY URL: None
DEBUG:snowflake.connector.ocsp_snowflake:OCSP dynamic cache server RETRY URL: None
2024-02-29 16:49:40,624 - MainThread ocsp_snowflake.py:966 - validate() - DEBUG - validating certificate: ys91781.snowflakecomputing.com
DEBUG:snowflake.connector.ocsp_snowflake:validating certificate: ys91781.snowflakecomputing.com
2024-02-29 16:49:40,624 - MainThread ocsp_asn1crypto.py:385 - extract_certificate_chain() - DEBUG - # of certificates: 4
DEBUG:snowflake.connector.ocsp_asn1crypto:# of certificates: 4
2024-02-29 16:49:40,625 - MainThread ocsp_asn1crypto.py:390 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('common_name', '*.us-west-2.snowflakecomputing.com')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon RSA 2048 M03')])
DEBUG:snowflake.connector.ocsp_asn1crypto:subject: OrderedDict([('common_name', '*.us-west-2.snowflakecomputing.com')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon RSA 2048 M03')])
2024-02-29 16:49:40,625 - MainThread ocsp_asn1crypto.py:390 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon RSA 2048 M03')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon Root CA 1')])
DEBUG:snowflake.connector.ocsp_asn1crypto:subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon RSA 2048 M03')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon Root CA 1')])
2024-02-29 16:49:40,625 - MainThread ocsp_asn1crypto.py:390 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon Root CA 1')]), issuer: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'Arizona'), ('locality_name', 'Scottsdale'), ('organization_name', 'Starfield Technologies, Inc.'), ('common_name', 'Starfield Services Root Certificate Authority - G2')])
DEBUG:snowflake.connector.ocsp_asn1crypto:subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon Root CA 1')]), issuer: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'Arizona'), ('locality_name', 'Scottsdale'), ('organization_name', 'Starfield Technologies, Inc.'), ('common_name', 'Starfield Services Root Certificate Authority - G2')])
2024-02-29 16:49:40,626 - MainThread ocsp_asn1crypto.py:390 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'Arizona'), ('locality_name', 'Scottsdale'), ('organization_name', 'Starfield Technologies, Inc.'), ('common_name', 'Starfield Services Root Certificate Authority - G2')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'Starfield Technologies, Inc.'), ('organizational_unit_name', 'Starfield Class 2 Certification Authority')])
DEBUG:snowflake.connector.ocsp_asn1crypto:subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'Arizona'), ('locality_name', 'Scottsdale'), ('organization_name', 'Starfield Technologies, Inc.'), ('common_name', 'Starfield Services Root Certificate Authority - G2')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'Starfield Technologies, Inc.'), ('organizational_unit_name', 'Starfield Class 2 Certification Authority')])
2024-02-29 16:49:40,627 - MainThread ocsp_asn1crypto.py:87 - read_cert_bundle() - DEBUG - reading certificate bundle: /Users/****/test/venv-test/lib/python3.11/site-packages/certifi/cacert.pem
DEBUG:snowflake.connector.ocsp_asn1crypto:reading certificate bundle: /Users/****/test/venv-test/lib/python3.11/site-packages/certifi/cacert.pem
2024-02-29 16:49:40,634 - MainThread ocsp_asn1crypto.py:413 - create_pair_issuer_subject() - DEBUG - not found issuer_der: OrderedDict([('country_name', 'US'), ('organization_name', 'Starfield Technologies, Inc.'), ('organizational_unit_name', 'Starfield Class 2 Certification Authority')])
DEBUG:snowflake.connector.ocsp_asn1crypto:not found issuer_der: OrderedDict([('country_name', 'US'), ('organization_name', 'Starfield Technologies, Inc.'), ('organizational_unit_name', 'Starfield Class 2 Certification Authority')])
2024-02-29 16:49:40,635 - MainThread ocsp_snowflake.py:730 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('common_name', '*.us-west-2.snowflakecomputing.com')])
DEBUG:snowflake.connector.ocsp_snowflake:hit cache for subject: OrderedDict([('common_name', '*.us-west-2.snowflakecomputing.com')])
2024-02-29 16:49:40,636 - MainThread ocsp_asn1crypto.py:205 - is_valid_time() - DEBUG - Verifying the attached certificate is signed by the issuer. Valid Not After: 2025-12-10 00:00:00+00:00
DEBUG:snowflake.connector.ocsp_asn1crypto:Verifying the attached certificate is signed by the issuer. Valid Not After: 2025-12-10 00:00:00+00:00
2024-02-29 16:49:40,636 - MainThread ocsp_snowflake.py:730 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon RSA 2048 M03')])
DEBUG:snowflake.connector.ocsp_snowflake:hit cache for subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon RSA 2048 M03')])
2024-02-29 16:49:40,637 - MainThread ocsp_asn1crypto.py:205 - is_valid_time() - DEBUG - Verifying the attached certificate is signed by the issuer. Valid Not After: 2025-12-10 00:00:00+00:00
DEBUG:snowflake.connector.ocsp_asn1crypto:Verifying the attached certificate is signed by the issuer. Valid Not After: 2025-12-10 00:00:00+00:00
2024-02-29 16:49:40,637 - MainThread ocsp_snowflake.py:730 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon Root CA 1')])
DEBUG:snowflake.connector.ocsp_snowflake:hit cache for subject: OrderedDict([('country_name', 'US'), ('organization_name', 'Amazon'), ('common_name', 'Amazon Root CA 1')])
2024-02-29 16:49:40,638 - MainThread ocsp_asn1crypto.py:205 - is_valid_time() - DEBUG - Verifying the attached certificate is signed by the issuer. Valid Not After: 2024-06-06 12:00:00+00:00
DEBUG:snowflake.connector.ocsp_asn1crypto:Verifying the attached certificate is signed by the issuer. Valid Not After: 2024-06-06 12:00:00+00:00
2024-02-29 16:49:40,638 - MainThread ocsp_snowflake.py:730 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'Arizona'), ('locality_name', 'Scottsdale'), ('organization_name', 'Starfield Technologies, Inc.'), ('common_name', 'Starfield Services Root Certificate Authority - G2')])
DEBUG:snowflake.connector.ocsp_snowflake:hit cache for subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'Arizona'), ('locality_name', 'Scottsdale'), ('organization_name', 'Starfield Technologies, Inc.'), ('common_name', 'Starfield Services Root Certificate Authority - G2')])
2024-02-29 16:49:40,639 - MainThread ocsp_snowflake.py:1023 - _validate() - DEBUG - ok
DEBUG:snowflake.connector.ocsp_snowflake:ok
2024-02-29 16:49:40,739 - MainThread connectionpool.py:474 - _make_request() - DEBUG - https://ys91781.snowflakecomputing.com:443 "POST /session/authenticator-request?request_guid=befab440-c588-40da-b98d-23849e9bf089 HTTP/1.1" 200 943
DEBUG:snowflake.connector.vendored.urllib3.connectionpool:https://ys91781.snowflakecomputing.com:443 "POST /session/authenticator-request?request_guid=befab440-c588-40da-b98d-23849e9bf089 HTTP/1.1" 200 943
2024-02-29 16:49:40,740 - MainThread network.py:1092 - _request_exec() - DEBUG - SUCCESS
DEBUG:snowflake.connector.network:SUCCESS
2024-02-29 16:49:40,740 - MainThread network.py:1229 - _use_requests_session() - DEBUG - Session status for SessionPool 'ys91781.snowflakecomputing.com', SessionPool 0/1 active sessions
DEBUG:snowflake.connector.network:Session status for SessionPool 'ys91781.snowflakecomputing.com', SessionPool 0/1 active sessions
2024-02-29 16:49:40,740 - MainThread network.py:745 - _post_request() - DEBUG - ret[code] = None, after post request
DEBUG:snowflake.connector.network:ret[code] = None, after post request
2024-02-29 16:49:40,740 - MainThread webbrowser.py:148 - prepare() - DEBUG - Validate SSO URL
DEBUG:snowflake.connector.auth.webbrowser:Validate SSO URL
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...
2024-02-29 16:49:40,740 - MainThread webbrowser.py:166 - prepare() - DEBUG - step 2: open a browser
DEBUG:snowflake.connector.auth.webbrowser:step 2: open a browser
Going to open: https://***/snowflake/exk1zhkyr23Lalxuf697/sso/saml?**** to authenticate...
2024-02-29 16:49:40,888 - MainThread webbrowser.py:191 - prepare() - DEBUG - step 3: accept SAML token
@github-actions github-actions bot changed the title When using externalbrowser printing to STDOUT breaks pipelining SNOW-1178890: When using externalbrowser printing to STDOUT breaks pipelining Feb 29, 2024
@sfc-gh-aalam
Copy link
Collaborator

@invisiblethreat would you like to open a PR with appropriate logging level to fix this if it is urgent for you?

@sfc-gh-aalam sfc-gh-aalam added triaged enhancement The issue is a request for improvement or a new feature and removed needs triage bug labels Feb 29, 2024
@invisiblethreat
Copy link
Author

@sfc-gh-aalam happy to do so!

@invisiblethreat invisiblethreat linked a pull request Feb 29, 2024 that will close this issue
Open
7 tasks
@invisiblethreat
Copy link
Author

PR opened: #1893

@sfc-gh-dszmolka sfc-gh-dszmolka added the status-pr_pending_merge A PR is made and is under review label Mar 11, 2024
@ronlut
Copy link

ronlut commented Jun 23, 2024

Hi, any progress here? This actually breaks tools that generate content and use the snowflake connector (dbt codegen for example), as those lines need to be manually filtered out from the output.

@sfc-gh-aalam
Copy link
Collaborator

@invisiblethreat started a PR but change in the PR was making a behavior change. We decided to introduce a kwarg to use logger instead of print to make this change but a follow PR is not yet put out. @ronlut Would you like to use PR #1893 and build on it to add a kwarg?

@ronlut
Copy link

ronlut commented Jun 24, 2024

@sfc-gh-aalam will try to do it soon, thanks for the update

@dlouseiro dlouseiro mentioned this issue Oct 23, 2024
Open
@dlouseiro
Copy link

dlouseiro commented Oct 23, 2024 •
edited
Loading

@sfc-gh-aalam @ronlut any updates here? This causes issues in any library/framework relying on a stdout (e.g. singer tap, as I reported here).So, I'd agree with @invisiblethreat here and believe logging should be the default option, allowing for an optional more verbose behaviour when needed/wanted by the user.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sfc-gh-aalam sfc-gh-aalam

Labels
enhancement The issue is a request for improvement or a new feature status-pr_pending_merge A PR is made and is under review triaged
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Convert print statements to logging statements invisiblethreat/snowflake-connector-python
5 participants
@invisiblethreat @ronlut @dlouseiro @sfc-gh-dszmolka @sfc-gh-aalam