[IGN-3829] Error executing system.db.commitTransaction

Jonathan · August 5, 2021, 1:47pm

When I use a named query transaction, but do not actually run any queries against it I receive an error.

If I do the same thing using system.db.beginTransaction I do not get an error.

Any ideas on how to get around this?

txId = system.db.beginNamedQueryTransaction("myDatabaseConnection")

system.db.commitTransaction(txId)
system.db.closeTransaction(txId)

Java Traceback:
Traceback (most recent call last):
  File "<input>", line 28, in <module>
	at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.error(AbstractDBUtilities.java:362)

	at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.commitTransaction(AbstractDBUtilities.java:438)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

	at java.base/java.lang.reflect.Method.invoke(Unknown Source)

java.lang.Exception: java.lang.Exception: Error executing system.db.commitTransaction(142fa9d6-379f-43f9-b76a-e83f332779ee)


	at org.python.core.Py.JavaError(Py.java:552)

	at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.error(AbstractDBUtilities.java:362)

	at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.commitTransaction(AbstractDBUtilities.java:438)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

	at java.base/java.lang.reflect.Method.invoke(Unknown Source)

	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:188)

	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:539)

	at org.python.core.PyObject.__call__(PyObject.java:480)

	at org.python.core.PyObject.__call__(PyObject.java:484)

	at org.python.pycode._pyx671.f$0(<input>:29)

	at org.python.pycode._pyx671.call_function(<input>)

	at org.python.core.PyTableCode.call(PyTableCode.java:171)

	at org.python.core.PyCode.call(PyCode.java:18)

	at org.python.core.Py.runCode(Py.java:1614)

	at org.python.core.Py.exec(Py.java:1658)

	at org.python.util.PythonInterpreter.exec(PythonInterpreter.java:276)

	at org.python.util.InteractiveInterpreter.runcode(InteractiveInterpreter.java:131)

	at com.inductiveautomation.ignition.designer.gui.tools.jythonconsole.JythonConsole$ConsoleWorker.doInBackground(JythonConsole.java:605)

	at com.inductiveautomation.ignition.designer.gui.tools.jythonconsole.JythonConsole$ConsoleWorker.doInBackground(JythonConsole.java:593)

	at java.desktop/javax.swing.SwingWorker$1.call(Unknown Source)

	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)

	at java.desktop/javax.swing.SwingWorker.run(Unknown Source)

	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

	at java.base/java.lang.Thread.run(Unknown Source)

Caused by: java.lang.Exception: Error executing system.db.commitTransaction(142fa9d6-379f-43f9-b76a-e83f332779ee)

	... 26 more

Caused by: com.inductiveautomation.ignition.client.gateway_interface.GatewayException: Transaction "142fa9d6-379f-43f9-b76a-e83f332779ee" is closed.

	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.newGatewayException(GatewayInterface.java:351)

	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:325)

	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.sendMessage(GatewayInterface.java:278)

	at com.inductiveautomation.ignition.client.gateway_interface.GatewayInterface.invoke(GatewayInterface.java:945)

	at com.inductiveautomation.ignition.client.script.ClientDBUtilities._commitTransaction(ClientDBUtilities.java:231)

	at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.commitTransaction(AbstractDBUtilities.java:436)

	... 24 more

Caused by: java.sql.SQLException: Transaction "142fa9d6-379f-43f9-b76a-e83f332779ee" is closed.

	at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.getTx(DatasourceManagerImpl.java:284)

	at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.commitTransaction(DatasourceManagerImpl.java:297)

	at com.inductiveautomation.ignition.gateway.servlets.gateway.functions.TxControl.commitTransaction(TxControl.java:28)

	at jdk.internal.reflect.GeneratedMethodAccessor266.invoke(null)

	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(null)

	at java.lang.reflect.Method.invoke(null)

	at com.inductiveautomation.ignition.gateway.servlets.gateway.AbstractGatewayFunction.invoke(AbstractGatewayFunction.java:225)

	at com.inductiveautomation.ignition.gateway.servlets.Gateway.doPost(Gateway.java:405)

	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)

	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

	at com.inductiveautomation.ignition.gateway.bootstrap.MapServlet.service(MapServlet.java:86)

	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)

	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)

	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)

	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)

	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)

	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)

	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1607)

	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)

	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1297)

	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)

	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)

	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577)

	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)

	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)

	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)

	at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322)

	at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)

	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)

	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)

	at org.eclipse.jetty.server.Server.handle(Server.java:500)

	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)

	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)

	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)

	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)

	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)

	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)

	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)

	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)

	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)

	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)

	at java.lang.Thread.run(null)

Traceback (most recent call last):
  File "<input>", line 28, in <module>
	at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.error(AbstractDBUtilities.java:362)

	at com.inductiveautomation.ignition.common.script.builtin.AbstractDBUtilities.commitTransaction(AbstractDBUtilities.java:438)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

	at java.base/java.lang.reflect.Method.invoke(Unknown Source)

java.lang.Exception: java.lang.Exception: Error executing system.db.commitTransaction(142fa9d6-379f-43f9-b76a-e83f332779ee)

kcollins1 · August 5, 2021, 2:07pm

What is the underlying database behind the JDBC driver? It might help to know that while taking a look at this.

Jonathan · August 5, 2021, 2:09pm

the JDBC driver is com.microsoft.sqlserver.jdbc.SQLServerDriver

kcollins1 · August 5, 2021, 3:10pm

@Jonathan , I looked into this and it looks like the transaction handling with Named Queries is slightly different than the standard method with beginTransaction. We essentially “queue” the transaction with beginNamedQueryTransaction() and then only put it into effect when a statement is run; this helps prevent a connection from getting tied up prematurely in some situations. In essence, it is an optimization.

That said, there is a bug here, as these queued transactions do stack up in the named query executor (though they’re not real at this point) in your example above. We should be more graceful about detecting the queued transaction and cleaning things up.

Jonathan · August 5, 2021, 3:18pm

Thanks for looking into it. For now I have placed a simple select query so that I do not receive an error in my testing. It would be great to get this on the bug list to be fixed in a future release. I am currently running 8.1.7.

kcollins1 · August 5, 2021, 3:25pm

You’re welcome. We’ll definitely get it in the backlog, it isn’t a difficult fix. For now you could also do something like this to catch that error:

import java.lang.Exception
logger = system.util.getLogger("named-query-test")
# Begin named query transaction
txId = system.db.beginNamedQueryTransaction("db")
attemptedQuery = False

# Optionally run statements and raise flag
# attemptedQuery = True

try:
	system.db.commitTransaction(txId)
	system.db.closeTransaction(txId)
except java.lang.Exception as e:
	if attemptedQuery:
		raise e  # if we get an exception at this point, something might have actually gone wrong so re-raise exception
	else:
		logger.warnf("Attempt to close tx %s failed, presumably due to queued but not active txId", txId) # optional log

… that said, SELECT 1 isn’t exactly an expensive query to just run either.

pturmel · February 17, 2022, 7:23pm

Was this ever fixed?

PGriffith · February 17, 2022, 8:09pm

No, hasn’t yet been picked up.

bkarabinchak.psi · February 18, 2022, 1:43pm

Is there a different workaround for this? The one above does not seem to work for me.

The summary of my named queries is

self.tx = system.db.beginNamedQueryTransaction(self.isolationLevel, self.timeout)
...
self.idx = system.db.runNamedQuery(createNamedQuery, self.newData, tx=self.tx, getKey=1)
...
deleteAliasesQuery = self.namedQueryFolder + '/deleteAliases'
system.db.runNamedQuery(deleteAliasesQuery,{'idx':self.idx}, tx=self.tx)
createAliasesQuery = self.namedQueryFolder + '/createAliases'
for (i, alias) in system.dataset.toPyDataSet(self.aliases):
		system.db.runNamedQuery(createAliasesQuery, {"customerId":self.idx, "alias":alias}, tx=self.tx)
...
system.db.commitTransaction(self.tx)
system.db.closeTransaction(self.tx)

This way always throws me caused by GatewayException: java.sql.SQLException: Datasource "4" does not exist in this Gateway. caused by Exception: java.sql.SQLException: Datasource "4" does not exist in this Gateway.
where the Datasource always correseponds to my isolation level - in this case my self.isolationLevel = system.db.REPEATABLE_READ. Setting self.isolationLevel = system.db.SERIALIZABLE then tells me Datasource “8” does not exist in my gateway.

The above work around does not work for me. Putting my namedQueries inside a try/except silences their error but I can’t imagine they are still running since they don’t have the right datasource and I do not see them come through.

Trying:

try:
    self.tx = system.db.beginNamedQueryTransaction(self.isolationLevel, self.timeout)
except java.lang.Exception, e:
    pass
...
try:
    self.idx = system.db.runNamedQuery(createNamedQuery, self.newData, tx=self.tx, getKey=1)
except java.lang.Exception, e:
    pass
...
deleteAliasesQuery = self.namedQueryFolder + '/deleteAliases'
try:
    system.db.runNamedQuery(deleteAliasesQuery,{'idx':self.idx}, tx=self.tx)
except java.lang.Exception, e:
    pass
createAliasesQuery = self.namedQueryFolder + '/createAliases'
for (i, alias) in system.dataset.toPyDataSet(self.aliases):
try:
		system.db.runNamedQuery(createAliasesQuery, {"customerId":self.idx, "alias":alias}, tx=self.tx)
except java.lang.Exception, e:
    pass
...
system.db.commitTransaction(self.tx)
system.db.closeTransaction(self.tx)

Then throws me errors like

caused by Exception: Error executing system.db.commitTransaction(5ddb00c3-61d9-4696-a355-fb1fc7b585a2)
	caused by GatewayException: Transaction "5ddb00c3-61d9-4696-a355-fb1fc7b585a2" is closed.
	caused by SQLException: Transaction "5ddb00c3-61d9-4696-a355-fb1fc7b585a2" is closed.

Putting the commit/close inside the try/except as well silences this error sure, but nothing is inserted and I get another error when self.idx is referenced as it is a None but I am expecting the ID indicating to me the query did never actually execute.

Is there some way to make this work or is it not feasible currently?

kcollins1 · February 22, 2022, 5:16pm

If you’re going to omit the database argument (and use the project default database, which is perfectly fine), you’ll probably want to use keyword arguments. It is interpreting the first argument as the database connection name.

Try:

...
self.tx = system.db.beginNamedQueryTransaction(isolationLevel=self.isolationLevel, timeout=self.timeout)
...

bkarabinchak.psi · February 22, 2022, 6:00pm

Scratch all that. This works. Thank you.

The documentation for system.db.beginNamedQueryTransaction - Ignition User Manual 8.0 - Ignition Documentation confused me a bit I guess.

For example notice here system.db.runNamedQuery - Ignition User Manual 8.0 - Ignition Documentation

If a parameter is optional it says so immediately after the parameter - indicating it's a keyword

String tx - An optional transaction ID, obtained from beginNamedQueryTransaction. If blank, will not be part of a transaction.

Boolean getKey - Optional. Only used for Update Query types. A flag indicating whether or not the result should be the number of rows affected (getKey=0) or the newly generated key value that was created as a result of the update (getKey=1). Not all databases support automatic retrieval of generated keys.

Whereas with beginNamedQueryTransaction it says it at the very end of the paramter description

Long timeout timeout - The amount of time, in milliseconds, that this connection is allowed to remain open without being used. Timeout counter is reset any time a query or call is executed against the transaction, or when committed or rolled-back. If omitted, defaults to 30,000.

I recognize this is my own fault I must have missed that. I do think its better that immediately after a parameter it's indicated if its a mandatory or optional paramter.

wpmccormick · April 20, 2023, 12:34am

I guess this issue is still in the backlog?

WRT the workaround; if I run statements (and why wouldn't I? I mean that's why I'm wrapping this is a transaction), and set the attemptedQuery = True, shouldn't I expect to find my code re-raising the exception if both commit and close will generate java.lang.Exception?

What am I missing?

bkarabinchak.psi · April 20, 2023, 3:58pm

I don't have an issue with this anymore (and have not since 8.1.17) but I don't know what you mean by attemptedQuery=True I don't see that as a kwarg in beginNamedQuery or anything related. What is your code?

dkhayes117 · April 20, 2023, 4:05pm

It's just a flag that was used in kcollins1 post above.

pascal.fragnoud · July 10, 2023, 7:25am

Hello beautiful people,

I had this issue a while ago and asked about it (here). @PGriffith redirected me there.
All in all, things got smoother and the error only ever appeared when a transaction was opened but there was nothing to commit. Which I fixed easily, by making sure not to open the transaction if there was no query to run.

But a few days ago, things got weird again.
I'm running queries, and I can see in my database that records were indeed inserted just fine, but I get a java.lang.Exception: Error executing system.db.closeTransaction error with this in the stack trace:

Caused by: org.python.core.PyException: java.lang.Exception: java.lang.Exception: Error executing system.db.closeTransaction(5bf23e6b-f299-45c4-8f99-3a3e16a1a5a6)
... 45 common frames omitted
Caused by: java.lang.Exception: Error executing system.db.closeTransaction(5bf23e6b-f299-45c4-8f99-3a3e16a1a5a6)
... 44 common frames omitted
Caused by: java.sql.SQLException: Transaction "5bf23e6b-f299-45c4-8f99-3a3e16a1a5a6" is closed.

To sum it up:

The data is actually inserted
I checked that the transaction ids match
From what I've seen so far this only happens when inserting, not updating.

I'm running 8.17 and can't update.
I'm not sure what to do now.

pturmel · July 10, 2023, 12:14pm

Generally, that means you will simply have to put up with it. IA never backports fixes--it always takes an upgrade to get them.

pascal.fragnoud · July 10, 2023, 12:21pm

I feel like there's a way to make it work satisfactorily.
It works fine in most cases, there's just this one query set that makes it behave like that.
And I believe this same query set used to work fine just last week...

Also, my situation here seems to be a little different that the one discussed previously, as I'm having an error on closeTransaction and not commitTransaction, and the commits do work.
My hope here is that there's an explanation, that someone might have an idea about what's going on, so that I can adapt my code to "fit the issue".

kcollins1 · July 10, 2023, 2:27pm

Not sure why you ran into an issue closing the transaction, I'm assuming you're not trying to close it twice or something like that. If everything committed just fine, you could probably catch anything that trips on the close and perhaps log it, but let your script continue on. Out of curiosity, what version of SQL Server and also what version of JDBC driver (in Ignition) are you using?

pascal.fragnoud · July 10, 2023, 2:37pm

I'm running the 2022-latest docker image, last updated about 3 weeks / 1month ago.
The JDBC driver seems to be 4.2

No, I'm actually using a decorator to handle basic transaction stuff, so all my transactional queries run through the exact same setup. This decorator and only this decorator is in charge of starting the transaction, rolling it back, committing it, and closing it.
Something like that:

def transaction(func):
	def wrapper(*args):
		tx = system.db.beginNamedQueryTransaction(
			project = project_name,
			database = db_name
		)
		try:
			ret = func(*args, tx=tx)
		except (Throwable, Exception) as e:
			system.db.rollbackTransaction(tx)
			raise
		else:
			system.db.commitTransaction(tx)
			return ret
		finally:
			system.db.closeTransaction(tx)
	return wrapper

I guess I'll end up doing something like that, but It's quite annoying as I'm using error catching quite heavily already.
Thanks for the input.

kcollins1 · July 10, 2023, 2:56pm

I know you're bound to 8.1.17, but that shouldn't mean that you need to stay on such an old JDBC driver. Take a peek at the support matrix here for insights (specifically the SQL Server Version matrix at this header).