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.
Naturally same goes for the SQLAlchemy developers with their cleanup procedure.