[psycopg] problem with readonly/autocommit, was: Changing set_sessionimplementation

Hi,

has anyone been able to reproduce the problem described
below?  I'd be glad to provide more information if needed.

Thanks !

Karsten


On Thu, Aug 03, 2017 at 11:08:18PM +0200, Karsten Hilbert wrote:

> 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

>
> 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()

>
> --
> 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