Error storing to data cache?

rahman.tarek · February 1, 2023, 1:56pm

Hello all the server that hosts Ignition crashed and after that i am getting the following errors. Does anyone know why this is happening and what we can do to prevent it?:

java.lang.NullPointerException: null

at com.inductiveautomation.ignition.gateway.history.stores.AbstractDatasourceStore.syncdStoreData(AbstractDatasourceStore.java:316)

at com.inductiveautomation.ignition.gateway.history.stores.AbstractDatasourceStore.storeQuarantinedData(AbstractDatasourceStore.java:271)

at com.inductiveautomation.ignition.gateway.history.stores.MemoryStore$BasicForwardTransaction.storeQuarantineData(MemoryStore.java:325)

at com.inductiveautomation.ignition.gateway.history.stores.MemoryStore$BasicForwardTransaction.markFailed(MemoryStore.java:281)

at com.inductiveautomation.ignition.gateway.history.forwarders.ForwarderThread.run(ForwarderThread.java:151)

PGriffith · February 1, 2023, 4:51pm

What version of Ignition is this? An NPE is, basically always, a bug in Ignition.

rahman.tarek · February 1, 2023, 5:04pm

version 8.1.19

Bryan_Mason · February 1, 2023, 5:15pm

I'm also experiencing this error in 8.1.21. It might be related to my store and forward events that are backed up. Ignition can't find any tables in my database (Invalid object name 'sqlth_drv'.) Seems like it's defaulting to the Master database even though I have specified the correct database.
@rahman.tarek do you have this error too?

There is a problem checking the tag history database tables during initialization of the store and forward engine which could prevent tag history data from being forwarded properly.

PGriffith · February 1, 2023, 5:21pm

Both of you should probably contact support. From some looking around our bug tracker, this looks similar to something our QA team encountered during automation runs, but we weren't able to track down the root cause of. More information could certainly help.

rahman.tarek · February 1, 2023, 5:24pm

How do i create a ticket for support

PGriffith · February 1, 2023, 5:31pm

https://support.inductiveautomation.com/hc/en-us

Bryan_Mason · February 1, 2023, 6:03pm

The solution for me was to change the default schema on my database login. I had to create a dedicated database login instead of using my own dbo account.

pturmel · February 21, 2023, 7:09pm

I have client getting these regularly on v8.1.15. Typically accompanied by a constraint failure. Logs look like this:

INFO   | jvm 1    | 2023/02/21 07:54:41 | E [S.S.M.MemoryForwardTransaction] [12:54:41]: Error forwarding data store-forward-name=HomerRD
INFO   | jvm 1    | 2023/02/21 07:54:41 | java.lang.RuntimeException: org.postgresql.util.PSQLException: ERROR: null value in column "id" violates not-null constraint
INFO   | jvm 1    | 2023/02/21 07:54:41 |   Detail: Failing row contains (null, _exempt_, 2).
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.common.functional.FragileConsumer.lambda$wrap$1(FragileConsumer.java:47)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ReferencePipeline$2$1.accept(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ReferencePipeline$3$1.accept(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ReferencePipeline$2$1.accept(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.Streams$StreamBuilderImpl.forEachRemaining(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ReferencePipeline$Head.forEach(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ReferencePipeline$7$1.accept(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at java.base/java.util.stream.ReferencePipeline.forEach(Unknown Source)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.gateway.history.sf.sinks.AbstractDatasourceSink.storeToDatasource(AbstractDatasourceSink.java:186)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.gateway.history.sf.sinks.AbstractDatasourceSink.storeData(AbstractDatasourceSink.java:156)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.gateway.history.sf.sinks.AggregateSink.storeData(AggregateSink.java:180)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.gateway.history.forwarders.ForwarderThread.run(ForwarderThread.java:147)
INFO   | jvm 1    | 2023/02/21 07:54:41 | Caused by: org.postgresql.util.PSQLException: ERROR: null value in column "id" violates not-null constraint
INFO   | jvm 1    | 2023/02/21 07:54:41 |   Detail: Failing row contains (null, _exempt_, 2).
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper$SRPreparedStatement.executeUpdate(SRConnectionWrapper.java:981)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper.runPrepInsertGetKey(SRConnectionWrapper.java:260)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.getIdOfScanclassName(TagHistoryDatasourceSink.java:634)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.getTagIds(TagHistoryDatasourceSink.java:759)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.insertTagValues(TagHistoryDatasourceSink.java:990)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.storeScanClassSet(TagHistoryDatasourceSink.java:529)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.storeDataToDatasource(TagHistoryDatasourceSink.java:504)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.gateway.history.sf.sinks.AbstractDatasourceSink.lambda$storeToDatasource$2(AbstractDatasourceSink.java:186)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	at com.inductiveautomation.ignition.common.functional.FragileConsumer.lambda$wrap$1(FragileConsumer.java:45)
INFO   | jvm 1    | 2023/02/21 07:54:41 | 	... 18 common frames omitted

However, some entries are abbreviated, like this:

INFO   | jvm 1    | 2023/02/21 07:54:22 | E [S.S.HsqlDataStore             ] [12:54:22]: Error storing to data cache. store-forward-name=HomerRD
INFO   | jvm 1    | 2023/02/21 07:54:22 | java.lang.NullPointerException: null
INFO   | jvm 1    | 2023/02/21 07:54:28 | E [S.S.HsqlDataStore             ] [12:54:28]: Error storing to data cache. store-forward-name=HomerRD
INFO   | jvm 1    | 2023/02/21 07:54:28 | java.lang.NullPointerException: null

I'm not sure if the two paths are related, but they come in batches. The client's trends have gaps corresponding to these log events.

Edit: I suppose I need to edit ignition.conf to get full traces from those latter log entries...

pturmel · February 21, 2023, 7:14pm

FWIW, they are also accumulating some quarantined items in their S&F caches, most of which succeed on retry. The description in the UI looks like some of the log entries: (null, _exempt_, 2), but that detail does not show in the quarantine's XML export. Also, successful retries do not fill in all of the gaps in the data.

pturmel · February 24, 2023, 1:41pm

I was able to restart the client's Ignition yesterday evening to enable the full traces from fast throws. The abbreviated Errors above expand as follows:

2023/02/24 07:24:45.345 | E [S.S.HsqlDataStore             ] [12:24:45]: Error storing to data cache. store-forward-name=HomerRD
2023/02/24 07:24:45.345 | java.lang.NullPointerException: null
2023/02/24 07:24:45.345 | 	at com.inductiveautomation.ignition.gateway.history.stores.AbstractDatasourceStore.syncdStoreData(AbstractDatasourceStore.java:313)
2023/02/24 07:24:45.345 | 	at com.inductiveautomation.ignition.gateway.history.stores.AbstractDatasourceStore.storeQuarantinedData(AbstractDatasourceStore.java:268)
2023/02/24 07:24:45.345 | 	at com.inductiveautomation.ignition.gateway.history.stores.MemoryStore$BasicForwardTransaction.storeQuarantineData(MemoryStore.java:325)
2023/02/24 07:24:45.345 | 	at com.inductiveautomation.ignition.gateway.history.stores.MemoryStore$BasicForwardTransaction.markFailed(MemoryStore.java:281)
2023/02/24 07:24:45.345 | 	at com.inductiveautomation.ignition.gateway.history.forwarders.ForwarderThread.run(ForwarderThread.java:151)

This client is getting many of these:

$ grep 'E \[S.S.HsqlDataStore' wrapper_20230224_0724.log |wc -l
549

About eight per minute.

{ I opened a support ticket. }

PGriffith · February 24, 2023, 3:23pm

That NPE is supposed to be fixed in 8.1.26; see this changelog:

For the S+F issue, Kindling might give you a more useful view of the serialized data to give you some idea where it's coming from?

pturmel · February 24, 2023, 4:57pm

Yes, the work-around in the meantime is to disable the S&F disk caches, rename/delete the corresponding folders in {installdir}/data/datacache, then re-enable the disk caches. I skipped the last step, as the client's system doesn't need disk caching. (Generously provisioned, lightly loaded.) The trend gaps are gone.

The remaining issue, the attempt to insert null into the DB during a MemoryForwardTransaction, is still happening but does not appear to be causing any ill effect. There's nothing to look at with kindling, as there are no quarantined records now. The log entry suggests that the error is in a metadata table, not a history partition.

{ I closed the support ticket, as the client-visible problem is fixed. }

hunterdg · April 18, 2024, 3:48pm

Does this look familiar? (I'm not seeing mention of MemoryForwardTransaction though)

Wrapper Log

INFO   | jvm 1    | 2024/04/18 10:45:03 | W [S.S.TagHistoryDatasourceSink  ] [15:45:03]: There is a problem checking the tag history database tables during initialization of the store and forward engine which could prevent tag history data from being forwarded properly. Trying again in 60 seconds. 
INFO   | jvm 1    | 2024/04/18 10:45:03 | com.microsoft.sqlserver.jdbc.SQLServerException: Cannot insert the value NULL into column 'id', table 'IGN_HIST_CS.dbo.sqlth_drv'; column does not allow nulls. INSERT fails.
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:265)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1662)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:615)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:537)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7417)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3488)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:262)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:237)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(SQLServerPreparedStatement.java:483)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper$SRPreparedStatement.executeUpdate(SRConnectionWrapper.java:981)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.inductiveautomation.ignition.gateway.datasource.SRConnectionWrapper.runPrepUpdate(SRConnectionWrapper.java:181)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.loadOrCreateSystemDetails(TagHistoryDatasourceSink.java:483)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.getSystemDetails(TagHistoryDatasourceSink.java:433)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.inductiveautomation.gateway.tags.history.storage.TagHistoryDatasourceSink.initialize(TagHistoryDatasourceSink.java:296)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$ThrowableCatchingRunnable.run(BasicExecutionEngine.java:544)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2024/04/18 10:45:03 | 	at java.base/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2024/04/18 10:46:03 | I [S.S.TagHistoryDatasourceSink  ] [15:46:03]: Tag history tables verified successfully.

pturmel · April 18, 2024, 4:41pm

Vaguely. That client of mine uses PostgreSQL, not MS SQL Server.