-
Notifications
You must be signed in to change notification settings - Fork 0
Expand file tree
/
Copy pathserver_log.txt
More file actions
84 lines (84 loc) · 16.9 KB
/
Copy pathserver_log.txt
File metadata and controls
84 lines (84 loc) · 16.9 KB
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
[2m2026-01-22T15:00:39.493158Z[0m [[32m[1minfo [0m] [1mSchema mapper initialized [0m [36miris_schema[0m=[35mSQLUser[0m [36msource[0m=[35mdefault[0m
DEBUG: iris module NOT in sys.modules at start of main
🔌 IRIS Python driver available, using external connection
[2m2026-01-22T15:00:39.571553Z[0m [[32m[1minfo [0m] [1mIRIS Python driver available, using external connection[0m
[2m2026-01-22T15:00:39.571586Z[0m [[32m[1minfo [0m] [1mIRIS executor initialized [0m [36membedded_mode[0m=[35mFalse[0m [36mhost[0m=[35mlocalhost[0m [36mnamespace[0m=[35mUSER[0m [36mport[0m=[35m1972[0m
[2m2026-01-22T15:00:39.571614Z[0m [[32m[1minfo [0m] [1mPGWire server initialized [0m [36mhost[0m=[35m0.0.0.0[0m [36miris_host[0m=[35mlocalhost[0m [36miris_namespace[0m=[35mUSER[0m [36miris_port[0m=[35m1972[0m [36mport[0m=[35m5436[0m
[2m2026-01-22T15:00:39.589697Z[0m [[32m[1minfo [0m] [1mIRIS connection test successful[0m [36mhost[0m=[35mlocalhost[0m [36mnamespace[0m=[35mUSER[0m [36mport[0m=[35m1972[0m
[2m2026-01-22T15:00:39.600003Z[0m [[32m[1minfo [0m] [1mIRIS vector support detected (external)[0m
[2m2026-01-22T15:00:39.600066Z[0m [[32m[1minfo [0m] [1mIRIS connection test successful[0m [36membedded_mode[0m=[35mFalse[0m [36mvector_support[0m=[35mTrue[0m
[2m2026-01-22T15:00:39.600276Z[0m [[32m[1minfo [0m] [1mPGWire server started [0m [36mactive_connections[0m=[35m0[0m [36maddress[0m=[35m0.0.0.0:5436[0m [36mssl_enabled[0m=[35mFalse[0m
[2m2026-01-22T15:00:45.463939Z[0m [[32m[1minfo [0m] [1mClient connection established [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.464509Z[0m [[33m[1mwarning [0m] [1mpython-gssapi not installed - Kerberos authentication disabled[0m
[2m2026-01-22T15:00:45.469055Z[0m [[32m[1minfo [0m] [1mauthentication_selector_initialized[0m [36mkerberos_enabled[0m=[35mFalse[0m [36moauth_enabled[0m=[35mTrue[0m [36mwallet_enabled[0m=[35mTrue[0m
[2m2026-01-22T15:00:45.469106Z[0m [[32m[1minfo [0m] [1moauth_bridge_initialized [0m [36mclient_id[0m=[35mpgwire-server[0m [36muse_wallet[0m=[35mTrue[0m
[2m2026-01-22T15:00:45.469129Z[0m [[32m[1minfo [0m] [1mwallet_credentials_initialized[0m [36maudit_enabled[0m=[35mTrue[0m [36mwallet_mode[0m=[35mboth[0m
[2m2026-01-22T15:00:45.469151Z[0m [[32m[1minfo [0m] [1mProtocol handler initialized [0m [36mbackend_pid[0m=[35m18725[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mtranslation_enabled[0m=[35mTrue[0m
[2m2026-01-22T15:00:45.469566Z[0m [[32m[1minfo [0m] [1m🔍 HANDSHAKE STEP 1: About to parse StartupMessage[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469585Z[0m [[32m[1minfo [0m] [1m🔍 parse_startup_message: Starting to parse StartupMessage[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mhas_buffered_data[0m=[35mTrue[0m
[2m2026-01-22T15:00:45.469598Z[0m [[32m[1minfo [0m] [1m📦 Using buffered data from SSL probe[0m [36mbuffered_size[0m=[35m8[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469611Z[0m [[32m[1minfo [0m] [1m📦 Buffered data correctly parsed[0m [36malready_read_bytes[0m=[35m4[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mmessage_length[0m=[35m62[0m
[2m2026-01-22T15:00:45.469624Z[0m [[32m[1minfo [0m] [1m🔍 About to read remaining message data[0m [36malready_have_bytes[0m=[35m4[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mremaining_bytes[0m=[35m58[0m
[2m2026-01-22T15:00:45.469635Z[0m [[32m[1minfo [0m] [1m📦 Reading additional bytes [0m [36mbytes_needed[0m=[35m54[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469647Z[0m [[32m[1minfo [0m] [1m📦 Message data assembled from buffered + new reads[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mtotal_bytes[0m=[35m58[0m
[2m2026-01-22T15:00:45.469670Z[0m [[32m[1minfo [0m] [1m🔍 Protocol version parsed [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mexpected[0m=[35m00030000[0m [36mprotocol_version[0m=[35m00030000[0m
[2m2026-01-22T15:00:45.469681Z[0m [[32m[1minfo [0m] [1m🔍 About to parse parameters [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mparam_data_size[0m=[35m54[0m
[2m2026-01-22T15:00:45.469696Z[0m [[32m[1minfo [0m] [1m✅ All parameters parsed successfully[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mparams[0m=[35m{'client_encoding': "'utf-8'", 'user': 'test_user', 'database': 'USER'}[0m
[2m2026-01-22T15:00:45.469708Z[0m [[32m[1minfo [0m] [1m✅ HANDSHAKE STEP 1: StartupMessage parsed successfully[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mparams[0m=[35m{'client_encoding': "'utf-8'", 'user': 'test_user', 'database': 'USER'}[0m
[2m2026-01-22T15:00:45.469720Z[0m [[32m[1minfo [0m] [1m🔍 HANDSHAKE STEP 2: About to send authentication[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mscram_enabled[0m=[35mFalse[0m
[2m2026-01-22T15:00:45.469745Z[0m [[32m[1minfo [0m] [1m✅ HANDSHAKE STEP 2: Authentication sent[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469755Z[0m [[32m[1minfo [0m] [1m🔍 HANDSHAKE STEP 3: About to send ParameterStatus[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469818Z[0m [[32m[1minfo [0m] [1m✅ HANDSHAKE STEP 3: ParameterStatus sent[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469829Z[0m [[32m[1minfo [0m] [1m🔍 HANDSHAKE STEP 4: About to send BackendKeyData[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469929Z[0m [[32m[1minfo [0m] [1m✅ HANDSHAKE STEP 4: BackendKeyData sent[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.469978Z[0m [[32m[1minfo [0m] [1m🔍 HANDSHAKE STEP 5: About to send ReadyForQuery[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.470022Z[0m [[32m[1minfo [0m] [1m✅ HANDSHAKE STEP 5: ReadyForQuery sent[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.470039Z[0m [[32m[1minfo [0m] [1m🎉 Startup sequence completed successfully[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mdatabase[0m=[35mUSER[0m [36muser[0m=[35mtest_user[0m
[2m2026-01-22T15:00:45.470067Z[0m [[32m[1minfo [0m] [1mEntering message loop [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.471350Z[0m [[32m[1minfo [0m] [1mParsed statement with translation[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mconstructs_translated[0m=[35m0[0m [36mnum_params[0m=[35m0[0m [36moriginal_query[0m=[35m'SELECT 1'[0m [36mstatement_name[0m=[35m__asyncpg_stmt_1__[0m [36mtranslated_query[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.471435Z[0m [[32m[1minfo [0m] [1m🔍 DEBUG: Sending ParameterDescription[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mparam_count[0m=[35m0[0m [36mparam_oids[0m=[35m[][0m [36mparam_types[0m=[35m[][0m
[2m2026-01-22T15:00:45.471466Z[0m [[32m[1minfo [0m] [1m🔍 Describe Statement: Checking query type[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mis_select[0m=[35mTrue[0m [36mis_show[0m=[35mFalse[0m [36mquery_preview[0m=[35m'SELECT 1'[0m [36mstatement_name[0m=[35m__asyncpg_stmt_1__[0m
[2m2026-01-22T15:00:45.471509Z[0m [[32m[1minfo [0m] [1m🔍 Describe Statement: Executing metadata discovery[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mquery[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.471527Z[0m [[32m[1minfo [0m] [1m🔍 Describe Statement: Using dummy parameters for metadata[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mparam_count[0m=[35m0[0m
[2m2026-01-22T15:00:45.471555Z[0m [[33m[1mwarning [0m] [1m🔍 DEBUG: execute_query() branching - embedded_mode = False[0m
[2m2026-01-22T15:00:45.471575Z[0m [[33m[1mwarning [0m] [1m🔍 DEBUG: Taking EXTERNAL path → _execute_external_async()[0m
[2m2026-01-22T15:00:45.474953Z[0m [[32m[1minfo [0m] [1m🔍 _normalize_iris_column_name CALLED[0m [36miris_name[0m=[35mHostVar_1[0m [36miris_type[0m=[35m4[0m [36mnormalized[0m=[35mhostvar_1[0m [36msql_preview[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.474991Z[0m [[32m[1minfo [0m] [1m🔍 IRIS metadata type discovery (EXTERNAL MODE)[0m [36mdesc[0m=[35mColumn(name='HostVar_1', type_code=4, display_size=None, internal_size=None, precision=10, scale=0, null_ok=2)[0m [36miris_type[0m=[35m4[0m [36mnormalized_column_name[0m=[35m?column?[0m [36moriginal_column_name[0m=[35mHostVar_1[0m [36msql_preview[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.475060Z[0m [[32m[1minfo [0m] [1m⏱️ EXTERNAL EXECUTION TIMING [0m [36mconnection_ms[0m=[35m0.11[0m [36mfetch_ms[0m=[35m0.21[0m [36miris_exec_ms[0m=[35m2.71[0m [36moptimization_ms[0m=[35m0.11[0m [36moverhead_ms[0m=[35m0.54[0m [36msession_id[0m=[35m127.0.0.1:58240[0m [36mtotal_ms[0m=[35m3.25[0m
[2m2026-01-22T15:00:45.475148Z[0m [[32m[1minfo [0m] [1m🔴 SEND_ROW_DESCRIPTION CALLED [0m [36mcolumns[0m=[35m[{'name': '?column?', 'type_oid': 23, 'type_size': None, 'type_modifier': -1, 'format_code': 0}][0m [36mfield_count[0m=[35m1[0m [36mresult_formats[0m=[35mNone[0m
[2m2026-01-22T15:00:45.475190Z[0m [[32m[1minfo [0m] [1m🟢 Using pre-computed type info from executor[0m [36mname[0m=[35m?column?[0m [36mtype_oid[0m=[35m23[0m [36mtype_size[0m=[35m-1[0m
[2m2026-01-22T15:00:45.475211Z[0m [[32m[1minfo [0m] [1m🔵 Format code determined [0m [36mcolumn_index[0m=[35m0[0m [36mcolumn_name[0m=[35m?column?[0m [36mformat_code[0m=[35m0[0m [36mformat_type[0m=[35mtext[0m
[2m2026-01-22T15:00:45.475231Z[0m [[32m[1minfo [0m] [1m🔵 Field info packed [0m [36mfield_info_hex[0m=[35m00000000000000000017ffffffffffff0000[0m [36mfield_info_length[0m=[35m18[0m [36mfield_name_length[0m=[35m9[0m [36mname[0m=[35m?column?[0m
[2m2026-01-22T15:00:45.475248Z[0m [[32m[1minfo [0m] [1m📤 Sending RowDescription message[0m [36mfield_count[0m=[35m1[0m [36mmessage_hex_preview[0m=[35m540000002100013f636f6c756d6e3f0000000000000000000017ffffffff[0m [36mtotal_message_length[0m=[35m34[0m
[2m2026-01-22T15:00:45.475262Z[0m [[32m[1minfo [0m] [1m📤 STEP A: Writing RowDescription to stream[0m [36mbytes_to_write[0m=[35m34[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.475295Z[0m [[32m[1minfo [0m] [1m📤 STEP B: RowDescription written, about to drain[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.475308Z[0m [[32m[1minfo [0m] [1m📤 STEP C: RowDescription drained - message sent to client[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.475321Z[0m [[32m[1minfo [0m] [1m✅ Sent RowDescription for statement Describe[0m [36mcolumn_count[0m=[35m1[0m [36mcolumns[0m=[35m['?column?'][0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mstatement_name[0m=[35m__asyncpg_stmt_1__[0m
[2m2026-01-22T15:00:45.475337Z[0m [[32m[1minfo [0m] [1mDescribed object [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mname[0m=[35m__asyncpg_stmt_1__[0m [36mtype[0m=[35mS[0m
[2m2026-01-22T15:00:45.475560Z[0m [[32m[1minfo [0m] [1mParsed result format codes [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mformats[0m=[35m[1][0m [36mnum_formats[0m=[35m1[0m [36mportal_name[0m=[35m[0m
[2m2026-01-22T15:00:45.475597Z[0m [[32m[1minfo [0m] [1mExecute: Using result formats from portal[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mportal_name[0m=[35m[0m [36mresult_formats[0m=[35m[1][0m
[2m2026-01-22T15:00:45.475613Z[0m [[32m[1minfo [0m] [1mExecuting prepared statement [0m [36mcache_hit[0m=[35mFalse[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mconstructs_translated[0m=[35m0[0m [36mportal_name[0m=[35m[0m [36mstatement_name[0m=[35m__asyncpg_stmt_1__[0m
[2m2026-01-22T15:00:45.475648Z[0m [[33m[1mwarning [0m] [1m🔍 DEBUG: execute_query() branching - embedded_mode = False[0m
[2m2026-01-22T15:00:45.475660Z[0m [[33m[1mwarning [0m] [1m🔍 DEBUG: Taking EXTERNAL path → _execute_external_async()[0m
[2m2026-01-22T15:00:45.477078Z[0m [[32m[1minfo [0m] [1m🔍 _normalize_iris_column_name CALLED[0m [36miris_name[0m=[35mHostVar_1[0m [36miris_type[0m=[35m4[0m [36mnormalized[0m=[35mhostvar_1[0m [36msql_preview[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.477102Z[0m [[32m[1minfo [0m] [1m🔍 IRIS metadata type discovery (EXTERNAL MODE)[0m [36mdesc[0m=[35mColumn(name='HostVar_1', type_code=4, display_size=None, internal_size=None, precision=10, scale=0, null_ok=2)[0m [36miris_type[0m=[35m4[0m [36mnormalized_column_name[0m=[35m?column?[0m [36moriginal_column_name[0m=[35mHostVar_1[0m [36msql_preview[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.477166Z[0m [[32m[1minfo [0m] [1m⏱️ EXTERNAL EXECUTION TIMING [0m [36mconnection_ms[0m=[35m0.0[0m [36mfetch_ms[0m=[35m0.19[0m [36miris_exec_ms[0m=[35m1.25[0m [36moptimization_ms[0m=[35m0.01[0m [36moverhead_ms[0m=[35m0.21[0m [36msession_id[0m=[35m127.0.0.1:58240[0m [36mtotal_ms[0m=[35m1.47[0m
[2m2026-01-22T15:00:45.477247Z[0m [[32m[1minfo [0m] [1mSending query result - DETAILED DEBUG[0m [36mcolumn_count[0m=[35m1[0m [36mcolumns_is_truthy[0m=[35mTrue[0m [36mcolumns_sample[0m=[35m[{'name': '?column?', 'type_oid': 23, 'type_size': None, 'type_modifier': -1, 'format_code': 0}][0m [36mcommand[0m=[35mSELECT[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mhas_rows[0m=[35mTrue[0m [36mrow_count[0m=[35m1[0m [36mrows_is_truthy[0m=[35mTrue[0m [36mrows_sample[0m=[35m[[1]][0m [36msend_ready[0m=[35mFalse[0m
[2m2026-01-22T15:00:45.477274Z[0m [[32m[1minfo [0m] [1m🔵 STEP 1 (SKIPPED): RowDescription already sent by Describe[0m [36mcolumn_count[0m=[35m1[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.477291Z[0m [[32m[1minfo [0m] [1m🔵 STEP 2: About to send DataRows[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mrow_count[0m=[35m1[0m
[2m2026-01-22T15:00:45.477305Z[0m [[32m[1minfo [0m] [1mSending large result set [0m [36mbatch_size[0m=[35m1000[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mtotal_rows[0m=[35m1[0m
[2m2026-01-22T15:00:45.477319Z[0m [[32m[1minfo [0m] [1m📦 DataRow column 0: name='?column?' value='1' type=int[0m
[2m2026-01-22T15:00:45.477332Z[0m [[32m[1minfo [0m] [1m🔍 DataRow hex dump (first 200 bytes): 440000000e00010000000400000001[0m
[2m2026-01-22T15:00:45.477341Z[0m [[32m[1minfo [0m] [1m🔍 DataRow message structure: [0m
[2m2026-01-22T15:00:45.477349Z[0m [[32m[1minfo [0m] [1m - Message type: 44 ('D') [0m
[2m2026-01-22T15:00:45.477356Z[0m [[32m[1minfo [0m] [1m - Total length: 14 bytes [0m
[2m2026-01-22T15:00:45.477364Z[0m [[32m[1minfo [0m] [1m - Field count: 1 [0m
[2m2026-01-22T15:00:45.477385Z[0m [[32m[1minfo [0m] [1mLarge result set transmission completed[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mtotal_rows[0m=[35m1[0m
[2m2026-01-22T15:00:45.477395Z[0m [[32m[1minfo [0m] [1m🔵 STEP 3: DataRows sent [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.477406Z[0m [[32m[1minfo [0m] [1m🔵 STEP 4: About to send CommandComplete[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mtag[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.477452Z[0m [[32m[1minfo [0m] [1m🔵 STEP 5: CommandComplete sent and drained[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.478797Z[0m [[32m[1minfo [0m] [1mQuery result sent [0m [36mcolumn_count[0m=[35m1[0m [36mcommand[0m=[35mSELECT[0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mrow_count[0m=[35m1[0m
[2m2026-01-22T15:00:45.478824Z[0m [[32m[1minfo [0m] [1mExecuted portal [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m [36mportal_name[0m=[35m[0m [36mquery[0m=[35m'SELECT 1'[0m
[2m2026-01-22T15:00:45.479250Z[0m [[32m[1minfo [0m] [1mClient terminated connection [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.479268Z[0m [[32m[1minfo [0m] [1mClosing session and returning connection to pool[0m [36msession_id[0m=[35m127.0.0.1:58240[0m
[2m2026-01-22T15:00:45.479374Z[0m [[32m[1minfo [0m] [1mClient connection closed [0m [36mconnection_id[0m=[35m127.0.0.1:58240[0m