Re: [psycopg] Changing set_session implementation - Mailing list psycopg
From | Karsten Hilbert |
---|---|
Subject | Re: [psycopg] Changing set_session implementation |
Date | |
Msg-id | 20170803210818.xyf6ike2uqmckeav@hermes.hilbert.loc Whole thread Raw |
In response to | Re: [psycopg] Changing set_session implementation (Karsten Hilbert <Karsten.Hilbert@gmx.net>) |
Responses |
[psycopg] problem with readonly/autocommit, was: Changing set_sessionimplementation
|
List | psycopg |
Regarding the below problem with readwrite autocommit connections in default-readonly databases I have whittled down a test case to the following (attached): db = u'gnumed_v20' # a database configured "alter database %s set default_transaction_read_only to on" user = 'gm-dbo' # a user with CREATE DATABASE powers cmd_def_tx_ro = "SELECT upper(source), name, upper(setting) FROM pg_settings WHERE name = 'default_transaction_read_only'" cmd_create_db = "create database %s_copy template %s" % (db, db) import sys import psycopg2 conn = psycopg2.connect(dbname = db, user = user) print 'conn:', conn print 'readonly:', conn.readonly print 'autocommit:', conn.autocommit conn.autocommit = False conn.readonly = False # <========== comment out for success conn.autocommit = True print 'autocommit now:', conn.autocommit conn.readonly = False print 'readonly now:', conn.readonly curs = conn.cursor() curs.execute(cmd_def_tx_ro) print 'should show DEFAULT_TRANSACTION_READ_ONLY set to ON' print curs.fetchall() curs.close() conn.commit() print 'the following CREATE DATABASE should fail' curs = conn.cursor() try: curs.execute(cmd_create_db) except psycopg2.InternalError as ex: print 'SQL failed:' print ex print 'shutting down' curs.close() conn.rollback() conn.close() which shows on the console: ncq@hermes:~$ python x-test-default_ro.py conn: <connection object at 0xb674e6bc; dsn: 'dbname=gnumed_v20 user=gm-dbo', closed: 0> readonly: None autocommit: False autocommit now: True readonly now: False should show DEFAULT_TRANSACTION_READ_ONLY set to ON [('DATABASE', 'default_transaction_read_only', 'ON')] the following CREATE DATABASE should fail SQL failed: cannot execute CREATE DATABASE in a read-only transaction shutting down The PostgreSQL log shows: 2017-08-03 21:00:19 GMT LOG: 00000: Verbindung empfangen: Host=[local] 2017-08-03 21:00:19 GMT ORT: BackendInitialize, postmaster.c:4135 2017-08-03 21:00:19 GMT LOG: 00000: Verbindung autorisiert: Benutzer=gm-dbo Datenbank=gnumed_v20 2017-08-03 21:00:19 GMT ORT: PerformAuthentication, postinit.c:272 2017-08-03 21:00:19 GMT LOG: 00000: statement: SELECT upper(source), name, upper(setting) FROM pg_settings WHERE name= 'default_transaction_read_only' 2017-08-03 21:00:19 GMT LOCATION: exec_simple_query, postgres.c:935 2017-08-03 21:00:19 GMT LOG: 00000: statement: create database gnumed_v20_copy template gnumed_v20 2017-08-03 21:00:19 GMT LOCATION: exec_simple_query, postgres.c:935 2017-08-03 21:00:19 GMT ERROR: 25006: cannot execute CREATE DATABASE in a read-only transaction 2017-08-03 21:00:19 GMT LOCATION: PreventCommandIfReadOnly, utility.c:236 2017-08-03 21:00:19 GMT STATEMENT: create database gnumed_v20_copy template gnumed_v20 2017-08-03 21:00:19 GMT LOG: 00000: disconnection: session time: 0:00:00.007 user=gm-dbo database=gnumed_v20 host=[local] 2017-08-03 21:00:19 GMT LOCATION: log_disconnections, postgres.c:4501 Commenting out the marked line makes it work and the log shows: 2017-08-03 21:01:24 GMT LOG: 00000: Verbindung empfangen: Host=[local] 2017-08-03 21:01:24 GMT ORT: BackendInitialize, postmaster.c:4135 2017-08-03 21:01:24 GMT LOG: 00000: Verbindung autorisiert: Benutzer=postgres Datenbank=postgres 2017-08-03 21:01:24 GMT ORT: PerformAuthentication, postinit.c:272 2017-08-03 21:01:25 GMT LOG: 00000: Anweisung: drop database gnumed_v20_copy ; 2017-08-03 21:01:25 GMT ORT: exec_simple_query, postgres.c:935 2017-08-03 21:01:26 GMT LOG: 00000: Verbindungsende: Sitzungszeit: 0:00:02.324 Benutzer=postgres Datenbank=postgresHost=[local] 2017-08-03 21:01:26 GMT ORT: log_disconnections, postgres.c:4501 2017-08-03 21:01:33 GMT LOG: 00000: Verbindung empfangen: Host=[local] 2017-08-03 21:01:33 GMT ORT: BackendInitialize, postmaster.c:4135 2017-08-03 21:01:33 GMT LOG: 00000: Verbindung autorisiert: Benutzer=gm-dbo Datenbank=gnumed_v20 2017-08-03 21:01:33 GMT ORT: PerformAuthentication, postinit.c:272 2017-08-03 21:01:33 GMT LOG: 00000: statement: SET default_transaction_read_only TO 'off' 2017-08-03 21:01:33 GMT LOCATION: exec_simple_query, postgres.c:935 2017-08-03 21:01:33 GMT LOG: 00000: statement: SELECT upper(source), name, upper(setting) FROM pg_settings WHERE name= 'default_transaction_read_only' 2017-08-03 21:01:33 GMT LOCATION: exec_simple_query, postgres.c:935 2017-08-03 21:01:33 GMT LOG: 00000: statement: create database gnumed_v20_copy template gnumed_v20 2017-08-03 21:01:33 GMT LOCATION: exec_simple_query, postgres.c:935 2017-08-03 21:01:37 GMT LOG: 00000: duration: 3447.360 ms 2017-08-03 21:01:37 GMT LOCATION: exec_simple_query, postgres.c:1164 2017-08-03 21:01:37 GMT LOG: 00000: disconnection: session time: 0:00:03.454 user=gm-dbo database=gnumed_v20 host=[local] 2017-08-03 21:01:37 GMT LOCATION: log_disconnections, postgres.c:4501 So, under some circumstances psycopg2 does send the 2017-08-03 21:01:33 GMT LOG: 00000: statement: SET default_transaction_read_only TO 'off' while sometimes it does not, despite both times being in autocommit=True and readonly=False when the "create database" is sent. Of course, the conn.autocommit = False conn.readonly = False # <========== comment out for success conn.autocommit = True conn.readonly = False seems redundant but that is the relevant sequence of events condensed from a larger body of code. Redundant as it may seem it should still work, no ? I am not sure I fully grok what is happening... Thanks for insights, Karsten On Wed, Aug 02, 2017 at 09:38:21PM +0200, Karsten Hilbert wrote: > On Wed, Aug 02, 2017 at 03:10:15PM +0100, Daniele Varrazzo wrote: > > > If you want to be absolutely sure about what the adapter does I > > suggest you to enable statements log on the server and check what > > statements are produced by psycopg. If you find any behaviour > > inconsistent with what documented please let us know. > > One thing I noticed is that it seems pycopg2 does not send a > "set default_transaction_read_only to off" when > > - a database had been created and ALTERed to permanently > be "default_transaction_read_only to ON" > > - a transaction had been opened on a connection with > > BEGIN ISOLATION LEVEL SERIALIZABLE READ WRITE > > in order to run various comments (such as setting > default client timezone) > > - that transaction had been committed > > - the connection is switched to autocommit=true > (for running DROP DATABASE et al) > > 2017-08-02 19:18:13 GMT LOG: 00000: Verbindung empfangen: Host=[local] > 2017-08-02 19:18:13 GMT ORT: BackendInitialize, postmaster.c:4135 > 2017-08-02 19:18:13 GMT LOG: 00000: Verbindung autorisiert: Benutzer=postgres Datenbank=gnumed_v20 > 2017-08-02 19:18:13 GMT ORT: PerformAuthentication, postinit.c:272 > 2017-08-02 19:18:13 GMT LOG: 00000: statement: BEGIN ISOLATION LEVEL SERIALIZABLE READ WRITE > 2017-08-02 19:18:13 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:13 GMT LOG: 00000: statement: set timezone to 'Europe/Madrid' > 2017-08-02 19:18:13 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:13 GMT LOG: 00000: statement: COMMIT > 2017-08-02 19:18:13 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:13 GMT LOG: 00000: statement: BEGIN ISOLATION LEVEL SERIALIZABLE READ WRITE > 2017-08-02 19:18:13 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:13 GMT LOG: 00000: statement: set lc_messages to 'C' > 2017-08-02 19:18:13 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:13 GMT LOG: 00000: statement: select md5(gm.concat_table_structure(20::integer)) as md5 > 2017-08-02 19:18:13 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:14 GMT LOG: 00000: duration: 1156.407 ms > 2017-08-02 19:18:14 GMT LOCATION: exec_simple_query, postgres.c:1164 > 2017-08-02 19:18:14 GMT LOG: 00000: statement: SELECT datname FROM pg_database WHERE datname='gnumed_v21' > 2017-08-02 19:18:14 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:14 GMT LOG: 00000: statement: COMMIT > 2017-08-02 19:18:14 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:14 GMT LOG: 00000: statement: DROP DATABASE "gnumed_v21" > 2017-08-02 19:18:14 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:14 GMT ERROR: 25006: cannot execute DROP DATABASE in a read-only transaction > 2017-08-02 19:18:14 GMT LOCATION: PreventCommandIfReadOnly, utility.c:236 > 2017-08-02 19:18:14 GMT STATEMENT: DROP DATABASE "gnumed_v21" > 2017-08-02 19:18:14 GMT LOG: 00000: statement: SET default_transaction_isolation TO DEFAULT > 2017-08-02 19:18:14 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:14 GMT LOG: 00000: statement: SET default_transaction_read_only TO DEFAULT > 2017-08-02 19:18:14 GMT LOCATION: exec_simple_query, postgres.c:935 > 2017-08-02 19:18:14 GMT LOG: 00000: disconnection: session time: 0:00:01.183 user=postgres database=gnumed_v20host=[local] > 2017-08-02 19:18:14 GMT LOCATION: log_disconnections, postgres.c:4501 > > The only other indirect proof I have for this is: if I insert > a manual "set default_transaction_read_only to off" right > before the "drop database ..." (but after having been > switched to autocommit) it works as expected. > > If the connection has NOT been used for any other > transactions (that is, if it is switched to autocommit=true > and then to readonly=off) it also works as expected - > psycopg2 sends a "set default_transaction_read_only to off". > > Karsten > -- > GPG key ID E4071346 @ eu.pool.sks-keyservers.net > E167 67FD A291 2BEA 73BD 4537 78B9 A9F9 E407 1346 > > > -- > Sent via psycopg mailing list (psycopg@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/psycopg -- GPG key ID E4071346 @ eu.pool.sks-keyservers.net E167 67FD A291 2BEA 73BD 4537 78B9 A9F9 E407 1346