search

snowflakedb / snowflake-connector-python

Snowflake Connector for Python
https://pypi.python.org/pypi/snowflake-connector-python/
Apache License 2.0
601 stars 473 forks source link

SNOW-701732: Connector keep alive feature doesn't work anymore with version > 2.8.0 #1361

Closed Alquant closed 1 year ago

Alquant commented 1 year ago

Please answer these questions before submitting your issue. Thanks!

  1. What version of Python are you using?

    Python 3.7.13

  2. What operating system and processor architecture are you using?

    Using the image "google/cloud-sdk:alpine" on a google cloud run machine

  3. What are the component versions in the environment (pip freeze)?

Django-3.2.16 MarkupSafe-2.1.1 Unidecode-1.3.6 aiohttp-3.8.3 aiosignal-1.3.1 asgiref-3.5.2 asn1crypto-1.5.1 astroid-2.12.13 async-timeout-4.0.2 asynctest-0.13.0 attrs-22.1.0 beautifulsoup4-4.11.1 black-22.8.0 bs4-0.0.1 cachecontrol-0.12.11 cachetools-5.2.0 certifi-2022.9.24 cffi-1.15.1 cfgv-3.3.1 charset-normalizer-2.1.1 click-8.1.3 cryptography-38.0.4 cycler-0.11.0 decorator-5.1.1 dill-0.3.6 distlib-0.3.6 django-cors-headers-3.13.0 djangorestframework-3.14.0 djangorestframework-jsonapi-6.0.0 dnspython-2.2.1 exchange-calendars-3.6.3 filelock-3.8.0 firebase-admin-6.0.1 flake8-5.0.4 fonttools-4.38.0 freezegun-1.2.2 frozenlist-1.3.3 fsspec-2022.11.0 gcsfs-2022.11.0 google-api-core-2.10.2 google-api-python-client-2.66.0 google-auth-2.14.1 google-auth-httplib2-0.1.0 google-auth-oauthlib-0.7.1 google-cloud-appengine-logging-1.1.6 google-cloud-audit-log-0.2.4 google-cloud-core-2.3.2 google-cloud-firestore-2.7.2 google-cloud-logging-3.2.4 google-cloud-pubsub-2.13.11 google-cloud-run-0.4.1 google-cloud-secret-manager-2.12.6 google-cloud-storage-2.6.0 google-cloud-tasks-2.10.4 google-crc32c-1.5.0 google-resumable-media-2.4.0 googleapis-common-protos-1.57.0 greenlet-2.0.1 grpc-google-iam-v1-0.12.4 grpcio-1.50.0 grpcio-status-1.50.0 gunicorn-20.1.0 httplib2-0.21.0 identify-2.5.9 idna-3.4 importlib-metadata-4.2.0 inflection-0.5.1 intrinio_sdk-6.22.2 investpy-1.0.8 isort-5.10.1 joblib-1.2.0 kiwisolver-1.4.4 korean_lunar_calendar-0.3.1 lazy-object-proxy-1.8.0 lxml-4.9.1 mailjet_rest-1.3.4 matplotlib-3.5.3 mccabe-0.7.0 more-itertools-9.0.0 msgpack-1.0.4 multidict-6.0.2 mypy-extensions-0.4.3 networkx-2.6.3 nodeenv-1.7.0 numpy-1.21.6 oauthlib-3.2.2 oscrypto-1.3.0 overrides-7.3.1 packaging-21.3 pandas-1.3.5 pathspec-0.10.2 pillow-9.3.0 platformdirs-2.5.4 pre-commit-2.20.0 proto-plus-1.22.1 protobuf-4.21.9 pyOpenSSL-22.1.0 pyarrow-8.0.0 pyasn1-0.4.8 pyasn1-modules-0.2.8 pycodestyle-2.9.1 pycoingecko-3.1.0 pycparser-2.21 pycryptodomex-3.16.0 pyflakes-2.5.0 pyjwt-2.6.0 pylint-2.15.3 pyluach-2.0.2 pymongo-4.3.3 pyparsing-3.0.9 python-dateutil-2.8.2 python-dotenv-0.21.0 pytz-2022.6 pyyaml-6.0 quandl-3.7.0 requests-2.28.1 requests-oauthlib-1.3.1 rest-pandas-1.1.0 retrying-1.3.4 rsa-4.9 scikit-learn-1.0.2 scipy-1.7.3 sentry-sdk-1.9.10 setuptools-65.6.3 six-1.16.0 snowflake-connector-python-2.8.3 snowflake-sqlalchemy-1.4.4 soupsieve-2.3.2.post1 sqlalchemy-1.4.44 sqlparse-0.4.3 threadpoolctl-3.1.0 toml-0.10.2 tomli-2.0.1 tomlkit-0.11.6 toolz-0.12.0 typed-ast-1.5.4 typing-extensions-4.4.0 uritemplate-4.1.1 urllib3-1.26.13 virtualenv-20.16.2 werkzeug-2.2.2 wrapt-1.14.1 yarl-1.8.1 zipp-3.11.0

  1. What did you do?

Our backend uses snowflake.connector.connect to create a connection to Snowflake, and as we have a lot of requests, we avoid recreating the connection all the time hence we provide the client_session_keep_alive parameter to True to the connector constructor. Our issue is that since 2.8.1, when the hearthbeat happens (after 1h by default), we see this:

Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')"))': /session/heartbeat?requestId=****&request_guid=****

Followed by:

Failed to get the response. Hanging? method: post, url: https://****.europe-west4.gcp.snowflakecomputing.com:443/session/heartbeat?requestId=****f&request_guid=****, headers:{'Content-Type': 'application/json', 'accept': 'application/json', 'User-Agent': 'PythonConnector/2.8.3 (Linux-4.4.0-x86_64-with-debian-buster-sid) CPython/3.7.13'}, data: None

This doesn't kill the machines, hence when we have requests reaching them later, the queries needing Snowflake give this error:

snowflake.connector.errors.ProgrammingError: 390114 (08001): None: Authentication token has expired.  The user must authenticate again.

Basically, keep alive feature doesn't work anymore for version > 2.8.0.

sfc-gh-stan commented 1 year ago

Hi @Alquant , thank you for reaching out. We could not reproduce this issue locally. Based on the error message, I can see that the heartbeat is sent, but the request hangs due to a failing TLS handshake. This seems more like a networking issue. Additionally, is this error consistently reproducible? You could turn on logging and set CLIENT_SESSION_KEEP_ALIVE_HEARTBEAT_FREQUENCY to 900 and check if the heartbeat requests are being set every 15 minutes as expected.

Alquant commented 1 year ago

Hi, so I put the 900 seconds, and it's failing as expected every 15 minutes, as you can see in the logs.

2022-12-01 10:05:10,457 - Thread-4 connection.py:1347 - _heartbeat_tick() - DEBUG - heartbeating!
2022-12-01 10:05:11,358 - Thread-4 network.py:579 - _heartbeat() - DEBUG - request_id: id1
2022-12-01 10:05:11,557 - Thread-4 network.py:1147 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 1/1 active sessions
2022-12-01 10:05:11,757 - Thread-4 network.py:830 - _request_exec_wrapper() - DEBUG - remaining request timeout: None, retry cnt: 1
2022-12-01 10:05:11,758 - Thread-4 network.py:808 - add_request_guid() - DEBUG - Request guid: id2
2022-12-01 10:05:11,758 - Thread-4 network.py:1006 - _request_exec() - DEBUG - socket timeout: 60
2022-12-01 10:05:12,657 - Thread-4 connectionpool.py:273 - _get_conn() - DEBUG - Resetting dropped connection: ****.europe-west4.gcp.snowflakecomputing.com
2022-12-01 10:05:13,157 - Thread-4 connection.py:1347 - _heartbeat_tick() - DEBUG - heartbeating!
2022-12-01 10:05:13,158 - Thread-4 network.py:579 - _heartbeat() - DEBUG - request_id: id3
2022-12-01 10:05:13,158 - Thread-4 network.py:1147 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 1/1 active sessions
2022-12-01 10:05:13,158 - Thread-4 network.py:830 - _request_exec_wrapper() - DEBUG - remaining request timeout: None, retry cnt: 1
2022-12-01 10:05:13,158 - Thread-4 network.py:808 - add_request_guid() - DEBUG - Request guid: id4
2022-12-01 10:05:13,158 - Thread-4 network.py:1006 - _request_exec() - DEBUG - socket timeout: 60
2022-12-01 10:05:13,858 - Thread-4 connectionpool.py:273 - _get_conn() - DEBUG - Resetting dropped connection: ****.europe-west4.gcp.snowflakecomputing.com
2022-12-01 10:05:22,140 - Thread-4 ssl_wrap_socket.py:83 - ssl_wrap_socket_with_ocsp() - DEBUG - OCSP Mode: FAIL_OPEN, OCSP response cache file name: None
2022-12-01 10:05:22,140 - Thread-4 ocsp_snowflake.py:523 - reset_ocsp_response_cache_uri() - DEBUG - ocsp_response_cache_uri: file:///home/cnb/.cache/snowflake/ocsp_response_cache.json
2022-12-01 10:05:22,141 - Thread-4 ocsp_snowflake.py:527 - reset_ocsp_response_cache_uri() - DEBUG - OCSP_VALIDATION_CACHE size: 190
2022-12-01 10:05:22,141 - Thread-4 ocsp_snowflake.py:334 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP response cache server is enabled: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json
2022-12-01 10:05:22,141 - Thread-4 ocsp_snowflake.py:346 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP dynamic cache server RETRY URL: None
2022-12-01 10:05:22,141 - Thread-4 ocsp_snowflake.py:956 - validate() - DEBUG - validating certificate: ****.europe-west4.gcp.snowflakecomputing.com
2022-12-01 10:05:22,141 - Thread-4 ocsp_asn1crypto.py:427 - extract_certificate_chain() - DEBUG - # of certificates: 3
2022-12-01 10:05:22,142 - Thread-4 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'California'), ('locality_name', 'San Mateo'), ('organization_name', 'Snowflake Inc.'), ('common_name', '*.europe-west4.gcp.snowflakecomputing.com')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')])
2022-12-01 10:05:22,143 - Thread-4 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')])
2022-12-01 10:05:22,144 - Thread-4 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')])
2022-12-01 10:05:22,148 - Thread-4 ocsp_snowflake.py:722 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'California'), ('locality_name', 'San Mateo'), ('organization_name', 'Snowflake Inc.'), ('common_name', '*.europe-west4.gcp.snowflakecomputing.com')])
2022-12-01 10:05:22,157 - Thread-4 ocsp_snowflake.py:722 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')])
2022-12-01 10:05:22,159 - Thread-4 ocsp_snowflake.py:1013 - _validate() - DEBUG - ok
2022-12-01 10:05:22,188 - Thread-4 connectionpool.py:465 - _make_request() - DEBUG - https://****.europe-west4.gcp.snowflakecomputing.com:443 "POST /session/heartbeat?requestId=id3&request_guid=id4 HTTP/1.1" 200 76
2022-12-01 10:05:22,189 - Thread-4 network.py:1032 - _request_exec() - DEBUG - SUCCESS
2022-12-01 10:05:22,189 - Thread-4 network.py:1153 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 0/1 active sessions
2022-12-01 10:05:22,189 - Thread-4 network.py:717 - _post_request() - DEBUG - ret[code] = None, after post request
2022-12-01 10:05:34,357 - Thread-4 retry.py:594 - increment() - DEBUG - Incremented Retry for (url='/session/heartbeat?requestId=id1&request_guid=id2'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2022-12-01 10:05:34,857 - Thread-4 connectionpool.py:813 - urlopen() - WARNING - Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')"))': /session/heartbeat?requestId=id1&request_guid=id2
2022-12-01 10:05:35,557 - Thread-4 connectionpool.py:1007 - _new_conn() - DEBUG - Starting new HTTPS connection (2): ****.europe-west4.gcp.snowflakecomputing.com:443
2022-12-01 10:05:54,658 - Thread-4 network.py:1064 - _request_exec() - DEBUG - Hit non-retryable SSL error, HTTPSConnectionPool(host='****.europe-west4.gcp.snowflakecomputing.com', port=443): Max retries exceeded with url: /session/heartbeat?requestId=id1&request_guid=id2 (Caused by SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')")))
2022-12-01 10:05:55,157 - Thread-4 network.py:973 - _handle_unknown_error() - ERROR - Failed to get the response. Hanging? method: post, url: https://****.europe-west4.gcp.snowflakecomputing.com:443/session/heartbeat?requestId=id1&request_guid=id2, headers:{'Content-Type': 'application/json', 'accept': 'application/json', 'User-Agent': 'PythonConnector/2.8.3 (Linux-4.4.0-x86_64-with-debian-buster-sid) CPython/3.7.13'}, data: None
2022-12-01 10:05:56,258 - Thread-4 network.py:1153 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 0/1 active sessions
2022-12-01 10:05:56,757 - Thread-4 time_util.py:41 - run() - DEBUG - failed to heartbeat: 250003: 250003: Failed to get the response. Hanging? method: post, url: https://****.europe-west4.gcp.snowflakecomputing.com:443/session/heartbeat?requestId=id1&request_guid=id2
2022-12-01 10:20:56,758 - Thread-4 connection.py:1347 - _heartbeat_tick() - DEBUG - heartbeating!
2022-12-01 10:20:56,758 - Thread-4 network.py:579 - _heartbeat() - DEBUG - request_id: id5
2022-12-01 10:20:56,759 - Thread-4 network.py:1147 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 1/1 active sessions
2022-12-01 10:20:56,759 - Thread-4 network.py:830 - _request_exec_wrapper() - DEBUG - remaining request timeout: None, retry cnt: 1
2022-12-01 10:20:56,759 - Thread-4 network.py:808 - add_request_guid() - DEBUG - Request guid: id6
2022-12-01 10:20:56,759 - Thread-4 network.py:1006 - _request_exec() - DEBUG - socket timeout: 60
2022-12-01 10:20:57,158 - Thread-4 connectionpool.py:1007 - _new_conn() - DEBUG - Starting new HTTPS connection (3): ****.europe-west4.gcp.snowflakecomputing.com:443
2022-12-01 10:21:11,557 - Thread-4 retry.py:594 - increment() - DEBUG - Incremented Retry for (url='/session/heartbeat?requestId=id5&request_guid=id6'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2022-12-01 10:21:11,857 - Thread-4 connectionpool.py:813 - urlopen() - WARNING - Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')"))': /session/heartbeat?requestId=id5&request_guid=id6
2022-12-01 10:21:11,858 - Thread-4 connectionpool.py:1007 - _new_conn() - DEBUG - Starting new HTTPS connection (4): ****.europe-west4.gcp.snowflakecomputing.com:443
2022-12-01 10:21:33,657 - Thread-4 network.py:1064 - _request_exec() - DEBUG - Hit non-retryable SSL error, HTTPSConnectionPool(host='****.europe-west4.gcp.snowflakecomputing.com', port=443): Max retries exceeded with url: /session/heartbeat?requestId=id5&request_guid=id6 (Caused by SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')")))
2022-12-01 10:21:34,757 - Thread-4 network.py:973 - _handle_unknown_error() - ERROR - Failed to get the response. Hanging? method: post, url: https://****.europe-west4.gcp.snowflakecomputing.com:443/session/heartbeat?requestId=id5&request_guid=id6, headers:{'Content-Type': 'application/json', 'accept': 'application/json', 'User-Agent': 'PythonConnector/2.8.3 (Linux-4.4.0-x86_64-with-debian-buster-sid) CPython/3.7.13'}, data: None
2022-12-01 10:21:36,357 - Thread-4 network.py:1153 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 0/1 active sessions
2022-12-01 10:21:36,457 - Thread-4 time_util.py:41 - run() - DEBUG - failed to heartbeat: 250003: 250003: Failed to get the response. Hanging? method: post, url: https://****.europe-west4.gcp.snowflakecomputing.com:443/session/heartbeat?requestId=id5&request_guid=id6
sfc-gh-stan commented 1 year ago

How many SnowflakeConnection objects are present here? I see that heartbeat requests are being sent as expected, one of them succeeded and the rest failed due to SSL error. Please try running the code outside Google Cloud Run container, maybe locally on your machine, do you still see the SSL errors? If so, please provide a minimal reproducing example so we can further investigate.

Alquant commented 1 year ago

We use a QueuePool to have multiple connections available:

from sqlalchemy.pool.impl import QueuePool

QueuePool(
    creator=_create_snowflake_connection,
    pool_size=4,
    max_overflow=0,
    reset_on_return=None,
)

To be sure I relaunched on GCP Cloud run but with 1 machine and 1 connection per machine, and I get this:

2022-12-02 09:45:45,420 - Thread-2 connection.py:1347 - _heartbeat_tick() - DEBUG - heartbeating!
2022-12-02 09:45:45,421 - Thread-2 network.py:579 - _heartbeat() - DEBUG - request_id: id1
2022-12-02 09:45:45,421 - Thread-2 network.py:1147 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 1/1 active sessions
2022-12-02 09:45:45,421 - Thread-2 network.py:830 - _request_exec_wrapper() - DEBUG - remaining request timeout: None, retry cnt: 1
2022-12-02 09:45:45,421 - Thread-2 network.py:808 - add_request_guid() - DEBUG - Request guid: id2
2022-12-02 09:45:45,421 - Thread-2 network.py:1006 - _request_exec() - DEBUG - socket timeout: 60
2022-12-02 09:45:45,974 - Thread-2 connectionpool.py:273 - _get_conn() - DEBUG - Resetting dropped connection: ****.europe-west4.gcp.snowflakecomputing.com
2022-12-02 09:45:59,474 - Thread-2 retry.py:594 - increment() - DEBUG - Incremented Retry for (url='/session/heartbeat?requestId=id1&request_guid=id2'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2022-12-02 09:45:59,475 - Thread-2 connectionpool.py:813 - urlopen() - WARNING - Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')"))': /session/heartbeat?requestId=id1&request_guid=id2
2022-12-02 09:45:59,574 - Thread-2 connectionpool.py:1007 - _new_conn() - DEBUG - Starting new HTTPS connection (2): ****.europe-west4.gcp.snowflakecomputing.com:443
2022-12-02 09:46:08,875 - Thread-2 ssl_wrap_socket.py:83 - ssl_wrap_socket_with_ocsp() - DEBUG - OCSP Mode: FAIL_OPEN, OCSP response cache file name: None
2022-12-02 09:46:08,974 - Thread-2 ocsp_snowflake.py:523 - reset_ocsp_response_cache_uri() - DEBUG - ocsp_response_cache_uri: file:///home/cnb/.cache/snowflake/ocsp_response_cache.json
2022-12-02 09:46:08,974 - Thread-2 ocsp_snowflake.py:527 - reset_ocsp_response_cache_uri() - DEBUG - OCSP_VALIDATION_CACHE size: 190
2022-12-02 09:46:08,974 - Thread-2 ocsp_snowflake.py:334 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP response cache server is enabled: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json
2022-12-02 09:46:08,975 - Thread-2 ocsp_snowflake.py:346 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP dynamic cache server RETRY URL: None
2022-12-02 09:46:08,975 - Thread-2 ocsp_snowflake.py:956 - validate() - DEBUG - validating certificate: ****.europe-west4.gcp.snowflakecomputing.com
2022-12-02 09:46:08,975 - Thread-2 ocsp_asn1crypto.py:427 - extract_certificate_chain() - DEBUG - # of certificates: 3
2022-12-02 09:46:09,674 - Thread-2 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'California'), ('locality_name', 'San Mateo'), ('organization_name', 'Snowflake Inc.'), ('common_name', '*.europe-west4.gcp.snowflakecomputing.com')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')])
2022-12-02 09:46:10,374 - Thread-2 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')])
2022-12-02 09:46:10,375 - Thread-2 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')])
2022-12-02 09:46:11,374 - Thread-2 ocsp_snowflake.py:722 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'California'), ('locality_name', 'San Mateo'), ('organization_name', 'Snowflake Inc.'), ('common_name', '*.europe-west4.gcp.snowflakecomputing.com')])
2022-12-02 09:46:12,074 - Thread-2 ocsp_snowflake.py:722 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')])
2022-12-02 09:46:12,275 - Thread-2 ocsp_snowflake.py:1013 - _validate() - DEBUG - ok
2022-12-02 09:46:12,775 - Thread-2 connectionpool.py:465 - _make_request() - DEBUG - https://****.europe-west4.gcp.snowflakecomputing.com:443 "POST /session/heartbeat?requestId=id1&request_guid=id2 HTTP/1.1" 200 76
2022-12-02 09:46:13,074 - Thread-2 network.py:1032 - _request_exec() - DEBUG - SUCCESS
2022-12-02 09:46:13,075 - Thread-2 network.py:1153 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 0/1 active sessions
2022-12-02 09:46:13,075 - Thread-2 network.py:717 - _post_request() - DEBUG - ret[code] = None, after post request
2022-12-02 10:01:13,076 - Thread-2 connection.py:1347 - _heartbeat_tick() - DEBUG - heartbeating!
2022-12-02 10:01:13,076 - Thread-2 network.py:579 - _heartbeat() - DEBUG - request_id: id3
2022-12-02 10:01:13,174 - Thread-2 network.py:1147 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 1/1 active sessions
2022-12-02 10:01:13,174 - Thread-2 network.py:830 - _request_exec_wrapper() - DEBUG - remaining request timeout: None, retry cnt: 1
2022-12-02 10:01:13,175 - Thread-2 network.py:808 - add_request_guid() - DEBUG - Request guid: id4
2022-12-02 10:01:13,175 - Thread-2 network.py:1006 - _request_exec() - DEBUG - socket timeout: 60
2022-12-02 10:01:13,374 - Thread-2 connectionpool.py:273 - _get_conn() - DEBUG - Resetting dropped connection: ****.europe-west4.gcp.snowflakecomputing.com
2022-12-02 10:01:26,975 - Thread-2 retry.py:594 - increment() - DEBUG - Incremented Retry for (url='/session/heartbeat?requestId=id3&request_guid=id4'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2022-12-02 10:01:26,975 - Thread-2 connectionpool.py:813 - urlopen() - WARNING - Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')"))': /session/heartbeat?requestId=id3&request_guid=id4
2022-12-02 10:01:27,374 - Thread-2 connectionpool.py:1007 - _new_conn() - DEBUG - Starting new HTTPS connection (3): ****.europe-west4.gcp.snowflakecomputing.com:443
2022-12-02 10:01:37,974 - Thread-2 ssl_wrap_socket.py:83 - ssl_wrap_socket_with_ocsp() - DEBUG - OCSP Mode: FAIL_OPEN, OCSP response cache file name: None
2022-12-02 10:01:37,974 - Thread-2 ocsp_snowflake.py:523 - reset_ocsp_response_cache_uri() - DEBUG - ocsp_response_cache_uri: file:///home/cnb/.cache/snowflake/ocsp_response_cache.json
2022-12-02 10:01:37,974 - Thread-2 ocsp_snowflake.py:527 - reset_ocsp_response_cache_uri() - DEBUG - OCSP_VALIDATION_CACHE size: 190
2022-12-02 10:01:37,975 - Thread-2 ocsp_snowflake.py:334 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP response cache server is enabled: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json
2022-12-02 10:01:37,975 - Thread-2 ocsp_snowflake.py:346 - reset_ocsp_dynamic_cache_server_url() - DEBUG - OCSP dynamic cache server RETRY URL: None
2022-12-02 10:01:37,975 - Thread-2 ocsp_snowflake.py:956 - validate() - DEBUG - validating certificate: ****.europe-west4.gcp.snowflakecomputing.com
2022-12-02 10:01:38,074 - Thread-2 ocsp_asn1crypto.py:427 - extract_certificate_chain() - DEBUG - # of certificates: 3
2022-12-02 10:01:38,275 - Thread-2 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'California'), ('locality_name', 'San Mateo'), ('organization_name', 'Snowflake Inc.'), ('common_name', '*.europe-west4.gcp.snowflakecomputing.com')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')])
2022-12-02 10:01:38,774 - Thread-2 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')])
2022-12-02 10:01:39,074 - Thread-2 ocsp_asn1crypto.py:433 - extract_certificate_chain() - DEBUG - subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')]), issuer: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('organizational_unit_name', 'www.digicert.com'), ('common_name', 'DigiCert Global Root CA')])
2022-12-02 10:01:40,374 - Thread-2 ocsp_snowflake.py:722 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('state_or_province_name', 'California'), ('locality_name', 'San Mateo'), ('organization_name', 'Snowflake Inc.'), ('common_name', '*.europe-west4.gcp.snowflakecomputing.com')])
2022-12-02 10:01:40,575 - Thread-2 ocsp_snowflake.py:722 - find_cache() - DEBUG - hit cache for subject: OrderedDict([('country_name', 'US'), ('organization_name', 'DigiCert Inc'), ('common_name', 'DigiCert TLS RSA SHA256 2020 CA1')])
2022-12-02 10:01:40,875 - Thread-2 ocsp_snowflake.py:1013 - _validate() - DEBUG - ok
2022-12-02 10:01:41,674 - Thread-2 network.py:1103 - _request_exec() - DEBUG - Hit retryable client error. Retrying... Ignore the following error stack: ('Connection aborted.', OSError("(32, 'EPIPE')"))
Traceback (most recent call last): 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/contrib/pyopenssl.py", line 346, in _send_until_done return self.connection.send(data) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/OpenSSL/SSL.py", line 1899, in send self._raise_ssl_error(self._ssl, result) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/OpenSSL/SSL.py", line 1699, in _raise_ssl_error raise SysCallError(errno, errorcode.get(errno)) OpenSSL.SSL.SysCallError: (32, 'EPIPE')
During handling of the above exception, another exception occurred:
Traceback (most recent call last): 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connectionpool.py", line 710, in urlopen chunked=chunked, 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connectionpool.py", line 398, in _make_request conn.request(method, url, **httplib_request_kw) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connection.py", line 239, in request super(HTTPConnection, self).request(method, url, body=body, headers=headers) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1281, in request self._send_request(method, url, body, headers, encode_chunked) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1327, in _send_request self.endheaders(body, encode_chunked=encode_chunked) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1276, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1036, in _send_output self.send(msg) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 997, in send self.sock.sendall(data) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/contrib/pyopenssl.py", line 358, in sendall data[total_sent : total_sent + SSL_WRITE_BLOCKSIZE] 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/contrib/pyopenssl.py", line 352, in _send_until_done raise SocketError(str(e)) OSError: (32, 'EPIPE')
During handling of the above exception, another exception occurred:
Traceback (most recent call last): 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/requests/adapters.py", line 499, in send timeout=timeout, 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connectionpool.py", line 828, in urlopen **response_kw 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connectionpool.py", line 788, in urlopen method, url, error=e, _pool=self, _stacktrace=sys.exc_info()[2] 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/util/retry.py", line 550, in increment raise six.reraise(type(error), error, _stacktrace) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/packages/six.py", line 769, in reraise raise value.with_traceback(tb) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connectionpool.py", line 710, in urlopen chunked=chunked, 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connectionpool.py", line 398, in _make_request conn.request(method, url, **httplib_request_kw) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/connection.py", line 239, in request super(HTTPConnection, self).request(method, url, body=body, headers=headers) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1281, in request self._send_request(method, url, body, headers, encode_chunked) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1327, in _send_request self.endheaders(body, encode_chunked=encode_chunked) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1276, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 1036, in _send_output self.send(msg) 
File "/layers/google.python.runtime/python/lib/python3.7/http/client.py", line 997, in send self.sock.sendall(data) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/contrib/pyopenssl.py", line 358, in sendall data[total_sent : total_sent + SSL_WRITE_BLOCKSIZE] 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/urllib3/contrib/pyopenssl.py", line 352, in _send_until_done raise SocketError(str(e)) snowflake.connector.vendored.urllib3.exceptions.ProtocolError: ('Connection aborted.', OSError("(32, 'EPIPE')"))
During handling of the above exception, another exception occurred:
Traceback (most recent call last): 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/network.py", line 1026, in _request_exec auth=SnowflakeAuth(token), 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/requests/sessions.py", line 587, in request resp = self.send(prep, **send_kwargs) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/requests/sessions.py", line 701, in send r = adapter.send(request, **kwargs) 
File "/layers/google.python.pip/pip/lib/python3.7/site-packages/snowflake/connector/vendored/requests/adapters.py", line 547, in send raise ConnectionError(err, request=request) snowflake.connector.vendored.requests.exceptions.ConnectionError: ('Connection aborted.', OSError("(32, 'EPIPE')"))
2022-12-02 10:01:42,885 - Thread-2 network.py:908 - _request_exec_wrapper() - DEBUG - retrying: errorclass=<class 'snowflake.connector.vendored.requests.exceptions.ConnectionError'>, error=('Connection aborted.', OSError("(32, 'EPIPE')")), counter=1, sleeping=3(s)
Error detected in [service] version [service]-[version]
Error detected in [service] version [service]-[version]
Error detected in [service] version [service]-[version]
Error detected in [service] version [service]-[version]
2022-12-02 10:01:45,886 - Thread-2 network.py:830 - _request_exec_wrapper() - DEBUG - remaining request timeout: None, retry cnt: 2
2022-12-02 10:01:45,886 - Thread-2 network.py:808 - add_request_guid() - DEBUG - Request guid: id5
2022-12-02 10:01:45,887 - Thread-2 network.py:1006 - _request_exec() - DEBUG - socket timeout: 60
2022-12-02 10:01:45,974 - Thread-2 connectionpool.py:1007 - _new_conn() - DEBUG - Starting new HTTPS connection (4): ****.europe-west4.gcp.snowflakecomputing.com:443
2022-12-02 10:02:00,974 - Thread-2 retry.py:594 - increment() - DEBUG - Incremented Retry for (url='/session/heartbeat?requestId=id3&request_guid=id5'): Retry(total=0, connect=None, read=None, redirect=None, status=None)
2022-12-02 10:02:00,974 - Thread-2 connectionpool.py:813 - urlopen() - WARNING - Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')"))': /session/heartbeat?requestId=id3&request_guid=id5
2022-12-02 10:02:01,074 - Thread-2 connectionpool.py:1007 - _new_conn() - DEBUG - Starting new HTTPS connection (5): ****.europe-west4.gcp.snowflakecomputing.com:443
2022-12-02 10:02:17,174 - Thread-2 network.py:1064 - _request_exec() - DEBUG - Hit non-retryable SSL error, HTTPSConnectionPool(host='****.europe-west4.gcp.snowflakecomputing.com', port=443): Max retries exceeded with url: /session/heartbeat?requestId=id3&request_guid=id5 (Caused by SSLError(SSLError("bad handshake: SysCallError(-1, 'Unexpected EOF')")))
2022-12-02 10:02:18,074 - Thread-2 network.py:973 - _handle_unknown_error() - ERROR - Failed to get the response. Hanging? method: post, url: https://****.europe-west4.gcp.snowflakecomputing.com:443/session/heartbeat?requestId=id3&request_guid=id5, headers:{'Content-Type': 'application/json', 'accept': 'application/json', 'User-Agent': 'PythonConnector/2.8.3 (Linux-4.4.0-x86_64-with-debian-buster-sid) CPython/3.7.13'}, data: None
2022-12-02 10:02:19,374 - Thread-2 network.py:1153 - _use_requests_session() - DEBUG - Session status for SessionPool '****.europe-west4.gcp.snowflakecomputing.com', SessionPool 0/1 active sessions
2022-12-02 10:02:19,375 - Thread-2 time_util.py:41 - run() - DEBUG - failed to heartbeat: 250003: 250003: Failed to get the response. Hanging? method: post, url: https://****.europe-west4.gcp.snowflakecomputing.com:443/session/heartbeat?requestId=id3&request_guid=id5

As you can see, the first heartbeat works, but then fail. I can't reproduce this error locally, I am looking for a way to reproduce it easily.

Alquant commented 1 year ago

I found what in the 2.8.1 is causing our issue: the bump of cryptography from <37.0.0 to <39.0.0. By pinning cryptography to 36.0.2 and letting the snowflake-connector-python[pandas] pick 2.8.3, no more issues. The changelog for 37.0.0 of cryptography has breaking changes linked to SSL. We are building the image we deploy on GCP Cloud Run through GCP Cloud Build and build pack, I will investigate there if there might be a problem with SSL.

sfc-gh-achandrasekaran commented 1 year ago

@Alquant is this still happening?

sfc-gh-achandrasekaran commented 1 year ago

Please reopen if this continues to occur and we will investigate

Alquant commented 1 year ago

We finally found what was causing the issue. The answer is available in https://github.com/snowflakedb/snowflake-connector-python/issues/1764.