Batchoperations flood of errors

ryanjmclaughlin · November 4, 2020, 1:58pm

In 8.0.16, I am getting a ton of logs under the tags.storage.batchoperations. Any ideas on what is going on here? It seems like something is corrupted with my tag provider, but not sure how I can fix it…

simpleorm.utils.SException$Error: Cannot access destroyed record [InternalJsonStorageInfoRecord [Destroyed SRecordInstance] Dirty-2]
at simpleorm.dataset.SRecordInstance.checkFieldIsAccessible(SRecordInstance.java:233)
at simpleorm.dataset.SRecordInstance.setObject(SRecordInstance.java:255)
at simpleorm.dataset.SRecordInstance.setObject(SRecordInstance.java:248)
at simpleorm.dataset.SRecordInstance.setString(SRecordInstance.java:424)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageInfoRecord.setVersion(InternalJsonStorageInfoRecord.java:35)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager.saveVersion(InternalJsonStorageManager.java:90)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager$RedundantTagSynchronizationProvider.setVersion(InternalJsonStorageManager.java:592)
at com.inductiveautomation.ignition.gateway.redundancy.types.AbstractSynchronizedStateProvider.incrementVersion(AbstractSynchronizedStateProvider.java:93)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager$RedundantTagSynchronizationProvider.processChanges(InternalJsonStorageManager.java:640)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager.save(InternalJsonStorageManager.java:181)
at com.inductiveautomation.ignition.gateway.tags.config.BatchConfigOperation.execute(BatchConfigOperation.java:100)
at com.inductiveautomation.ignition.gateway.tags.evaluation.BatchContextImpl$OpController.run(BatchContextImpl.java:187)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.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)

adam.todorski · November 10, 2020, 6:02pm

I’ve also seen this alongside some pretty scary stability issues with the platform itself (installed licenses disappearing, HTTP 500 errors when trying to get into the gateway web UI, connected designer sessions locking up). This was on a dev system that gets flogged with major changes all the time for me so I assumed we had created some bad sequence of peering it with other gateways then having those gateways go away or something along those lines to cause it, but the only clue I have is that the internal DB appears to be inaccessible by parts of the system:

INFO | jvm 1 | 2020/11/10 17:51:09 INFO | jvm 1 | 2020/11/10 17:51:09 INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | INFO | jvm 1 | 2020/11/10 17:51:09 | | E [t.s.internaljson ] [17:51:09]: Errror storing tag changes. provider=default
| simpleorm.utils.SException$Jdbc: Executing UPDATE tagconfig SET cfg = ? WHERE id = ? AND cfg = ? for [TagConfigurationRecord 46ae0157-c826-4e2b-ac9c-7628c7e8d257.5462bb3f-1b41-47ce-9d30-77bfd1bcda1c Dirty0]
at simpleorm.sessionjdbc.SSessionJdbcHelper.flushExecuteUpdate(SSessionJdbcHelper.java:434)
at simpleorm.sessionjdbc.SSessionJdbcHelper.flush(SSessionJdbcHelper.java:400)
at simpleorm.sessionjdbc.SSessionJdbc.flush(SSessionJdbc.java:459)
at simpleorm.sessionjdbc.SSessionJdbc.flush(SSessionJdbc.java:443)
at simpleorm.sessionjdbc.SSessionJdbc.commit(SSessionJdbc.java:375)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager.saveInternal(InternalJsonStorageManager.java:286)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager$IndependantTagSynchronizationProvider.processChanges(InternalJsonStorageManager.java:532)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager$RedundantTagSynchronizationProvider.processChanges(InternalJsonStorageManager.java:622)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager.save(InternalJsonStorageManager.java:181)
at com.inductiveautomation.ignition.gateway.tags.config.BatchConfigOperation.execute(BatchConfigOperation.java:100)
at com.inductiveautomation.ignition.gateway.tags.evaluation.BatchContextImpl$OpController.run(BatchContextImpl.java:187)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.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)
Suppressed: simpleorm.utils.SException$Jdbc: Executing UPDATE tagconfig SET cfg = ? WHERE id = ? AND cfg = ? for [TagConfigurationRecord 4e6678a1-e4ce-4015-ae7b-06cba77ffb05.58a6a5de-1130-4258-b1a9-bb3415003a7b Dirty1]
at simpleorm.sessionjdbc.SSessionJdbcHelper.flushExecuteUpdate(SSessionJdbcHelper.java:434)
at simpleorm.sessionjdbc.SSessionJdbcHelper.flush(SSessionJdbcHelper.java:400)
at simpleorm.sessionjdbc.SSessionJdbc.flush(SSessionJdbc.java:459)
at simpleorm.sessionjdbc.SSessionJdbc.flush(SSessionJdbc.java:443)
at simpleorm.sessionjdbc.SSessionJdbc.commitAndDetachDataSet(SSessionJdbc.java:382)
at com.inductiveautomation.ignition.gateway.localdb.persistence.PersistenceSession.close(PersistenceSession.java:61)
at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager.saveInternal(InternalJsonStorageManager.java:284)
… 11 common frames omitted
Caused by: org.sqlite.SQLiteException: [SQLITE_CANTOPEN] Unable to open the database file (unable to open database file)
at org.sqlite.core.DB.newSQLException(DB.java:909)
at org.sqlite.core.DB.newSQLException(DB.java:921)
at org.sqlite.core.DB.execute(DB.java:825)
at org.sqlite.core.DB.executeUpdate(DB.java:863)
at org.sqlite.jdbc3.JDBC3PreparedStatement.executeUpdate(JDBC3PreparedStatement.java:102)
at simpleorm.sessionjdbc.SSessionJdbcHelper.flushExecuteUpdate(SSessionJdbcHelper.java:432)
… 17 common frames omitted
| Caused by: org.sqlite.SQLiteException: [SQLITE_CANTOPEN] Unable to open the database file (unable to open database file)
at org.sqlite.core.DB.newSQLException(DB.java:909)
at org.sqlite.core.DB.newSQLException(DB.java:921)
at org.sqlite.core.DB.execute(DB.java:825)
at org.sqlite.core.DB.executeUpdate(DB.java:863)
at org.sqlite.jdbc3.JDBC3PreparedStatement.executeUpdate(JDBC3PreparedStatement.java:102)
at simpleorm.sessionjdbc.SSessionJdbcHelper.flushExecuteUpdate(SSessionJdbcHelper.java:432)
… 16 common frames omitted

ryanjmclaughlin · November 10, 2020, 6:48pm

Support reviewed this for me and it sounded as its a known issue. A gateway restart fixed it for me, still not sure the root cause.

adam.todorski · November 10, 2020, 6:58pm

Same here with the GW restart fixing it, did they give you an indication of what version may have the bug fix?

Gaurav.Shitole · October 20, 2021, 7:25am

Hello, is there any update on this?

I am using version 8.1.1 and still facing this issue.

ryanjmclaughlin · October 21, 2021, 1:24pm

This was fixed in the current release of Ignition. Suggest you update from 8.1.1 to 8.1.11

Gaurav.Shitole · October 21, 2021, 7:29pm

Okay thanks for the update

martinel3746 · March 3, 2022, 4:02am

I’m seeing the same issue in 8.1.14.
Tech support said to reboot the gateway.
I stopped and restarted the service and it helped for a day.
I’ll reboot the server this weekend and see if that helps.

rbachman · March 11, 2022, 5:28pm

I’m seeing this for the first time today. We plan to reboot the server this weekend to see if that will help. It would be nice to know if there is a known cause so we can address the root issue.

martinel3746 · March 14, 2022, 4:27pm

I have an open ticket for this.
I was told that there was a fix for this in 8.1.15.
After updating from 8.1.14 to 8.1.15 and rebooting the server we now get 3 errors per second.
This server is very simple, using all defaults (except user source), only 24 devices, one UDT and one daily scheduled process.

John_S1 · September 7, 2022, 3:12pm

Hi did you find any solution for this from IA team.

martinel3746 · September 7, 2022, 4:33pm

No.
I’ve upgraded to 8.1.17 and it’s still there.
It doesn’t seem to impact performance for this server and so far hasn’t shown up on any of our other 130+ gateways. I ran out of energy and got tired of chasing it so had the ticket closed.
Every time it flares up, usually ~two days after a gateway startup, I go to the Log Configuration and turn off the “tags.*.batchoperations” loggers.

bprice · December 16, 2022, 10:04pm

I'm not sure when this error persisted for our system. But we are on Version 8.1.18 and this is the first time it has caught my attention. Hoping to be able to restart the gateway soon, as I don't have administrative access on our new server at the moment.

louagejasper · February 24, 2023, 2:30pm

I'm having this on 8.1.24.

Isaac_Hodgkins · June 5, 2023, 2:39pm

I'm having this on 8.1.22

Transistor · June 5, 2023, 2:46pm

Me too on 8.1.26. I'm having to restart the gateway any time I need to use the logs for debugging.

ryanjmclaughlin · June 5, 2023, 2:53pm

Upgraded to 8.1.28 and still an issue

ironyeti1 · June 26, 2023, 7:01pm

I think this will have to be the permanent solution

Anthony_Granato · August 15, 2023, 8:20pm

Agreed. The Log Configuration settings apply to all users, so it is not a bad one either... for now at least. Just need to be careful and have awareness

avaughn · August 29, 2023, 10:09pm

There should be a fix for this in 8.1.32 RC1 which is currently available to download for testing.

Screenshot from the 8.1.32 RC1 Release Notes