apache / arrow-flight-sql-postgresql

Apache Arrow Flight SQL adapter for PostgreSQL
https://arrow.apache.org/flight-sql-postgresql/
Apache License 2.0
68 stars 9 forks source link

Querying through Python ADBC hangs forever #178

Closed vogelsgesang closed 11 months ago

vogelsgesang commented 11 months ago

I tried using this extension through ADBC from Python, using the following script

import adbc_driver_flightsql.dbapi as flight_sql

with flight_sql.connect(uri="grpc://localhost:15432",
                        db_kwargs={"username": "avogelsgesang",
                                   "adbc.flight.sql.rpc.call_header.x-flight-sql-database": "avogelsgesang"
                                   }
                        ) as conn:
   with conn.cursor() as cur:
       cur.execute("SELECT 42;")
       x = cur.fetch_arrow_table()
       print(x)

Observed behavior: The script is hanging forever

kou commented 11 months ago

Thanks for trying this project!

Did you try it with 0.1.0? If so, could you try the main branch instead? There are many improvements after 0.1.0. (We should release a new version...)

vogelsgesang commented 11 months ago

I tried version 0.1.0, following the instructions from https://arrow.apache.org/flight-sql-postgresql/0.1.0/install.html

vogelsgesang commented 11 months ago

I built from source code now (based on commit 60c748aa1fbf7aa1bee125849bfa9f7635fca5fc). Unfortunately still no success.

Here is the console output which I get

avogelsgesang@avogelsges-wsl2:~/Documents$ python3 af-query.py
/home/avogelsgesang/.local/lib/python3.10/site-packages/adbc_driver_manager/dbapi.py:298: Warning: Cannot disable autocommit; conn will not be DB-API 2.0 compliant
  warnings.warn(

As soon as I kill Postgres using sudo pkill -9 -u postgres, I get the following stack trace from the client

Traceback (most recent call last):
  File "/home/avogelsgesang/Documents/af-query.py", line 9, in <module>
    cur.execute("SELECT 42;")
  File "/home/avogelsgesang/.local/lib/python3.10/site-packages/adbc_driver_manager/dbapi.py", line 669, in execute
    handle, self._rowcount = self._stmt.execute_query()
  File "adbc_driver_manager/_lib.pyx", line 1106, in adbc_driver_manager._lib.AdbcStatement.execute_query
  File "adbc_driver_manager/_lib.pyx", line 227, in adbc_driver_manager._lib.check_error
adbc_driver_manager.OperationalError: IO: [FlightSQL] error reading from server: EOF (Unavailable; ExecuteQuery)

Are there any debug setting which I could enable so I get additional tracing on the server and/or client?

kou commented 11 months ago

log_min_messages=debug5 PostgreSQL configuration helps us but it generates many outputs...

I'll try this later.

FYI: We have a simple ADBC client written in Ruby https://github.com/apache/arrow-flight-sql-postgresql/blob/main/benchmark/select-adbc-flight-sql.rb and it worked when I used. So ADBC client must work.

vogelsgesang commented 11 months ago

Here is the debug output under log_min_messages=debug5

Log file contents ``` 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: postgres: PostmasterMain: initial environment dump: 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: ----------------------------------------- 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: PG_OOM_ADJUST_FILE=/proc/self/oom_score_adj 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: PG_GRANDPARENT_PID=1126180 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: PGLOCALEDIR=/usr/share/locale 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: PGSYSCONFDIR=/etc/postgresql-common 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: LANG=en_US.UTF-8 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: PWD=/ 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: PGDATA=/var/lib/postgresql/15/main 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: LC_COLLATE=en_US.UTF-8 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: LC_CTYPE=en_US.UTF-8 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: LC_MESSAGES=en_US.UTF-8 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: LC_MONETARY=C 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: LC_NUMERIC=C 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: LC_TIME=C 2023-12-08 23:03:29.668 UTC [1126186] DEBUG: ----------------------------------------- 2023-12-08 23:03:29.679 UTC [1126186] DEBUG: registering background worker "logical replication launcher" 2023-12-08 23:03:29.679 UTC [1126186] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql" 2023-12-08 23:03:29.679 UTC [1126186] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql.so" 2023-12-08 23:03:29.700 UTC [1126186] DEBUG: registering background worker "arrow-flight-sql: main" 2023-12-08 23:03:29.700 UTC [1126186] DEBUG: loaded library "arrow_flight_sql" 2023-12-08 23:03:29.703 UTC [1126186] DEBUG: invoking IpcMemoryCreate(size=149520384) 2023-12-08 23:03:29.704 UTC [1126186] DEBUG: mmap(150994944) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory 2023-12-08 23:03:29.713 UTC [1126186] DEBUG: dynamic shared memory system will support 674 segments 2023-12-08 23:03:29.713 UTC [1126186] DEBUG: created dynamic shared memory control segment 3514440144 (26976 bytes) 2023-12-08 23:03:29.780 UTC [1126186] DEBUG: max_safe_fds = 987, usable_fds = 1000, already_open = 3 2023-12-08 23:03:29.780 UTC [1126186] LOG: starting PostgreSQL 15.5 (Ubuntu 15.5-1.pgdg22.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit 2023-12-08 23:03:29.780 UTC [1126186] LOG: listening on IPv4 address "127.0.0.1", port 5433 2023-12-08 23:03:29.780 UTC [1126186] LOG: could not bind IPv4 address "127.0.0.1": Address already in use 2023-12-08 23:03:29.780 UTC [1126186] HINT: Is another postmaster already running on port 5433? If not, wait a few seconds and retry. 2023-12-08 23:03:29.780 UTC [1126186] LOG: could not bind IPv6 address "::1": Cannot assign requested address 2023-12-08 23:03:29.784 UTC [1126186] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433" 2023-12-08 23:03:29.794 UTC [1126188] DEBUG: checkpointer updated shared memory configuration values 2023-12-08 23:03:29.796 UTC [1126190] LOG: database system was shut down at 2023-12-08 23:03:12 UTC 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: checkpoint record is at 0/1979210 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: redo record is at 0/1979210; shutdown true 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: next transaction ID: 740; next OID: 24587 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: next MultiXactId: 1; next MultiXactOffset: 0 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: oldest unfrozen transaction ID: 716, in database 1 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: oldest MultiXactId: 1, in database 1 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: commit timestamp Xid oldest/newest: 0/0 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: transaction ID wrap limit is 2147484363, limited by database with OID 1 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: starting up replication slots 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: xmin required by slots: data 0, catalog 0 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: starting up replication origin progress state 2023-12-08 23:03:29.796 UTC [1126190] DEBUG: reading stats file "pg_stat/pgstat.stat" 2023-12-08 23:03:29.797 UTC [1126190] DEBUG: removing permanent stats file "pg_stat/pgstat.stat" 2023-12-08 23:03:29.797 UTC [1126190] DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1 2023-12-08 23:03:29.797 UTC [1126190] DEBUG: MultiXact member stop limit is now 4294914944 based on MultiXact 1 2023-12-08 23:03:29.801 UTC [1126190] DEBUG: shmem_exit(0): 4 before_shmem_exit callbacks to make 2023-12-08 23:03:29.801 UTC [1126190] DEBUG: shmem_exit(0): 6 on_shmem_exit callbacks to make 2023-12-08 23:03:29.801 UTC [1126190] DEBUG: proc_exit(0): 1 callbacks to make 2023-12-08 23:03:29.801 UTC [1126190] DEBUG: exit(0) 2023-12-08 23:03:29.802 UTC [1126190] DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2023-12-08 23:03:29.802 UTC [1126190] DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2023-12-08 23:03:29.802 UTC [1126190] DEBUG: proc_exit(-1): 0 callbacks to make 2023-12-08 23:03:29.806 UTC [1126186] DEBUG: reaping dead processes 2023-12-08 23:03:29.808 UTC [1126186] DEBUG: starting background worker process "arrow-flight-sql: main" 2023-12-08 23:03:29.809 UTC [1126192] DEBUG: autovacuum launcher started 2023-12-08 23:03:29.810 UTC [1126186] DEBUG: starting background worker process "logical replication launcher" 2023-12-08 23:03:29.810 UTC [1126192] DEBUG: InitPostgres 2023-12-08 23:03:29.810 UTC [1126192] DEBUG: my backend ID is 1 2023-12-08 23:03:29.810 UTC [1126192] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.810 UTC [1126192] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.811 UTC [1126186] LOG: database system is ready to accept connections 2023-12-08 23:03:29.811 UTC [1126193] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql" 2023-12-08 23:03:29.811 UTC [1126193] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql.so" 2023-12-08 23:03:29.812 UTC [1126194] DEBUG: logical replication launcher started 2023-12-08 23:03:29.812 UTC [1126194] DEBUG: InitPostgres 2023-12-08 23:03:29.812 UTC [1126194] DEBUG: my backend ID is 2 2023-12-08 23:03:29.812 UTC [1126194] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.812 UTC [1126194] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.812 UTC [1126194] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.812 UTC [1126194] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.813 UTC [1126194] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.813 UTC [1126194] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:29.814 UTC [1126186] DEBUG: registering background worker "arrow-flight-sql: server" 2023-12-08 23:03:29.814 UTC [1126186] DEBUG: starting background worker process "arrow-flight-sql: server" 2023-12-08 23:03:29.816 UTC [1126195] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql" 2023-12-08 23:03:29.816 UTC [1126195] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql.so" 2023-12-08 23:03:29.819 UTC [1126195] LOG: listening on grpc://127.0.0.1:15432 for Apache Arrow Flight SQL 2023-12-08 23:03:30.354 UTC [1126186] DEBUG: forked new backend, pid=1126200 socket=7 2023-12-08 23:03:30.355 UTC [1126200] [unknown]@[unknown] DEBUG: shmem_exit(0): 0 before_shmem_exit callbacks to make 2023-12-08 23:03:30.355 UTC [1126200] [unknown]@[unknown] DEBUG: shmem_exit(0): 0 on_shmem_exit callbacks to make 2023-12-08 23:03:30.355 UTC [1126200] [unknown]@[unknown] DEBUG: proc_exit(0): 1 callbacks to make 2023-12-08 23:03:30.355 UTC [1126200] [unknown]@[unknown] DEBUG: exit(0) 2023-12-08 23:03:30.356 UTC [1126200] [unknown]@[unknown] DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2023-12-08 23:03:30.356 UTC [1126200] [unknown]@[unknown] DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2023-12-08 23:03:30.356 UTC [1126200] [unknown]@[unknown] DEBUG: proc_exit(-1): 0 callbacks to make 2023-12-08 23:03:30.360 UTC [1126186] DEBUG: reaping dead processes 2023-12-08 23:03:30.360 UTC [1126186] DEBUG: server process (PID 1126200) exited with exit code 0 2023-12-08 23:03:30.866 UTC [1126186] DEBUG: forked new backend, pid=1126203 socket=7 2023-12-08 23:03:30.867 UTC [1126203] postgres@template1 DEBUG: InitPostgres 2023-12-08 23:03:30.867 UTC [1126203] postgres@template1 DEBUG: my backend ID is 3 2023-12-08 23:03:30.867 UTC [1126203] postgres@template1 DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:30.878 UTC [1126203] postgres@template1 DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:30.878 UTC [1126203] postgres@template1 DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: shmem_exit(0): 4 before_shmem_exit callbacks to make 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: shmem_exit(0): 6 on_shmem_exit callbacks to make 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: proc_exit(0): 2 callbacks to make 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: exit(0) 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2023-12-08 23:03:30.879 UTC [1126203] postgres@template1 DEBUG: proc_exit(-1): 0 callbacks to make 2023-12-08 23:03:30.885 UTC [1126186] DEBUG: reaping dead processes 2023-12-08 23:03:30.885 UTC [1126186] DEBUG: server process (PID 1126203) exited with exit code 0 2023-12-08 23:03:31.394 UTC [1126186] DEBUG: forked new backend, pid=1126231 socket=7 2023-12-08 23:03:31.395 UTC [1126231] postgres@template1 DEBUG: InitPostgres 2023-12-08 23:03:31.395 UTC [1126231] postgres@template1 DEBUG: my backend ID is 3 2023-12-08 23:03:31.396 UTC [1126231] postgres@template1 DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.401 UTC [1126231] postgres@template1 DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.401 UTC [1126231] postgres@template1 DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.401 UTC [1126231] postgres@template1 DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.401 UTC [1126231] postgres@template1 DEBUG: shmem_exit(0): 4 before_shmem_exit callbacks to make 2023-12-08 23:03:31.401 UTC [1126231] postgres@template1 DEBUG: shmem_exit(0): 6 on_shmem_exit callbacks to make 2023-12-08 23:03:31.401 UTC [1126231] postgres@template1 DEBUG: proc_exit(0): 2 callbacks to make 2023-12-08 23:03:31.401 UTC [1126231] postgres@template1 DEBUG: exit(0) 2023-12-08 23:03:31.402 UTC [1126231] postgres@template1 DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2023-12-08 23:03:31.402 UTC [1126231] postgres@template1 DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2023-12-08 23:03:31.402 UTC [1126231] postgres@template1 DEBUG: proc_exit(-1): 0 callbacks to make 2023-12-08 23:03:31.408 UTC [1126186] DEBUG: reaping dead processes 2023-12-08 23:03:31.408 UTC [1126186] DEBUG: server process (PID 1126231) exited with exit code 0 2023-12-08 23:03:31.916 UTC [1126186] DEBUG: forked new backend, pid=1126234 socket=7 2023-12-08 23:03:31.918 UTC [1126234] postgres@template1 DEBUG: InitPostgres 2023-12-08 23:03:31.918 UTC [1126234] postgres@template1 DEBUG: my backend ID is 3 2023-12-08 23:03:31.918 UTC [1126234] postgres@template1 DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.923 UTC [1126234] postgres@template1 DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.923 UTC [1126234] postgres@template1 DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.923 UTC [1126234] postgres@template1 DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:03:31.924 UTC [1126234] postgres@template1 DEBUG: shmem_exit(0): 4 before_shmem_exit callbacks to make 2023-12-08 23:03:31.924 UTC [1126234] postgres@template1 DEBUG: shmem_exit(0): 6 on_shmem_exit callbacks to make 2023-12-08 23:03:31.924 UTC [1126234] postgres@template1 DEBUG: proc_exit(0): 2 callbacks to make 2023-12-08 23:03:31.924 UTC [1126234] postgres@template1 DEBUG: exit(0) 2023-12-08 23:03:31.924 UTC [1126234] postgres@template1 DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2023-12-08 23:03:31.924 UTC [1126234] postgres@template1 DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2023-12-08 23:03:31.924 UTC [1126234] postgres@template1 DEBUG: proc_exit(-1): 0 callbacks to make 2023-12-08 23:03:31.930 UTC [1126186] DEBUG: reaping dead processes 2023-12-08 23:03:31.930 UTC [1126186] DEBUG: server process (PID 1126234) exited with exit code 0 2023-12-08 23:03:44.821 UTC [1126189] DEBUG: snapshot of 0+0 running transaction ids (lsn 0/19792C0 oldest xid 740 latest complete 739 next xid 740) 2023-12-08 23:04:29.858 UTC [1126192] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:29.858 UTC [1126192] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:29.861 UTC [1126462] DEBUG: InitPostgres 2023-12-08 23:04:29.865 UTC [1126462] DEBUG: my backend ID is 3 2023-12-08 23:04:29.865 UTC [1126462] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: autovacuum: processing database "template1" 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_authid: vac: 0 (threshold 53), ins: 0 (threshold 1003), anl: 0 (threshold 51) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_subscription: vac: 0 (threshold 50), ins: 0 (threshold 1000), anl: 0 (threshold 50) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_attribute: vac: 0 (threshold 661), ins: 0 (threshold 1611), anl: 0 (threshold 355) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_class: vac: 0 (threshold 132), ins: 0 (threshold 1082), anl: 0 (threshold 91) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_index: vac: 0 (threshold 82), ins: 0 (threshold 1032), anl: 0 (threshold 66) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_opclass: vac: 0 (threshold 85), ins: 0 (threshold 1035), anl: 0 (threshold 68) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_am: vac: 0 (threshold 51), ins: 0 (threshold 1001), anl: 0 (threshold 51) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_amproc: vac: 0 (threshold 189), ins: 0 (threshold 1139), anl: 0 (threshold 120) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: pg_database: vac: 0 (threshold 50), ins: 0 (threshold 1000), anl: 0 (threshold 50) 2023-12-08 23:04:29.867 UTC [1126462] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:29.868 UTC [1126462] DEBUG: shmem_exit(0): 4 before_shmem_exit callbacks to make 2023-12-08 23:04:29.868 UTC [1126462] DEBUG: shmem_exit(0): 7 on_shmem_exit callbacks to make 2023-12-08 23:04:29.868 UTC [1126462] DEBUG: proc_exit(0): 1 callbacks to make 2023-12-08 23:04:29.868 UTC [1126462] DEBUG: exit(0) 2023-12-08 23:04:29.868 UTC [1126462] DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2023-12-08 23:04:29.868 UTC [1126462] DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2023-12-08 23:04:29.868 UTC [1126462] DEBUG: proc_exit(-1): 0 callbacks to make 2023-12-08 23:04:29.874 UTC [1126186] DEBUG: reaping dead processes 2023-12-08 23:04:29.874 UTC [1126186] DEBUG: server process (PID 1126462) exited with exit code 0 2023-12-08 23:04:35.223 UTC [1126186] DEBUG: registering background worker "arrow-flight-sql: executor: 9383821395685254437" 2023-12-08 23:04:35.223 UTC [1126186] DEBUG: starting background worker process "arrow-flight-sql: executor: 9383821395685254437" 2023-12-08 23:04:35.224 UTC [1126533] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql" 2023-12-08 23:04:35.224 UTC [1126533] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/15/lib/arrow_flight_sql.so" 2023-12-08 23:04:35.224 UTC [1126533] DEBUG: InitPostgres 2023-12-08 23:04:35.224 UTC [1126533] DEBUG: my backend ID is 3 2023-12-08 23:04:35.225 UTC [1126533] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:35.228 UTC [1126533] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:35.232 UTC [1126533] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 2023-12-08 23:04:35.232 UTC [1126533] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 ```

The query from ADBC was sent at 23:04:29 in the log file

vogelsgesang commented 11 months ago

Ok, I think I am getting closer. The problem seems to be that the "parameters" of the prepared query are never set. If I use

       cur.execute("SELECT $1;", parameters=(42,))

instead of

       cur.execute("SELECT 42;")

everything works as expected.

For the original, non-parameterized query, I was able to confirm that parameters_ is empty when reaching PreparedStatement::select

I guess ADBC skips the call to DoPutPreparedStatementQuery in this case. Not sure if this is a client-side bug in ADBC. But even if it is, I guess the server should be robust against this and report an error?

kou commented 11 months ago

Ah, good catch! I didn't care about the case. I've fixed it: GH-179

I've opened #180 for a timeout case.

vogelsgesang commented 11 months ago

Thanks for the patch! With this, the line

       cur.execute("SELECT 42;")

now works as expected.

However, error handling seems to be brittle. The query

       cur.execute("SELECT 1/0;")

first hangs for a couple of minutes before then reporting

Traceback (most recent call last):
  File "/home/avogelsgesang/Documents/af-query.py", line 9, in <module>
    cur.execute("SELECT 1/0;")
  File "/home/avogelsgesang/.local/lib/python3.10/site-packages/adbc_driver_manager/dbapi.py", line 669, in execute
    handle, self._rowcount = self._stmt.execute_query()
  File "adbc_driver_manager/_lib.pyx", line 1106, in adbc_driver_manager._lib.AdbcStatement.execute_query
  File "adbc_driver_manager/_lib.pyx", line 227, in adbc_driver_manager._lib.check_error
adbc_driver_manager.ProgrammingError: INVALID_ARGUMENT: [FlightSQL] failed to run: Action::SelectPreparedStatement: division by zero (InvalidArgument; ExecuteQuery)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/avogelsgesang/Documents/af-query.py", line 8, in <module>
    with conn.cursor() as cur:
  File "/home/avogelsgesang/.local/lib/python3.10/site-packages/adbc_driver_manager/dbapi.py", line 225, in __exit__
    self.close()
  File "/home/avogelsgesang/.local/lib/python3.10/site-packages/adbc_driver_manager/dbapi.py", line 611, in close
    self._stmt.close()
  File "adbc_driver_manager/_lib.pyx", line 1078, in adbc_driver_manager._lib.AdbcStatement.close
  File "adbc_driver_manager/_lib.pyx", line 1084, in adbc_driver_manager._lib.AdbcStatement.close
  File "adbc_driver_manager/_lib.pyx", line 227, in adbc_driver_manager._lib.check_error
adbc_driver_manager.ProgrammingError: INVALID_ARGUMENT: [FlightSQL] stolen session: 1283150246607583965 (InvalidArgument; ClosePreparedStatement)
Exception ignored in: <function Cursor.__del__ at 0x7fa517960280>
Traceback (most recent call last):
  File "/home/avogelsgesang/.local/lib/python3.10/site-packages/adbc_driver_manager/dbapi.py", line 766, in __del__
  File "/home/avogelsgesang/.local/lib/python3.10/site-packages/adbc_driver_manager/dbapi.py", line 611, in close
  File "adbc_driver_manager/_lib.pyx", line 1077, in adbc_driver_manager._lib.AdbcStatement.close
  File "adbc_driver_manager/_lib.pyx", line 293, in adbc_driver_manager._lib._AdbcHandle._close_child
  File "adbc_driver_manager/_lib.pyx", line 295, in adbc_driver_manager._lib._AdbcHandle._close_child
RuntimeError: Underflow in closing this AdbcStatement
kou commented 11 months ago

Thanks for finding one more edge case. Could you open a new issue for it to close this by #179?