c/driver/postgresql Writing timezone-aware types causes connection leave a transaction

[avm19]

What happened?

Writing timezone-aware types causes connection leave a transaction
Related: PR #868
Workaround: Do not use timezone-aware types.

I discovered this by seeing unexpected warnings in my Postgres logs:

WARNING: there is no transaction in progress

Note that the warning is in the database logs, not in any output of the client.

It took me a while to reproduce, because I was looking in all the wrong places, but eventually I realised that a timezone is to blame (I did not expect that adbc_driver_postgresql treats tz-aware and tz-naive types so differently).

How can we reproduce the bug?

Python code to reproduce

import datetime
import adbc_driver_postgresql.dbapi

dt_naive = datetime.datetime.now()  # TZ-naive works OK
dt_aware = datetime.datetime.now(tz=datetime.UTC)  # TZ-aware causes trouble

q = "INSERT INTO test123 VALUES ($1, $2);"
with adbc_driver_postgresql.dbapi.connect(uri) as conn:
    with conn.cursor() as cursor:
        cursor.execute('DROP TABLE IF EXISTS test123;')
        cursor.execute('CREATE TABLE test123 AS (SELECT 123 AS id, NOW() AS ts);')
    conn.commit()  # OK
    with conn.cursor() as cursor:
        cursor.executemany(q, [(111, dt_naive)])
    conn.commit()  # OK
    with conn.cursor() as cursor:
        cursor.executemany(q, [(111, dt_aware)])
    conn.commit()  # WARNING: there is no transaction in progress

Here is the relevant part of the database log with my comments:

Postgres Log

2025-01-05 21:36:54 UTC:172.12.123.123(40398):[unknown]@[unknown]:[5990]:LOG: connection received: host=172.12.123.123 port=40398
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: connection authenticated: identity="postgres" method=md5 (/rdsdbdata/config/pg_hba.conf:13)
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: connection authorized: user=postgres database=postgres SSL enabled (protocol=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384, bits=256)
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: BEGIN TRANSACTION
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.117 ms
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.032 ms parse <unnamed>: DROP TABLE IF EXISTS test123
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.008 ms bind <unnamed>: DROP TABLE IF EXISTS test123
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: execute <unnamed>: DROP TABLE IF EXISTS test123
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 1.855 ms
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.119 ms parse <unnamed>: CREATE TABLE test123 AS (SELECT 123 AS id, NOW() AS ts)
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.009 ms bind <unnamed>: CREATE TABLE test123 AS (SELECT 123 AS id, NOW() AS ts)
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: execute <unnamed>: CREATE TABLE test123 AS (SELECT 123 AS id, NOW() AS ts)
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 2.439 ms


######    conn.commit()  starts here:

2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: COMMIT; BEGIN TRANSACTION
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 1.288 ms


######         cursor.executemany(q, [(111, dt_naive)]) starts here:

2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.113 ms parse <unnamed>: INSERT INTO test123 VALUES ($1, $2);
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.046 ms bind <unnamed>: INSERT INTO test123 VALUES ($1, $2);
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:DETAIL: parameters: $1 = '111', $2 = '2025-01-05 21:36:53.957838'
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: execute <unnamed>: INSERT INTO test123 VALUES ($1, $2);
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:DETAIL: parameters: $1 = '111', $2 = '2025-01-05 21:36:53.957838'
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.076 ms


######    conn.commit()  starts here:

2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: COMMIT; BEGIN TRANSACTION
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 5.405 ms

######         cursor.executemany(q, [(111, dt_aware)]) starts here:

2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: SELECT current_setting('TIMEZONE')
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.181 ms
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: SET TIME ZONE 'UTC'
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.059 ms
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.040 ms parse <unnamed>: INSERT INTO test123 VALUES ($1, $2);
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.033 ms bind <unnamed>: INSERT INTO test123 VALUES ($1, $2);
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:DETAIL: parameters: $1 = '111', $2 = '2025-01-05 21:36:53.957806'
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: execute <unnamed>: INSERT INTO test123 VALUES ($1, $2);
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:DETAIL: parameters: $1 = '111', $2 = '2025-01-05 21:36:53.957806'
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.041 ms
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: SET TIME ZONE 'UTC'
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.036 ms
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: COMMIT
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.480 ms

######    conn.commit()  starts here:

2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: statement: COMMIT; BEGIN TRANSACTION
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:WARNING: there is no transaction in progress
2025-01-05 21:36:54 UTC:172.12.123.123(40398):postgres@postgres:[5990]:LOG: duration: 0.052 ms

Discussion

From the log, and also from the C code (below), we see that tz-aware timestamps are dealt with by SET TIME ZONE queries under the hood. After the prepared statement is run, the timezone setting is restored:

arrow-adbc/c/driver/postgresql/bind_stream.h

Lines 252 to 262 in 76a4d78

	Status Cleanup(PGconn* pg_conn) {
	if (has_tz_field) {
	PqResultHelper reset(pg_conn, "SET TIME ZONE '" + tz_setting + "'");
	UNWRAP_STATUS(reset.Execute());
	PqResultHelper commit(pg_conn, "COMMIT");
	UNWRAP_STATUS(reset.Execute());
	}
	return Status::Ok();
	}

I don't write in C and I am not familiar with this code base, so forgive me, but I do see some issues with this code:

1. Is it a typo in the second repetition UNWRAP_STATUS(reset.Execute()); on line 258? Shouldn't it be UNWRAP_STATUS(commit.Execute()); instead? It may seem confusing that the typo should prevent COMMIT from execution, while the logs show that it was executed. This is because I am using an older version, before this refactor in PR refactor(c/driver/postgresql): Use Status for error handling in BindStream #2187 , which introduced the typo. The typo should be corrected anyway.

2. Why commit? My connection has autocommit=False (default), and I would prefer to stay in control of my commits and have them only when I call conn.commit(). Even if there are good reasons for a forced commit, the next problem remains.

3. Most importantly, conn.commit() does COMMIT; BEGIN TRANSACTION, so that any following statement is a part of transaction (source). This is deliberate and fine. What is not fine, is the bare COMMIT that breaks this convention, whenever input contains a tz-aware value. As a consequence, rollbacks become impossible, unknowingly to the user.

I think database transactions should be taken very seriously, and I wonder if when fixing this bug, one could also audit the code to ensure that there no lonely COMMITs elsewhere? An extra BEGIN TRANSACTION might be not as dangerous, but it still generates a warning in the logs.

Environment/Setup

Python 3.11.5
adbc-driver-manager       1.1.0
adbc-driver-postgresql    1.1.0
adbc-driver-sqlite        1.1.0

[lidavidm]

Thanks for reporting this. I plan to fix this before the next release.

[lidavidm]

FWIW, you seem to have an older version of the driver explaining the code discrepancy

[lidavidm]

Should be fixed. I plan to begin the release process this week (hopefully finishing next week)