Re: [I] adbc_ingest is working better, but still has some COPY INTO issues after adbc 1.2 release [arrow-adbc]

via GitHub Mon, 09 Sep 2024 17:38:36 -0700


davlee1972 commented on issue #2128:
URL: https://github.com/apache/arrow-adbc/issues/2128#issuecomment-2339389901


   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
   
   
![image](https://github.com/user-attachments/assets/ef5511c5-3969-4aac-af02-0b69c1ba4415)
   
   
   ```
   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: [email protected]

For queries about this service, please contact Infrastructure at:
[email protected]

Re: [I] adbc_ingest is working better, but still has some COPY INTO issues after adbc 1.2 release [arrow-adbc]

Reply via email to