You are viewing a plain text version of this content. The canonical link for it is here.
Posted to github@arrow.apache.org by "davlee1972 (via GitHub)" <gi...@apache.org> on 2024/09/10 00:30:26 UTC
Re: [I] snowflake: `adbc_ingest` will fail with "double free" segmentation fault if record batch schema is incorrect [arrow-adbc]
davlee1972 commented on issue #2108:
URL: https://github.com/apache/arrow-adbc/issues/2108#issuecomment-2339383531
I reinstalled adbc 1.2.0 drivers and ran them in debug mode..
Here's a successful COPY INTO which looks like some internal connection using the same session id for all PUTs and COPY INTO(S):
```
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: TIMESTAMP_OUTPUT_FORMAT, value: YYYY-MM-DD HH24:MI:SS.FF3 TZHTZM LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_PREFETCH_THREADS, value: 4 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: TIME_OUTPUT_FORMAT, value: HH24:MI:SS LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_RESULT_CHUNK_SIZE, value: 160 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: TIMESTAMP_TZ_OUTPUT_FORMAT, value: LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_SESSION_KEEP_ALIVE, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_OUT_OF_BAND_TELEMETRY_ENABLED, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: QUERY_CONTEXT_CACHE_SIZE, value: 5 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_METADATA_USE_SESSION_DATABASE, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: ENABLE_STAGE_S3_PRIVATELINK_FOR_US_EAST_1, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_RESULT_PREFETCH_THREADS, value: 1 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: TIMESTAMP_NTZ_OUTPUT_FORMAT, value: YYYY-MM-DD HH24:MI:SS.FF3 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_METADATA_REQUEST_USE_CONNECTION_CTX, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_HONOR_CLIENT_TZ_FOR_TIMESTAMP_NTZ, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_MEMORY_LIMIT, value: 1536 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_TIMESTAMP_TYPE_MAPPING, value: TIMESTAMP_LTZ LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: TIMEZONE, value: America/New_York LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_RESULT_PREFETCH_SLOTS, value: 2 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_TELEMETRY_ENABLED, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_DISABLE_INCIDENTS, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_USE_V1_QUERY_API, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_RESULT_COLUMN_CASE_INSENSITIVE, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: BINARY_OUTPUT_FORMAT, value: HEX LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CSV_TIMESTAMP_FORMAT, value: LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_ENABLE_LOG_INFO_STATEMENT_PARAMETERS, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_TELEMETRY_SESSIONLESS_ENABLED, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: DATE_OUTPUT_FORMAT, value: YYYY-MM-DD LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_FORCE_PROTECT_ID_TOKEN, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_CONSENT_CACHE_ID_TOKEN, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_STAGE_ARRAY_BINDING_THRESHOLD, value: 65280 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_SESSION_KEEP_ALIVE_HEARTBEAT_FREQUENCY, value: 3600 LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: AUTOCOMMIT, value: true LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_SESSION_CLONE, value: false LOG_SESSION_ID=341236648727106
DEBU[0698]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: TIMESTAMP_LTZ_OUTPUT_FORMAT, value: LOG_SESSION_ID=341236648727106
DEBU[0698]rows.go:140 gosnowflake.(*snowflakeRows).Columns Rows.Columns
DEBU[0698]rows.go:80 gosnowflake.(*snowflakeRows).Close Rows.Close LOG_SESSION_ID=341236648727106
INFO[0699]connection.go:399 gosnowflake.(*snowflakeConn).queryContextInternal Query: "COPY INTO IDENTIFIER(?) FROM @ADBC$BIND MATCH_BY_COLUMN_NAME = CASE_INSENSITIVE", [{ 0 "RISK_CURVE_HIST"}]
INFO[0699]connection.go:117 gosnowflake.(*snowflakeConn).exec parameters: map[]
DEBU[0699]log.go:176 gosnowflake.(*defaultLogger).Debugf TYPE: string, "RISK_CURVE_HIST"
INFO[0699]connection.go:126 gosnowflake.(*snowflakeConn).exec bindings: map[1:{TEXT 0xc022594600 <nil>}]
INFO[0699]restful.go:236 gosnowflake.postRestfulQueryHelper params: &map[]
INFO[0699]retry.go:299 gosnowflake.(*retryHTTP).execute retryHTTP.totalTimeout: 0s
DEBU[0699]retry.go:309 gosnowflake.(*retryHTTP).execute retry count: 0
INFO[0700]restful.go:253 gosnowflake.postRestfulQueryHelper postQuery: resp: &{200 OK 200 HTTP/1.1 1 1 map[Cache-Control:[no-cache, no-store] Connection:[keep-alive] Content-Type:[application/json] Date:[Mon, 09 Sep 2024 23:25:40 GMT] Expect-Ct:[enforce, max-age=3600] Keep-Alive:[timeout=175] Vary:[Accept-Encoding, User-Agent] X-Content-Type-Options:[nosniff] X-Frame-Options:[deny] X-Xss-Protection:[1; mode=block]] 0xc028ca4fc0 -1 [chunked] false true map[] 0xc02262f300 0xc0226b64d0}
INFO[0700]connection.go:156 gosnowflake.(*snowflakeConn).exec Success: true, Code: -1
DEBU[0700]log.go:176 gosnowflake.(*defaultLogger).Debugf adding query context: {0 1725924340335596 0 }
INFO[0700]connection.go:190 gosnowflake.(*snowflakeConn).exec Exec/Query SUCCESS
```
Then stuff starts getting weird.. A internal connection is made to run what I'm assuming is the last "select count(*)", but:
A. This select count(*) SQL statement tries to open a new connection with a different session id and closes the old one??
DEBU[0700]rows.go:140 gosnowflake.(*snowflakeRows).Columns Rows.Columns
DEBU[0700]rows.go:80 gosnowflake.(*snowflakeRows).Close Rows.Close LOG_SESSION_ID=341236648727106
B. But it looks like COPY INTO(s) are still running.
C. It looks like the COPY INTO connections die with WARNings which orphans the COPY INTO(s).
D. Then we start getting context cancelled ERRORs
```
DEBU[0700]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_STAGE_ARRAY_BINDING_THRESHOLD, value: 65280 LOG_SESSION_ID=341236648727106
DEBU[0700]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_SESSION_KEEP_ALIVE_HEARTBEAT_FREQUENCY, value: 3600 LOG_SESSION_ID=341236648727106
DEBU[0700]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: AUTOCOMMIT, value: true LOG_SESSION_ID=341236648727106
DEBU[0700]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: CLIENT_SESSION_CLONE, value: false LOG_SESSION_ID=341236648727106
DEBU[0700]connection_util.go:185 gosnowflake.(*snowflakeConn).populateSessionParameters parameter. name: TIMESTAMP_LTZ_OUTPUT_FORMAT, value: LOG_SESSION_ID=341236648727106
DEBU[0700]rows.go:140 gosnowflake.(*snowflakeRows).Columns Rows.Columns
DEBU[0700]rows.go:80 gosnowflake.(*snowflakeRows).Close Rows.Close LOG_SESSION_ID=341236648727106
INFO[0700]connection.go:399 gosnowflake.(*snowflakeConn).queryContextInternal Query: "SELECT COUNT(*) FROM IDENTIFIER(?)", [{ 1 "RISK_CURVE_HIST"}]
INFO[0700]connection.go:117 gosnowflake.(*snowflakeConn).exec parameters: map[]
DEBU[0700]log.go:176 gosnowflake.(*defaultLogger).Debugf TYPE: string, "RISK_CURVE_HIST"
INFO[0700]connection.go:126 gosnowflake.(*snowflakeConn).exec bindings: map[1:{TEXT 0xc077c3f910 <nil>}]
WARN[0700]retry.go:332 gosnowflake.(*retryHTTP).execute failed http connection. err: Get "https://?????.privatelink.snowflakecomputing.com:443/queries/01b6ecdd-0b07-38b5-0001-365ae554753a/result": context canceled . retrying...
WARN[0700]retry.go:332 gosnowflake.(*retryHTTP).execute failed http connection. err: Get "https://?????.privatelink.snowflakecomputing.com:443/queries/01b6ecdd-0b07-38b3-0001-365ae5546612/result": context canceled . retrying...
INFO[0700]retry.go:378 gosnowflake.(*retryHTTP).execute sleeping 2.022s. to timeout: 0s. retrying
INFO[0700]retry.go:378 gosnowflake.(*retryHTTP).execute sleeping 1.385s. to timeout: 0s. retrying
WARN[0700]retry.go:332 gosnowflake.(*retryHTTP).execute failed http connection. err: Get "https://?????.privatelink.snowflakecomputing.com:443/queries/01b6ecdd-0b07-38b3-0001-365ae554656e/result": context canceled . retrying...
INFO[0700]retry.go:378 gosnowflake.(*retryHTTP).execute sleeping 2.645s. to timeout: 0s. retrying
INFO[0700]retry.go:379 gosnowflake.(*retryHTTP).execute retry count: 1, retry reason: 0
INFO[0700]retry.go:379 gosnowflake.(*retryHTTP).execute retry count: 1, retry reason: 0
ERRO[0700]connection.go:410 gosnowflake.(*snowflakeConn).queryContextInternal error: context canceled
INFO[0700]connection.go:399 gosnowflake.(*snowflakeConn).queryContextInternal Query: "COPY INTO IDENTIFIER(?) FROM @ADBC$BIND MATCH_BY_COLUMN_NAME = CASE_INSENSITIVE", [{ 0 "RISK_CURVE_HIST"}]
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@arrow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org