'Error storing tag values' on internal db auto backup

chi · June 8, 2015, 1:12pm

After upgrading from 7.6 to 7.7.4 there is an error looged everytime i save a changed project. Is there anything i can do to fix this?

[code]INFO | jvm 1 | 2015/06/08 15:02:07 | INFO [ENGINE ] [15:02:07,233]: Successfully backed up instance ‘settings’ to ‘C:\Program Files\Inductive Automation\Ignition\data\db\autobackup\db_20150608_150203.tar.gz’
INFO | jvm 1 | 2015/06/08 15:02:07 | INFO [LocalDBManagerImpl ] [15:02:07,313]: Created auto-backup of internal database “settings” in 4 Sekunden
INFO | jvm 1 | 2015/06/08 15:02:07 | ERROR [TagStore ] [15:02:07,329]: Error storing tag values.
INFO | jvm 1 | 2015/06/08 15:02:07 | simpleorm.utils.SException$Jdbc: Executing UPDATE SQLTagProp SET DoubleVal = ? WHERE TagId = ? AND Name = ? AND DoubleVal = ? AND Path = ? for [TagPropertyRecord 754, Value, Dirty0]
INFO | jvm 1 | 2015/06/08 15:02:07 | at simpleorm.sessionjdbc.SSessionJdbcHelper.flushExecuteUpdate(SSessionJdbcHelper.java:409)
INFO | jvm 1 | 2015/06/08 15:02:07 | at simpleorm.sessionjdbc.SSessionJdbcHelper.flush(SSessionJdbcHelper.java:376)
INFO | jvm 1 | 2015/06/08 15:02:07 | at simpleorm.sessionjdbc.SSessionJdbc.flush(SSessionJdbc.java:425)
INFO | jvm 1 | 2015/06/08 15:02:07 | at simpleorm.sessionjdbc.SSessionJdbc.flush(SSessionJdbc.java:410)
INFO | jvm 1 | 2015/06/08 15:02:07 | at simpleorm.sessionjdbc.SSessionJdbc.commit(SSessionJdbc.java:344)
INFO | jvm 1 | 2015/06/08 15:02:07 | at com.inductiveautomation.ignition.gateway.sqltags.tagproviders.internal.InternalTagStore.internalStoreTagValues(InternalTagStore.java:1302)
INFO | jvm 1 | 2015/06/08 15:02:07 | at com.inductiveautomation.ignition.gateway.sqltags.tagproviders.internal.InternalTagStore.storeTagValues(InternalTagStore.java:1190)
INFO | jvm 1 | 2015/06/08 15:02:07 | at com.inductiveautomation.ignition.gateway.sqltags.providers.AbstractStoreBasedTagProvider.tagValuesChanged(AbstractStoreBasedTagProvider.java:2064)
INFO | jvm 1 | 2015/06/08 15:02:07 | at com.inductiveautomation.ignition.gateway.sqltags.scanclasses.SimpleExecutableScanClass$ScanClassTagEvaluationContext.processAndReset(SimpleExecutableScanClass.java:1155)
INFO | jvm 1 | 2015/06/08 15:02:07 | at com.inductiveautomation.ignition.gateway.sqltags.scanclasses.SimpleExecutableScanClass.run(SimpleExecutableScanClass.java:889)
INFO | jvm 1 | 2015/06/08 15:02:07 | at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$TrackedTask.run(BasicExecutionEngine.java:584)
INFO | jvm 1 | 2015/06/08 15:02:07 | at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at java.util.concurrent.FutureTask.runAndReset(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at java.lang.Thread.run(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | Caused by: java.sql.SQLTransactionRollbackException: transaction rollback: serialization failure
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.jdbc.JDBCPreparedStatement.fetchResult(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.jdbc.JDBCPreparedStatement.executeUpdate(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:102)
INFO | jvm 1 | 2015/06/08 15:02:07 | at simpleorm.sessionjdbc.SSessionJdbcHelper.flushExecuteUpdate(SSessionJdbcHelper.java:407)
INFO | jvm 1 | 2015/06/08 15:02:07 | … 17 more
INFO | jvm 1 | 2015/06/08 15:02:07 | Caused by: org.hsqldb.HsqlException: transaction rollback: serialization failure
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.error.Error.error(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.error.Error.error(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.Session.executeCompiledStatement(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | at org.hsqldb.Session.execute(Unknown Source)
INFO | jvm 1 | 2015/06/08 15:02:07 | … 21 more

[/code]

Colby.Clegg · June 10, 2015, 11:06pm

Hi,

This happens every time you save? From that log, it looks like it might be related to the auto-backups, that perhaps that operation is killing all outstanding operations on the internal db.

We haven’t narrowed down exactly what’s going on with this yet, but it has been coming up sporadically. We upgraded the version of the internal db library for 7.7.5 rc2. If it is so repeatable on your system, and you are able to test the upgrade, that might be useful. You can probably also try upgrading the hsql db jar directly in lib/core/gateway to 2.3.3-rc (I only mention it because I know you would probably surmise this anyhow).

Regards,

chi · July 22, 2015, 1:28pm

Hi,

i had to restart the gateway some days ago, after that the error does not show anymore. I think this was the first restart since the update.

chi · July 27, 2017, 1:24pm

Hi,

it happens again, this time on Ignition 7.8.5 without any previous update. I’m not sure when the errors started again, but this time a gateway restart does not help.
The internal db has a size of about 65.000 kb. On the same gateway, there’s a problem with system memory comsumption (in this thread), maybe this problem is somehow related.

INFO   | jvm 1    | 2017/07/27 15:21:15 | ERROR [SingleConnectionDatasource    ] [15:21:15,769]: The following stack successfully received a connection. A new attempt was blocked for over 30000 ms
INFO   | jvm 1    | 2017/07/27 15:21:15 | java.lang.Throwable
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.localdb.sqlite.SingleConnectionDatasource.getConnection(SingleConnectionDatasource.java:43)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.localdb.sqlite.SQLiteDBManager$AutoBackupDaemon.run(SQLiteDBManager.java:592)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$TrackedTask.run(BasicExecutionEngine.java:584)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.FutureTask.runAndReset(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | ERROR [TagStore                      ] [15:21:15,778]: Error storing tag values.
INFO   | jvm 1    | 2017/07/27 15:21:15 | simpleorm.utils.SException$Jdbc: Opening com.inductiveautomation.ignition.gateway.localdb.sqlite.SingleConnectionDatasource@a451ca
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at simpleorm.sessionjdbc.SSessionJdbc.innerOpen(SSessionJdbc.java:113)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.localdb.persistence.PersistenceSession.initialize(PersistenceSession.java:28)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.localdb.PersistenceInterfaceImpl.getSession(PersistenceInterfaceImpl.java:69)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.localdb.PersistenceInterfaceImpl.getSession(PersistenceInterfaceImpl.java:46)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.sqltags.tagproviders.internal.InternalTagStore.openIfNot(InternalTagStore.java:1293)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.sqltags.tagproviders.internal.InternalTagStore.internalStoreTagValues(InternalTagStore.java:1332)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.sqltags.tagproviders.internal.InternalTagStore.storeTagValues(InternalTagStore.java:1241)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.sqltags.providers.AbstractStoreBasedTagProvider.tagValuesChanged(AbstractStoreBasedTagProvider.java:2343)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.sqltags.scanclasses.SimpleExecutableScanClass$ScanClassTagEvaluationContext.processAndReset(SimpleExecutableScanClass.java:1186)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.sqltags.scanclasses.SimpleExecutableScanClass.run(SimpleExecutableScanClass.java:908)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$SelfSchedulingRunner.run(BasicExecutionEngine.java:502)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$TrackedTask.run(BasicExecutionEngine.java:584)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2017/07/27 15:21:15 | Caused by: java.sql.SQLException: Connection is locked. Datasource only allows one connection at a time. To log the concurrent connection, turn the logger 'com.inductiveautomation.ignition.gateway.localdb.sqlite.SingleConnectionDatasource' to DEBUG.
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at com.inductiveautomation.ignition.gateway.localdb.sqlite.SingleConnectionDatasource.getConnection(SingleConnectionDatasource.java:58)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	at simpleorm.sessionjdbc.SSessionJdbc.innerOpen(SSessionJdbc.java:111)
INFO   | jvm 1    | 2017/07/27 15:21:15 | 	... 18 more
INFO   | jvm 1    | 2017/07/27 15:21:18 | INFO  [LocalDBManagerImpl            ] [15:21:18,446]: Created auto-backup of internal database "config.idb" in 33 seconds

richardNZ15 · March 5, 2019, 8:08am

I am now getting this same internal DB error with the following error on v7.9.10. Any resolutions?

Caused by: java.sql.SQLException: Connection is locked. Datasource only allows one connection at a time. More information was logged to the gateway console.

at com.inductiveautomation.ignition.gateway.localdb.sqlite.SingleConnectionDatasource.getConnection(SingleConnectionDatasource.java:75)