SNOW-1296831: Intermittent hanging when initiating a connection

[kbushman]

Python version

Python 3.11.3 (main, May 23 2023, 13:34:03) [GCC 10.2.1 20210110]

Operating system and processor architecture

Linux-5.10.205-195.804.amzn2.x86_64-x86_64-with-glibc2.31

Installed packages

aiorwlock==1.1.0
amqp==5.1.1
anyio==3.7.1
appdirs==1.4.4
appdirs-stubs==0.1.0
asgiref==3.7.2
asn1crypto==1.5.1
async-generator==1.10
attrs==23.1.0
billiard==4.1.0
boto3==1.28.34
botocore==1.31.34
CacheControl==0.12.14
celery==5.3.1
certifi==2023.7.22
cffi==1.15.1
charset-normalizer==2.1.1
cleo==2.1.0
click==8.1.7
click-didyoumean==0.3.0
click-plugins==1.1.1
click-repl==0.3.0
crashtest==0.4.1
cryptography==40.0.2
Deprecated==1.2.14
distlib==0.3.8
dnspython==2.2.1
dulwich==0.20.50
et-xmlfile==1.1.0
fastapi==0.95.2
filelock==3.12.2
firebolt-sdk==0.16.4
firebolt-sqlalchemy==0.9.1
googleapis-common-protos==1.56.2
greenlet==2.0.2
grpcio==1.57.0
gunicorn==20.1.0
h11==0.14.0
h2==4.1.0
hpack==4.0.0
html5lib==1.1
httpcore==0.17.2
httpx==0.24.0
hyperframe==6.0.1
idna==3.4
importlib-metadata==7.0.1
jaraco.classes==3.3.0
jeepney==0.8.0
jmespath==1.0.1
jsonschema==4.21.1
jsonschema-specifications==2023.12.1
keyring==23.13.1
kombu==5.3.1
lockfile==0.12.2
more-itertools==10.2.0
msgpack==1.0.7
munch==2.5.0
numpy==1.23.4
openpyxl==3.1.2
opentelemetry-api==1.12.0
opentelemetry-exporter-jaeger==1.12.0
opentelemetry-exporter-jaeger-proto-grpc==1.12.0
opentelemetry-exporter-jaeger-thrift==1.12.0
opentelemetry-instrumentation==0.33b0
opentelemetry-instrumentation-asgi==0.33b0
opentelemetry-instrumentation-fastapi==0.33b0
opentelemetry-sdk==1.12.0
opentelemetry-semantic-conventions==0.33b0
opentelemetry-util-http==0.33b0
oracledb==1.3.1
oscrypto==1.3.0
outcome==1.2.0
packaging==23.1
pandas==1.5.0
pexpect==4.9.0
pkginfo==1.9.6
platformdirs==2.6.2
poetry==1.3.2
poetry-core==1.4.0
poetry-plugin-export==1.3.1
prompt-toolkit==3.0.39
protobuf==3.20.3
ptyprocess==0.7.0
pyarrow==12.0.0
pycparser==2.21
pycryptodomex==3.18.0
pydantic==1.10.12
PyJWT==2.5.0
pymongo==4.2.0
pyodbc==4.0.39
pyOpenSSL==23.1.0
python-dateutil==2.8.2
python-dotenv==1.0.0
pytz==2023.3
PyYAML==6.0
rapidfuzz==3.6.1
readerwriterlock==1.0.9
referencing==0.33.0
requests==2.28.1
requests-toolbelt==0.10.1
rpds-py==0.17.1
s3transfer==0.6.2
SecretStorage==3.3.3
shellingham==1.5.4
six==1.16.0
smart-open==6.2.0
sniffio==1.3.0
snowflake-connector-python==3.0.4
snowflake-sqlalchemy==1.4.7
sortedcontainers==2.4.0
SQLAlchemy==1.4.48
sqlparse==0.4.4
starlette==0.27.0
thrift==0.16.0
tomlkit==0.12.3
trio==0.21.0
trove-classifiers==2024.1.31
typing_extensions==4.3.0
tzdata==2023.3
urllib3==1.26.16
uvicorn==0.18.3
vine==5.0.0
virtualenv==20.21.1
wcwidth==0.2.6
webencodings==0.5.1
wrapt==1.15.0
XlsxWriter==3.1.2
zipp==3.17.0

What did you do?

This is an intermittent issue that we have seen a few times but do not have any way to reproduce. The connector hangs when initiating a connection. It never successfully connects or returns any error message. If we kill this python process and try again, the connection is successful.

What did you expect to see?

Would expect the connection to be successful and able to execute queries.

Can you set logging to DEBUG and collect the logs?

2023-12-06T15:41:27.376201598Z [2023-12-06 15:41:27,376] [110] [DEBUG] - snowflake.connector.connection - REST API object was created: xxxxx.us-east-1.snowflakecomputing.com:443
2023-12-06T15:41:27.376410060Z [2023-12-06 15:41:27,376] [110] [DEBUG] - snowflake.connector.auth._auth - authenticate
2023-12-06T15:41:27.376529542Z [2023-12-06 15:41:27,376] [110] [DEBUG] - snowflake.connector.auth._auth - assertion content: *********
2023-12-06T15:41:27.376575222Z [2023-12-06 15:41:27,376] [110] [DEBUG] - snowflake.connector.auth._auth - account=xxxxx, user=xxxxx, database=xxxxx, schema=xxxxx, warehouse=None, role=None, request_id=874edbb0-282d-4f65-819b-ce7e6f58336f
2023-12-06T15:41:27.376725024Z [2023-12-06 15:41:27,376] [110] [DEBUG] - snowflake.connector.auth._auth - body['data']: {'CLIENT_APP_ID': 'SnowflakeSQLAlchemy', 'CLIENT_APP_VERSION': '1.4.7', 'SVN_REVISION': None, 'ACCOUNT_NAME': 'xxxxx', 'LOGIN_NAME': 'xxxxx', 'CLIENT_ENVIRONMENT': {'APPLICATION': 'SnowflakeSQLAlchemy', 'OS': 'Linux', 'OS_VERSION': 'Linux-5.10.192-183.736.amzn2.x86_64-x86_64-with-glibc2.31', 'PYTHON_VERSION': '3.11.3', 'PYTHON_RUNTIME': 'CPython', 'PYTHON_COMPILER': 'GCC 10.2.1 20210110', 'OCSP_MODE': 'FAIL_OPEN', 'TRACING': 0, 'LOGIN_TIMEOUT': 120, 'NETWORK_TIMEOUT': None}, 'SESSION_PARAMETERS': {'AUTOCOMMIT': False, 'CLIENT_PREFETCH_THREADS': 4}}
2023-12-06T15:41:27.376755725Z [2023-12-06 15:41:27,376] [110] [DEBUG] - snowflake.connector.auth._auth - Timeout set to 120
2023-12-06T15:41:27.377113839Z [2023-12-06 15:41:27,376] [110] [DEBUG] - snowflake.connector.vendored.urllib3.util.retry - Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
2023-12-06T15:41:27.377226681Z [2023-12-06 15:41:27,377] [110] [DEBUG] - snowflake.connector.vendored.urllib3.util.retry - Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
2023-12-06T15:41:27.377271361Z [2023-12-06 15:41:27,377] [110] [DEBUG] - snowflake.connector.network - Session status for SessionPool 'xxxxx.us-east-1.snowflakecomputing.com', SessionPool 1/1 active sessions
2023-12-06T15:41:27.377455994Z [2023-12-06 15:41:27,377] [110] [DEBUG] - snowflake.connector.network - remaining request timeout: 120, retry cnt: 1
2023-12-06T15:41:27.377539465Z [2023-12-06 15:41:27,377] [110] [DEBUG] - snowflake.connector.network - Request guid: 51a3f938-aba0-4ace-8d38-24faac5476ce
2023-12-06T15:41:27.377550495Z [2023-12-06 15:41:27,377] [110] [DEBUG] - snowflake.connector.network - socket timeout: 60
2023-12-06T15:41:27.384165121Z [2023-12-06 15:41:27,383] [110] [DEBUG] - snowflake.connector.vendored.urllib3.connectionpool - Starting new HTTPS connection (1): xxxxx.us-east-1.snowflakecomputing.com:443
2023-12-06T15:41:27.604318809Z [2023-12-06 15:41:27,604] [110] [DEBUG] - snowflake.connector.ssl_wrap_socket - OCSP Mode: FAIL_OPEN, OCSP response cache file name: None
2023-12-06T15:41:27.604373180Z [2023-12-06 15:41:27,604] [110] [DEBUG] - snowflake.connector.ocsp_snowflake - ocsp_response_cache_uri: None
2023-12-06T15:41:27.604381600Z [2023-12-06 15:41:27,604] [110] [DEBUG] - snowflake.connector.ocsp_snowflake - OCSP_VALIDATION_CACHE size: 190
2023-12-06T15:41:27.604503502Z [2023-12-06 15:41:27,604] [110] [DEBUG] - snowflake.connector.ocsp_snowflake - OCSP response cache server is enabled: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json
2023-12-06T15:41:27.604537692Z [2023-12-06 15:41:27,604] [110] [DEBUG] - snowflake.connector.ocsp_snowflake - OCSP dynamic cache server RETRY URL: None

--------- Connector hangs here indefinitely. No further logs when the issue occurs. --------

--------- In cases when connection is successful, we get the same log lines as above but then logs continue with these additional lines. --------



2023-12-06T14:09:32.371162798Z [2023-12-06 14:09:32,371] [110] [DEBUG] - snowflake.connector.ocsp_snowflake - validating certificate: xxxxx.us-east-1.snowflakecomputing.com
2023-12-06T14:09:32.371325119Z [2023-12-06 14:09:32,371] [110] [DEBUG] - snowflake.connector.ocsp_asn1crypto - # of certificates: 4

[sfc-gh-dszmolka]

hey and thanks for submitting this issue ! as a control check, could you please try to reproduce with OCSP turned off ?

con = snowflake.connector.connect(
   ...
   insecure_mode=True,
)

if with OCSP disabled the issue never reproduces, then there's a chance it is related to the issue fixed in #1898 which should be available with the next connector version

[sfc-gh-dszmolka]

as a side note, the above PR is now released with v3.8.0 so you can also test with upgrading to this new version and see if the lock still appears upon OCSP checks

[kbushman]

Ok, thank you! We will try with the upgraded version and report back.

[sfc-gh-dszmolka]

I'm assuming the new version helped you and closing this issue. If you still have the problem even with the fixed version, please comment and I can reopen and look further.