PostgreSQL and "there is no transaction in progress" warning


#1

TLDR;
When you use Zato service for storing data into a PostgreSQL database, rollback is always called after a session is closed. This causes transaction warning if the commit was made before the rollback statement.
Temporally “fix” for the issue can be made by modifying PostgreSQL configuration by setting log_min_messages setting to ignore warnings.

Greetings for everyone,

We are using PostgreSQL 9.5 as our database solution on our server (Ubuntu 16.04 LTS / Zato 2.0.8). Yesterday we noticed that the database’s log file (postgresql-9.5-main.log), was full of warnings and log files were over 100 MB by size (Rotation is indeed a good thing).

Example of the log file’s contents:

xxxxusr@yyyydb WARNING:  there is no transaction in progress
xxxxusr@yyyydb WARNING:  there is no transaction in progress
xxxxusr@yyyydb WARNING:  there is no transaction in progress

This warning was written into the log file multiple times/second, as the data was being written on to the database. We started investigating the issue by checking out the stat_activity with psql client.
From there we found out that there were multiple sessions that had the last query as rollback.

select * from pg_stat_activity;
       | state  | backend_xid | backend_xmin | query              
...    | idle   |    ...       |    ...      | rollback                                                                              
...    | idle   |    ...       |    ...      | rollback  

This made me worry that our data has not been properly stored. However after checking, everything seemed to be working normally. After this I extended amount of logged information from the PostgreSQL configuration and wrote some Zato services for testing, which can be found below with the PostgreSQL log files. (Notice: The code and logs have been heavily modified)

class SelectTest(Service)
       """ No commits, just select queries
       """
	def handle(self):
		 with closing(self.outgoing.sql.get(XXXX.YYYY) as session:
			 print("Session:"+str(session))
			 result = session.execute("SELECT 1")
			 result = session.execute("SELECT 2")

class WithTest(Service)
	""" Closes the session after block ends
	"""
	def handle(self):
		with closing(self.outgoing.sql.get(XXXX.YYYY) as session:
			mypackage.store_data_example({"text":"hello"}, auto_commit=False) # (Removed real code)
			session.commit() 
						 
class WithoutTest(Service):
	""" Closes the session manually
	"""
	def handle(self):
		session = self.outgoing.sql.get(XXXX.YYYY).session()
		mypackage.store_data_example({"text":"hello"}, auto_commit=True) # (Removed real code)
		session.close()

Snippet #1: PSQL log of the SelectTest Service:

LOG:  execute pg8000_statement_0/pg8000_portal_84: begin transaction
LOG:  execute pg8000_statement_9/pg8000_portal_85: SELECT 1
LOG:  execute pg8000_statement_10/pg8000_portal_86: SELECT 2
LOG:  execute pg8000_statement_8/pg8000_portal_87: rollback

Snippet 2#: PSQL log for WithTest and WithoutTest services:

LOG:  execute pg8000_statement_0/pg8000_portal_17: begin transaction
LOG:  execute pg8000_statement_5/pg8000_portal_24: UPDATE hidden_values SET text=$1 where hidden_value.id = $2
LOG:  execute pg8000_statement_6/pg8000_portal_25: commit
LOG:  execute pg8000_statement_7/pg8000_portal_26: rollback
WARNING:  there is no transaction in progress

From these results, it seems to me that when the session is closed, rollback statement is automatically called, which causes the transaction warning when a commit was made before rollback.

I’m not issuing this as a bug, because It might be wanted behaviour and because we did not have this issue with our previous setup (zato 2.0.7 / PostgreSQL 9.3 on ubuntu 14.04 LTS).

At our end, we “fixed” this issue by adding following line into the postgresql.conf, which removes all warnings.

log_min_messages = error

While our “fix” works in this case, I would be interested to hear if there are any other ways for avoiding the warning to be spammed into our log files. I tried to find a way to suppress this exact warning from the PostgreSQL logging, but without any luck. My only worry is missing something important when the warnings are suppressed completely.


How to handle timeouts
#2

Hi @liuz,

I just want to double-check it - you probably did it so, but let me confirm anyway.

You did make sure that the rollback pertains to your service, is that correct? This is not another concurrent transaction’s rollback?

Also, did you check it with regular SQL queries or SQLAlchemy models? I’m just not sure what mypackage.store_data_example is and where auto_commit comes from?

Thanks.


#3

I checked PostgreSQL’s source code and I’m not sure how to link to git tags using git’s default web interface but in a git checkout on disk I could spot that tag REL9_3_20 (latest in 9.3.x series) did not issue a warning in case of a ROLLBACK in an implicit transaction.

Then, this commit added “there is no transaction in progress” for such situations (called TBLOCK_IMPLICIT_INPROGRESS in xact.c).

What precisely is your PostgreSQL version as returned by apt-cache show postgresql and what PostgreSQL’s git commit was it built from, can you check it?

Consider that there is also a note in xact.c saying “(It’s debatable whether we should issue a WARNING in this case, but we have done so historically.)” - I’m not 100% sure how to interpret it because in 9.3 there was no such warning but maybe there used to be one much earlier (8.x, 7.x etc.), then was removed for 9.x and now is brought back for 9.5+.

I can also confirm that none of our PostgreSQL dependencies changed between 2.0.7 and 2.0.8 - the dependencies are sqlalchemy and pg8000:

And the last thing - can you set echo=True in extra options of your outgoing SQL connection? This will log all SQL statements to server.log. Thanks.


#4

Hi @dsuch

Also, did you check it with regular SQL queries or SQLAlchemy models? I’m just not sure what mypackage.store_data_example is and where auto_commit comes from?

The mypackage.store_data_example (faked name), refers to a Python package which is handling the writes and reads for our system and it uses SQLAlchemy. The auto_commit part is just a way of passing boolean value, which determinates if the session.commit will be called within the function or not.

PostgreSQL version

developer@xxxx:~$ dpkg -l|grep postgresql
ii  postgresql                         9.5+173                                    all          object-relational SQL database (supported version)
ii  postgresql-9.5                     9.5.9-0ubuntu0.16.04                       amd64        object-relational SQL database, version 9.5 server
ii  postgresql-client-9.5              9.5.9-0ubuntu0.16.04                       amd64        front-end programs for PostgreSQL 9.5
ii  postgresql-client-common           173                                        all          manager for multiple PostgreSQL client versions
ii  postgresql-common                  173                                        all          PostgreSQL database-cluster manager
ii  postgresql-contrib                 9.5+173                                    all          additional facilities for PostgreSQL (supported version)
ii  postgresql-contrib-9.5             9.5.9-0ubuntu0.16.04                       amd64        additional facilities for PostgreSQL


developer@xxxx:~$ pg_config --version
PostgreSQL 9.5.9

About server output
I copy & pasted following text directly from the stdout (I’m currently running the server foreground for our development environment) and also from the postgreSQL log for comparison. Sadly I had to remove some parts from the output, however I believe that they should not be relevant to this matter.

SelectTest

Server STDOUT:
Session:<sqlalchemy.orm.session.Session object at 0x7f6df1060c10>
2017-12-01 12:55:33,017 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
2017-12-01 12:55:33,017 - INFO - 28111:Dummy-170 - sqlalchemy.engine.base.Engine:109 - BEGIN (implicit)
2017-12-01 12:55:33,019 INFO sqlalchemy.engine.base.Engine SELECT 1
2017-12-01 12:55:33,019 - INFO - 28111:Dummy-170 - sqlalchemy.engine.base.Engine:109 - SELECT 1
2017-12-01 12:55:33,020 INFO sqlalchemy.engine.base.Engine ()
2017-12-01 12:55:33,020 - INFO - 28111:Dummy-170 - sqlalchemy.engine.base.Engine:109 - ()
2017-12-01 12:55:33,023 INFO sqlalchemy.engine.base.Engine SELECT 2
2017-12-01 12:55:33,023 - INFO - 28111:Dummy-170 - sqlalchemy.engine.base.Engine:109 - SELECT 2
2017-12-01 12:55:33,024 INFO sqlalchemy.engine.base.Engine ()
2017-12-01 12:55:33,024 - INFO - 28111:Dummy-170 - sqlalchemy.engine.base.Engine:109 - ()
Finished
2017-12-01 12:55:33,026 INFO sqlalchemy.engine.base.Engine ROLLBACK
2017-12-01 12:55:33,026 - INFO - 28111:Dummy-170 - sqlalchemy.engine.base.Engine:109 - ROLLBACK
Closing down


PostgreSQL Log
2017-12-01 10:55:33 UTC [state:00000, session:5a2131c6.6e1f, procid:28191, session-ln:134] foamdbadmin@foamdb LOG:  execute pg8000_statement_0/pg8000_portal_92: begin transaction
2017-12-01 10:55:33 UTC [state:00000, session:5a2131c6.6e1f, procid:28191, session-ln:135] foamdbadmin@foamdb LOG:  execute pg8000_statement_9/pg8000_portal_93: SELECT 1
2017-12-01 10:55:33 UTC [state:00000, session:5a2131c6.6e1f, procid:28191, session-ln:136] foamdbadmin@foamdb LOG:  execute pg8000_statement_11/pg8000_portal_94: SELECT 2
2017-12-01 10:55:33 UTC [state:00000, session:5a2131c6.6e1f, procid:28191, session-ln:137] foamdbadmin@foamdb LOG:  execute pg8000_statement_7/pg8000_portal_95: rollback

WithoutTest

Server STDOUT:

Session:<sqlalchemy.orm.session.Session object at 0x7f6df0ffc650>
2017-12-01 12:58:34,239 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
2017-12-01 12:58:34,239 - INFO - 28111:Dummy-184 - sqlalchemy.engine.base.Engine:109 - BEGIN (implicit)
   .....
2017-12-01 12:58:34,262 - INFO - 28111:Dummy-184 - sqlalchemy.engine.base.Engine:109 - UPDATE hidden_data SET timestamp=%s WHERE hidden_data.id = %s
2017-12-01 12:58:34,263 INFO sqlalchemy.engine.base.Engine (datetime.datetime(2017, 12, 1, 10, 58, 34, 238711, tzinfo=tzutc()), 296)
2017-12-01 12:58:34,263 - INFO - 28111:Dummy-184 - sqlalchemy.engine.base.Engine:109 - (datetime.datetime(2017, 12, 1, 10, 58, 34, 238711, tzinfo=tzutc()), 296)
2017-12-01 12:58:34,264 INFO sqlalchemy.engine.base.Engine COMMIT
2017-12-01 12:58:34,264 - INFO - 28111:Dummy-184 - sqlalchemy.engine.base.Engine:109 - COMMIT
Finished
Closing down

PostgreSQL log:	
2017-12-01 10:58:34 UTC [session:5a2131c6.6e1f]xxxx@yyyydb LOG:  execute pg8000_statement_0/pg8000_portal_119: begin transaction
     .....
2017-12-01 10:58:34 UTC [session:5a2131c6.6e1f]xxxx@yyyydb LOG:  execute pg8000_statement_16/pg8000_portal_126: UPDATE hidden_data SET timestamp=$1 WHERE hidden_data.id = $2
2017-12-01 10:58:34 UTC [session:5a2131c6.6e1f]xxxx@yyyydb DETAIL:  parameters: $1 = '2017-12-01 10:58:34.238711+00', $2 = '296'
2017-12-01 10:58:34 UTC [session:5a2131c6.6e1f]xxxx@yyyydb LOG:  execute pg8000_statement_17/pg8000_portal_127: commit
2017-12-01 10:58:34 UTC [session:5a2131c6.6e1f]xxxx@yyyydb LOG:  execute pg8000_statement_7/pg8000_portal_128: rollback
2017-12-01 10:58:34 UTC [session:5a2131c6.6e1f]xxxx@yyyydb WARNING:  there is no transaction in progress

It seems that server output does not have the same rollback messages that are visible from the postgresql log.


#5

This topic on StackOverlow explains why the implicit ROLLBACK is not logged with echo=True, it looks that echo_pool=‘debug’ is additionally needed.

On the whole, this is a change in PostgreSQL 9.5 according to the commit I linked to above but I can see how this can be construed as caused by Zato even if it must have been going on all the time - I will check what in SQLAlchemy insists on these ROLLBACK calls. Perhaps in a newer version of SQLAlchemy it can be disabled.

In the meantime, if you log through syslog, can you filter out this particular log message instead of reconfiguring the whole of the database to log on error instead of warn?


#6

In the meantime, if you log through syslog, can you filter out this particular log message instead of reconfiguring the whole of the database to log on error instead of warn?

I think it might be possible to do so, as PostgreSQL seems to allow using syslog for logging.
https://www.postgresql.org/docs/9.5/static/runtime-config-logging.html


#7

Having closely read this chapter, my understanding is that the implicit ROLLBACK is kind of a cleanup procedure on SQLAlchemy’s part and it’s explicitly documented as a feature, which I understand and can agree with.

On the other hand, from an end user’s perspective, with PostgreSQL 9.5 this leads to accumulation of messages that are confusing.

I opened a ticket in SQLAlchemy’s tracker for this - https://bitbucket.org/zzzeek/sqlalchemy/issues/4139/implicit-rollback-and-postgresql-95 - let’s wait for response and then I can follow up in PostgreSQL’s mailing lists if needed.

Thanks.


#8

Thanks for your help.

It’s debatable whether we should issue a WARNING in this case, but we have done so historically.

I kinda can understand the PostgreSQL developer who made this change, after all the question can be seen as debatable.

On one hand it is technically wrong to make statements that do nothing useful and if the client is broken, it could be revealed earlier with a warning. On the other hand, the change can cause issues just like we are having right now. :stuck_out_tongue: Naturally same goes for the SQLAlchemy developers with their cleanup procedure.


#9

Just FYI - I reproduced this situation in isolation, without Zato, feel free to join the discussion in BitBucket if you’d like to: