SnowflakeのODBCドライバのログを利用してエラーの原因を確認してみた
このエントリは、Snowflake Advent Calendar 2020の19日目のエントリです。
こんにちは！DA(データアナリティクス)事業本部 インテグレーション部の大高です。
先日、ODBCドライバを利用したExcelアドオン「Excelerator」を触ってみたのですが、その際に想定外のエラーが発生して困っていました。原因が分からずIssueチケットを作成して相談していたのですが、こんなコメントをいただきました。
Do you guys know how to find the ODBC log files? Would you post them here?
「ODBCログファイルってどこに出ているのか全然知らないな…」となって、急いで調べて知っている顔をして返信したので、本エントリでは「SnowflakeのODBCドライバのログファイル」について書きたいと思います。
前提
OSはWindows 10の64bitを利用しています。以下のドキュメントを参考に、SnowflakeのODBCドライバ最新版をインストール済みの環境です。
一般的なODBCログファイルについて
まず、一般的なODBCログファイル出力についてです。「コントロールパネル > 管理ツール > ODBC データ ソース (64 ビット)」から「ODBC データソース アドミニストレーター」を立ち上げます。
この中の「トレース」タブで「ログファイルのパス」が設定できるので、ログファイルの保存先を指定して、「トレースの開始」ボタンをクリックすると記録が開始されます。
あとは、この状態でODBC接続を利用する操作をするとログが出力されていきます。例としては以下のようなログです。
EXCEL 2924-2d24 ENTER SQLAllocEnv HENV * 0x00007FFD704CE510 EXCEL 2924-2d24 EXIT SQLAllocEnv with return code 0 (SQL_SUCCESS) HENV * 0x00007FFD704CE510 ( 0x000002138FB0AAC0)
こちらは本当に汎用的なログなので、これだけだと解析が難しい場合はSnowflakeのODBCログファイルを見ることになります。
SnowflakeのODBCログファイルはどこに出ているのか
SnowflakeのODBCドライバーはODBCのログファイルを出力してくれます。詳細については以下のドキュメントに記載の通りですが、regeditコマンドでレジストリエディタを起動し、HKEY_LOCAL_MACHINE\SOFTWARE\Snowflake\Driverで出力先などの設定値を確認することができます。
ログファイルのパスはLogPathキーの値に記載されており、デフォルトだと「ドキュメント」配下のSnowflake ODBC Driver\logディレクトリに出力されるようになっています。任意のパスに変更して出力先を変更することもできます。
また、LogLevelキーの値でログ出力レベルが設定できるので、必要に応じて設定を変更すると良さそうです。デバッグ時には6に設定すると良さそうですね。
| LegLevel | 出力レベル |
|---|---|
| 0 | 無効 |
| 1 | 致命的なエラー |
| 2 | エラー |
| 3 | 警告 |
| 4 | 情報 |
| 5 | デバッグ |
| 6 | トレース |
どんなログファイルが出力されるのか
実際に私の環境でエラー調査をした際には、上記の設定をした上でODBC接続をしたところ、以下の4つのログが出力されました。
- snowflake_odbc_generic0.log
- snowflake_odbc_connection_0.log
- snowflake_odbc_driver.log
- snowflake_odbc_curl.dmp
それぞれのログファイルの中身を確認しながら、エラーを確認したいと思います。
snowflake_odbc_generic0.log
こちらは一般ログ、となる感じでしょうか。ドライバやOSのバージョンも確認でき、curlのリクエスト時にエラーが発生していることが良く分かりますね。
2020-12-07T13:35:23.322 INFO 5848 Snowflake::Client::IFileTransferAgent.cpp::: External logger injected. libsnowflakeclient version: 0.5.10
2020-12-07T13:35:23.323 TRACE 5848 Simba::Snowflake::SFDriver::SetDriverPropertyValues: Driver version: 2.22.2
2020-12-07T13:35:23.326 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting property (16) with type 4
～(略)～
2020-12-07T13:35:23.327 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting property (19) with type 4
2020-12-07T13:35:23.327 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Not connected to databaseset auto commit
2020-12-07T13:35:23.327 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting property (21) with type 4
2020-12-07T13:35:23.327 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting connection (curl) timeout to: 0
2020-12-07T13:35:23.327 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting property (23) with type 4
2020-12-07T13:35:23.327 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting login timeout to: 0
2020-12-07T13:35:23.327 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting property (24) with type 4
～(略)～
2020-12-07T13:35:23.334 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting property (23) with type 4
2020-12-07T13:35:23.334 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting login timeout to: 120
2020-12-07T13:35:23.336 TRACE 5848 Simba::Snowflake::SFConnection::SetProperty: Setting property (167) with type 2
2020-12-07T13:35:23.336 INFO 5848 Simba::Snowflake::SFConnection::connect: Tracing level: 6
2020-12-07T13:35:23.336 TRACE 5848 Simba::Snowflake::SFConnection::connect: OUT_OF_RANGE_TIMESTAMP_EXCEPTION: off
2020-12-07T13:35:23.336 TRACE 5848 Simba::Snowflake::SFConnection::connect: ClientStoreTemporaryCredential: false
2020-12-07T13:35:23.336 TRACE 5848 sf::CurDesc::checkSSLVersion: ssl version: OpenSSL/1.1.1g
2020-12-07T13:35:23.336 TRACE 5848 Simba::Snowflake::SFConnection::connect: CURLTimeout: 300(s)
2020-12-07T13:35:23.337 TRACE 5848 sf::Mutex::Mutex/ہQ/1370569592 mutex=00000001E5B619A8: sf_mutex
2020-12-07T13:35:23.337 TRACE 5848 Simba::Snowflake::SFConnection::connect: Connecting to server with host=foobar.us-east-1.snowflakecomputing.com, port=443, proxy=, noProxy=, ocspFailOpen=FAIL_OPEN,account=foobar, user=ADMIN, authenticator=snowflake, passcodeInPassword=0, db=DEMO_DB, schema=PUBLIC, warehouse=COMPUTE_WH, role=EXCELANALYST, ssl=1, login timeout=10, network timeout=0, query timeout=0, translate sql=0, tracing level=6, curl timeout=300, curl timeout for login=300, ca bundle file=
2020-12-07T13:35:23.337 TRACE 5848 sf::Connection::connect: Connecting to Snowflake
2020-12-07T13:35:23.337 INFO 5848 sf::Connection::connect: Snowflake ODBC Driver: 2.22.2, OS: Windows, OS Version: 10.0-x86_64
2020-12-07T13:35:23.338 TRACE 5848 sf::Connection::connect: Setting HTTP_PROXY, HTTPS_PROXY, http_proxy and https_proxy environment variables to:
2020-12-07T13:35:23.338 TRACE 5848 sf::Connection::connect: Setting NO_PROXY and no_proxy environment variable to:
2020-12-07T13:35:23.340 TRACE 5848 sf::CurlDescPool::getSubPool: Getting subpool for endPoint=https://foobar.us-east-1.snowflakecomputing.com:443 res=00000108517A1D90
2020-12-07T13:35:23.340 TRACE 5848 sf::CurDesc::reset: cleanup 0
2020-12-07T13:35:23.340 TRACE 5848 sf::CurDesc::reset: curl_easy_init 0000010851E07EB0
2020-12-07T13:35:23.340 TRACE 5848 sf::CurlDescPool::newCurlDesc: Allocate new curl descriptor 00000108510C1990(curl=0000010851E07EB0) from subpool 00000108517A1D90
2020-12-07T13:35:23.340 TRACE 5848 sf::CurDesc::prepare: Setting timeout to 300s
2020-12-07T13:35:23.340 TRACE 5848 sf::CurlDesc::prepare: AcceptEncoding=
2020-12-07T13:35:23.340 TRACE 5848 sf::RestRequest::httpPerform: CA (Certificate Authority) Bundle file=C:\Program Files\Snowflake ODBC Driver\etc\cacert.pem
2020-12-07T13:35:23.340 TRACE 5848 sf::RestRequest::httpPerform: SSL version setting=, SSL version picked=6
2020-12-07T13:35:23.340 TRACE 5848 sf::RestRequest::httpPerform: OCSP: FAIL_OPEN
2020-12-07T13:35:23.340 TRACE 5848 sf::RestRequest::httpPerform: Setting CURLOPT_CAINFO to: C:\Program Files\Snowflake ODBC Driver\etc\cacert.pem
2020-12-07T13:35:24.131 WARN 5848 sf::RestRequest::httpPerform: Got CURL(0000010851E07EB0) error: SSL certificate problem: unable to get local issuer certificate when fetching data from https://foobar.us-east-1.snowflakecomputing.com:443/session/v1/login-request?requestId=d92e143e-fb61-4098-9956-315e5aeb1d61&request_guid=d8012102-dc0f-4bb7-a4b6-07b7d1e9d934&databaseName=DEMO_DB&schemaName=PUBLIC&warehouse=COMPUTE_WH&roleName=EXCELANALYST. Status code: 11, curl error code: 60
2020-12-07T13:35:24.133 DEBUG 5848 sf::TelemetryOOBUtil::NULL::sendOOBeventAndDump: Emitting OOB telemetry. Payload: [{
"Created_On": "2020-12-07 13:35:24",
"Name": "Curl Error",
"SchemaVersion": 1,
"Tags": {
"UUID": "41a58b5f-9f23-4471-9627-6797f159378c",
"connectionString": "https://foobar.us-east-1.snowflakecomputing.com:443",
"ctx_account": "foobar",
"ctx_host": "foobar.us-east-1.snowflakecomputing.com",
"ctx_port": "443",
"ctx_protocol": "https",
"ctx_user": "ADMIN",
"driver": "ODBC",
"version": "2.22.2",
"hostOs": "Win32",
"telemetryServerDeployment": "prod"
},
"Type": "Log",
"UUID": "41a58b5f-9f23-4471-9627-6797f159378c",
"Urgent": false,
"Value": {
"errorCode": 60,
"exceptionMessage": "RestRequest httpPerform error : SSL certificate problem: unable to get local issuer certificatewhen fetching data from https://foobar.us-east-1.snowflakecomputing.com:443/session/v1/login-request?requestId=d92e143e-fb61-4098-9956-315e5aeb1d61&request_guid=d8012102-dc0f-4bb7-a4b6-07b7d1e9d934&databaseName=DEMO_DB&schemaName=PUBLIC&warehouse=COMPUTE_WH&roleName=EXCELANALYST. Status code: 11 and curl errorcode 60",
"request": "https://foobar.us-east-1.snowflakecomputing.com:443/session/v1/login-request?requestId=d92e143e-fb61-4098-9956-315e5aeb1d61&request_guid=d8012102-dc0f-4bb7-a4b6-07b7d1e9d934&databaseName=DEMO_DB&schemaName=PUBLIC&warehouse=COMPUTE_WH&roleName=EXCELANALYST",
"sqlState": "HY000"
}
}]
～(略)～
snowflake_odbc_driver.log
こちらはドライバ自体のログですね。こちらには特に問題がないのでエラーは出ていませんね。
Dec 07 22:35:23 INFO 11252 SharedSingletonManager::LogVersions: SDK Version: 10.01.15.1109 Dec 07 22:35:23 INFO 11252 SharedSingletonManager::LogVersions: DSII Version: 2.22.2 Dec 07 22:35:23 INFO 11252 Driver::Initialize: Database CHAR Encoding: UTF-8 Dec 07 22:35:23 INFO 11252 Driver::Initialize: Database WCHAR Encoding: UTF-16LE Dec 07 22:35:23 INFO 11252 Driver::Initialize: Driver ANSI CHAR Encoding: Windows-31J Dec 07 22:35:23 INFO 11252 Driver::Initialize: Driver Manager WCHAR Encoding: UTF-16LE Dec 07 22:35:23 INFO 11252 Driver::Initialize: Detected Driver Manager: Windows, Unknown Dec 07 22:35:23 INFO 11252 Driver::Initialize: Locale name: ja_JP Dec 07 22:35:23 INFO 11252 Driver::Initialize: Bitness: 64-bit Dec 07 22:35:23 TRACE 11252 CInterface::SQLAllocHandle::<lambda_41941a92ceb35011ccab6162f075d317>::operator (): +++++ enter +++++ Dec 07 22:35:23 INFO 11252 CInterface::SQLAllocHandle: Allocating environment handle. Dec 07 22:35:23 TRACE 11252 Driver::CreateEnvironment: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 SFDriver::CreateEnvironment: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 SFEnvironment::SFEnvironment: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 Driver::RegisterEnvironment: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 CInterface::SQLAllocHandle::<lambda_41941a92ceb35011ccab6162f075d317>::operator (): ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLSetEnvAttr: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 Driver::GetEnvironment: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 Environment::SQLSetEnvAttr: +++++ enter +++++ Dec 07 22:35:23 INFO 11252 Environment::SQLSetEnvAttr: Attribute: SQL_ATTR_ODBC_VERSION (200) Dec 07 22:35:23 TRACE 11252 EnvironmentState1Allocated::SQLSetEnvAttr: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 EnvironmentAttributes::SetAttribute: +++++ enter +++++ Dec 07 22:35:23 INFO 11252 EnvironmentAttributes::SetAttribute: Setting ODBC version to: 2 Dec 07 22:35:23 TRACE 11252 CInterface::SQLSetEnvAttr: ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLAllocHandle::<lambda_41941a92ceb35011ccab6162f075d317>::operator (): +++++ enter +++++ Dec 07 22:35:23 INFO 11252 CInterface::SQLAllocHandle: Allocating connection handle. Dec 07 22:35:23 TRACE 11252 Driver::GetEnvironment: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 Environment::SQLAllocHandle: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 EnvironmentState1Allocated::SQLAllocHandle: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 SFEnvironment::CreateConnection: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 Driver::RegisterConnection: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 CInterface::SQLAllocHandle::<lambda_41941a92ceb35011ccab6162f075d317>::operator (): ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLGetInfoW: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 CInterface::SQLGetInfoW: ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLGetInfoW: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 CInterface::SQLGetInfoW: ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLGetInfoW: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 CInterface::SQLGetInfoW: ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLSetConnectAttr: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 CInterface::SQLSetConnectAttr: ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLSetConnectAttr: +++++ enter +++++ Dec 07 22:35:23 TRACE 11252 CInterface::SQLSetConnectAttr: ----- exit ----- Dec 07 22:35:23 TRACE 11252 CInterface::SQLDriverConnectW: +++++ enter +++++ ～(略)～
snowflake_odbc_connection_0.log
このログには以下のようなコネクションに関するログが出力されます。接続先のアカウントやDB名など、接続設定に関する情報が確認できますね。RESTリクエスト時にエラーが発生しているのが分かります。
Dec 07 22:35:23 TRACE 11252 SFConnection::SFConnection: +++++ enter +++++
Dec 07 22:35:23 INFO 11252 Connection::SQLGetInfoW: InfoType: SQL_DRIVER_ODBC_VER (77)
Dec 07 22:35:23 INFO 11252 Connection::SQLGetInfoW: InfoType: SQL_ASYNC_DBC_FUNCTIONS (10023)
Dec 07 22:35:23 INFO 11252 Connection::SQLGetInfoW: InfoType: SQL_ASYNC_NOTIFICATION (10025)
Dec 07 22:35:23 TRACE 11252 Connection::SQLSetConnectAttr: +++++ enter +++++
Dec 07 22:35:23 INFO 11252 Connection::SQLSetConnectAttr: Attribute: SQL_ATTR_ANSI_APP (115)
Dec 07 22:35:23 TRACE 11252 ConnectionState::SQLSetConnectAttr: +++++ enter +++++
Dec 07 22:35:23 TRACE 11252 ConnectionAttributes::SetAttribute: +++++ enter +++++
Dec 07 22:35:23 TRACE 11252 Connection::SQLSetConnectAttr: +++++ enter +++++
Dec 07 22:35:23 INFO 11252 Connection::SQLSetConnectAttr: Attribute: SQL_ATTR_LOGIN_TIMEOUT (103)
Dec 07 22:35:23 TRACE 11252 ConnectionState::SQLSetConnectAttr: +++++ enter +++++
Dec 07 22:35:23 TRACE 11252 ConnectionAttributes::SetAttribute: +++++ enter +++++
Dec 07 22:35:23 TRACE 11252 Connection::SQLDriverConnectW: +++++ enter +++++
Dec 07 22:35:23 TRACE 11252 ConnectionState2::SQLDriverConnectW: +++++ enter +++++
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "CLIENT_SESSION_KEEP_ALIVE" = "true"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "DATABASE" = "DEMO_DB"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "DRIVER" = "SnowflakeDSIIDriver"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "LOGIN_TIMEOUT" = "10"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "PWD" = "***"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "ROLE" = "EXCELANALYST"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "SCHEMA" = "PUBLIC"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "SERVER" = "foobar.us-east-1.snowflakecomputing.com"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "UID" = "***"
Dec 07 22:35:23 INFO 11252 ConnectionSettings::LoadSettings: ConnString setting: "WAREHOUSE" = "COMPUTE_WH"
～(略)～
Dec 07 22:35:23 TRACE 11252 SFConnection::Connect: +++++ enter +++++
Dec 07 22:35:40 ERROR 11252 Connection::SQLDriverConnectW: [Snowflake][Snowflake] (4)
REST request for URL https://foobar.us-east-1.snowflakecomputing.com:443/session/v1/login-request?requestId=d92e143e-fb61-4098-9956-315e5aeb1d61&request_guid=d8012102-dc0f-4bb7-a4b6-07b7d1e9d934&databaseName=DEMO_DB&schemaName=PUBLIC&warehouse=COMPUTE_WH&roleName=EXCELANALYST failed: CURLerror (curl_easy_perform() failed) - code=60 msg='SSL peer certificate or SSH remote key was not OK' osCode=9 osMsg='Bad file descriptor'.
～(略)～
snowflake_odbc_curl.dmp
最後に本命のcurlのログです。snowflake_odbc_generic0.logにもcurlに関するエラーが出ていたので、これが一番気になるログです。
2020-12-07T13:35:39Z.580 [thread-5848] Info Hostname foobar.us-east-1.snowflakecomputing.com was found in DNS cache. 2020-12-07T13:35:39Z.584 [thread-5848] Info Trying x.xxx.xx.xx:443.... 2020-12-07T13:35:39Z.587 [thread-5848] Info TCP_NODELAY set. 2020-12-07T13:35:39Z.770 [thread-5848] Info Connected to foobar.us-east-1.snowflakecomputing.com (x.xxx.xx.xx) port 443 (#0). 2020-12-07T13:35:39Z.774 [thread-5848] Info ALPN, offering http/1.1. 2020-12-07T13:35:39Z.790 [thread-5848] Info successfully set certificate verify locations:. 2020-12-07T13:35:39Z.792 [thread-5848] Info CAfile: C:\Program Files\Snowflake ODBC Driver\etc\cacert.pem. CApath: none. 2020-12-07T13:35:39Z.793 [thread-5848] Info TLSv1.3 (OUT), TLS handshake, Client hello (1):. 2020-12-07T13:35:40Z.133 [thread-5848] Info TLSv1.3 (IN), TLS handshake, Server hello (2):. 2020-12-07T13:35:40Z.135 [thread-5848] Info TLSv1.2 (IN), TLS handshake, Certificate (11):. 2020-12-07T13:35:40Z.137 [thread-5848] Info TLSv1.2 (OUT), TLS alert, unknown CA (560):. 2020-12-07T13:35:40Z.139 [thread-5848] Info SSL certificate problem: unable to get local issuer certificate. 2020-12-07T13:35:40Z.141 [thread-5848] Info Closing connection 0.
ログを見ると、どうもTLSのハンドシェイクの途中でunknown CAエラーが発生してエラーになっていることが分かりました。これにより、「Snowflakeに接続しに行く際の、証明書周りが怪しそうなエラー」だということまで分かりました。
おまけ
なお、このエラーの原因としては、セキュリティソフトによる「SSL/TLSプロトコルフィルタリング」の機能によって通信がブロックされていることが原因だと分かりました。通信まわりのエラー原因の特定はなかなか難しいですね…。
まとめ
以上、「SnowflakeのODBCドライバのログファイル」についてでした。ODBC接続時に何かエラーが出た際には、こちらのログを参照すると原因の特定に役立ちそうです。
どなたかのお役に立てば幸いです。それでは！
