Hi,
i have a little problem with my driver module. After a restart i get a debug message:
INFO | jvm 1 | 2013/04/01 18:59:31 | DEBUG [DriverVariableNode ] [18:59:31,856]: Setting [TCPBin]Msg0/_Timestamp@2000ms to stale. Last update was 11316ms ago. Max age is 10000.0ms.As this does not happen with other drivers i think i did something wrong. On shutdown i remove all Nodes with NodeManager#removeNode. Is there anything else i am missing?
Thanks for your help.
Do you get any warnings when removing the node?
Or is it possible that you are setting a value initially on start up but then not again until ~11 seconds later?
Setting DriverVariableNode’s logger to TRACE will let you see everything that gets set on it… but it’s going to log info for ALL driver nodes, so you’ll need to make sure you’ve got a minimal setup.
Sorry, i shoulf have mentioned that this message repeats every second with the last update value increasing. Only way to stop it is restarting the OPC-UA server module.
This only happens when the node has been subscribed on shutdown. The driver adds many other nodes that do not show this message.
There are no errors when removing the node. The sequence used is:
INFO | jvm 1 | 2013/04/01 19:54:28 | DEBUG [StandardNodeManager ] [19:54:28,647]: Adding Node "DriverVariableNode@10ecc06[nodeId=[TCPBin]Msg0/_Timestamp,nodeClass=Variable,dataType=ns=0:i=13]".
INFO | jvm 1 | 2013/04/01 19:54:28 | TRACE [DriverVariableNode ] [19:54:28,647]: Driver setting value value=null, status=StatusCode[0x80320000, Severity=Bad, Subcode=Bad_WaitingForInitialData], source=null, server=Mon Apr 01 19:54:28 CEST 2013 on NodeId [TCPBin]Msg0/_Timestamp
...
INFO | jvm 1 | 2013/04/01 19:54:37 | DEBUG [DriverVariableNode ] [19:54:37,890]: MonitoredItem@2000 added to DriverVariableNode@10ecc06[nodeId=[TCPBin]Msg0/_Timestamp,nodeClass=Variable,dataType=ns=0:i=13].
SHUTDOWN...
INFO | jvm 1 | 2013/04/01 19:56:56 | DEBUG [StandardNodeManager ] [19:56:56,850]: Removed Node "DriverVariableNode@10ecc06[nodeId=[TCPBin]Msg0/_Timestamp,nodeClass=Variable,dataType=ns=0:i=13]".
RESTART...
INFO | jvm 1 | 2013/04/01 19:56:57 | DEBUG [StandardNodeManager ] [19:56:57,561]: Adding Node "DriverVariableNode@78a1e9[nodeId=[TCPBin]Msg0/_Timestamp,nodeClass=Variable,dataType=ns=0:i=13]".
INFO | jvm 1 | 2013/04/01 19:56:57 | TRACE [DriverVariableNode ] [19:56:57,561]: Driver setting value value=null, status=StatusCode[0x80320000, Severity=Bad, Subcode=Bad_WaitingForInitialData], source=null, server=Mon Apr 01 19:56:57 CEST 2013 on NodeId [TCPBin]Msg0/_Timestamp
...
INFO | jvm 1 | 2013/04/01 19:57:09 | TRACE [DriverVariableNode ] [19:57:09,418]: Driver setting value value=1364838786519, status=StatusCode[0x00000000, Severity=Good, Subcode=NotSpecified], source=Mon Apr 01 19:57:07 CEST 2013, server=null on NodeId [TCPBin]Msg0/_Timestamp
INFO | jvm 1 | 2013/04/01 19:57:09 | DEBUG [DriverVariableNode ] [19:57:09,548]: Setting [TCPBin]Msg0/_Timestamp@2000ms to stale. Last update was 12788ms ago. Max age is 10000.0ms.
INFO | jvm 1 | 2013/04/01 19:57:10 | DEBUG [DriverVariableNode ] [19:57:10,560]: Setting [TCPBin]Msg0/_Timestamp@2000ms to stale. Last update was 13800ms ago. Max age is 10000.0ms.
...The subscription works after the restart, but it seems the MonitoredItem added after the initial start is still there. I wonder why there isn’t a MonotoredItem added to the new node after the restart.
Hmm, it’s a bit of an oversight that the item isn’t added back to the node after restart - I’ll have to fix that. I don’t think that’s the issue here though.
It almost sounds like setValue() is still being called on the old Node instance rather than the new one…
I just analyzed a few heap dumps. Does ‘StaleCheckList’ ring any bell?
After the driver restart, the number of driver variable nodes increased, and i have a lot of nodes that are only referenced by this staleCheckList.
When i restart the OPC-UA module there are suddenly two different DriverVariableNode classes in the heap dump. One of them (seems to be stale) has only nodes referenced by staleCheckList. After every OPC-UA restart another stale class is added.
After seeing this, i did a test with the Simulation driver, and it shows the same behaviour:
INFO | jvm 1 | 2013/04/01 20:56:56 | DEBUG [DriverVariableNode ] [20:56:56,646]: Setting [Sim]_Meta:Random/RandomInteger1@1000ms to stale. Last update was 8162ms ago. Max age is 5000.0ms.
I think the key to this that i call #setValue on nodes, even if there are no subscription (I think that is the same way the _Meta tags in the Sim Driver work). My guess is, that those nodes are added to a stale checker and never removed from it. As soon as there has been a subscription, the stale checker starts throwing those warnings.
[quote=“chi”]I just analyzed a few heap dumps. Does ‘StaleCheckList’ ring any bell?
After the driver restart, the number of driver variable nodes increased, and i have a lot of nodes that are only referenced by this staleCheckList.
When i restart the OPC-UA module there are suddenly two different DriverVariableNode classes in the heap dump. One of them (seems to be stale) has only nodes referenced by staleCheckList. After every OPC-UA restart another stale class is added.
[attachment=0]HeapDump.png[/attachment]
After seeing this, i did a test with the Simulation driver, and it shows the same behaviour:
INFO | jvm 1 | 2013/04/01 20:56:56 | DEBUG [DriverVariableNode ] [20:56:56,646]: Setting [Sim]_Meta:Random/RandomInteger1@1000ms to stale. Last update was 8162ms ago. Max age is 5000.0ms.
I think the key to this that i call #setValue on nodes, even if there are no subscription (I think that is the same way the _Meta tags in the Sim Driver work). My guess is, that those nodes are added to a stale checker and never removed from it. As soon as there has been a subscription, the stale checker starts throwing those warnings.[/quote]
I think you’re on to something, I’ll look at the stale checker’s removal logic.
I can’t get the same behavior to happen with the Sim driver though… what version are you using again?
Version is 7.5.6(b1316).
For the SimDriver i just created a SQLTag in default ScanClass and then restartet the Allen-Bradley Drivers module. With DriverVariableNode set to TRACE, the stale messages started appearing in the log ~10 seconds after the restart.
Ok, thanks. I was just restarting the individual device via edit/save.
Looks like I’ve got some reference leaks to plug 
Ok, I’ve attached a 1.5.7-beta1 OPC-UA module.
Please verify that upon restarting both your driver module and the UA module itself the instance count of DriverVariableNodes remains the same in the profiler (assuming the rest of the system is in a static state).
I have verified that this is the case with the UA module + AB driver module.
I’ve also found the lingering reference that was causing StaleCheckList instances to persist across module restarts (and along with that reference came instances of practically everything else, not just StaleCheckList… 
) and fixed that as well.
OPC-UA-module.modl (1.53 MB)
I did some tests with the new module, here are the results:
The instance count of DriverVariableNodes remains the same. I get a lot of info messages from ‘StaleCheckList…marked for removal’ now after the restart.
The ‘Setting … to stale’ messages are now gone, so this problem should be fixed.
After a restart of the OPC-UA module, there are now no old instances of DriverVariableNode anymore (though the classes are still not unloaded).
Only noticable thing is that there are still no MonitoredItems readded after a driver restart.
Update:
Some very strange things happen now:
After every second restart of UPC-UA module i get double subscriptions:
After first restart:
INFO | jvm 1 | 2013/04/02 21:15:07 | TRACE [msg0 ] [21:15:07,111]: Subscription updating tag Msg0/intVal[0] Value:38285
INFO | jvm 1 | 2013/04/02 21:15:07 | TRACE [DriverVariableNode ] [21:15:07,111]: Driver setting value value=38285, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Tue Apr 02 21:14:33 CEST 2013, server=Tue Apr 02 21:15:03 CEST 2013 on NodeId [TCPBin]Msg0/intVal[0]
INFO | jvm 1 | 2013/04/02 21:15:07 | TRACE [DriverVariableNode ] [21:15:07,111]: Driver setting value value=38285, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Tue Apr 02 21:14:33 CEST 2013, server=Tue Apr 02 21:15:03 CEST 2013 on NodeId [TCPBin]Msg0/intVal[0]
After second restart:
INFO | jvm 1 | 2013/04/02 21:16:17 | TRACE [msg0 ] [21:16:17,032]: Subscription updating tag Msg0/intVal[0] Value:38291
INFO | jvm 1 | 2013/04/02 21:16:17 | TRACE [DriverVariableNode ] [21:16:17,032]: Driver setting value value=38291, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Tue Apr 02 21:15:33 CEST 2013, server=Tue Apr 02 21:15:50 CEST 2013 on NodeId [TCPBin]Msg0/intVal[0]Also, after a restart, it now takes a long time till items are subscribed (about 25-30 seconds).
I am not sure if this also happened in the previous version.
Here’s a 1.5.7-beta2 module, I’ve done more work in this area since yesterday.
OPC-UA-module.modl (1.53 MB)
Good job, beta2 looks good to me.
Count of DriverVariableNodes remains the same after restarts, MonitoredItems are now added after a driver restart.
I don’t see any unusual messages any more.
The time delay after OPC-UA module restart mentioned in my last post may be caused by the client, not by the server. The subscription are added as soon as the clients connection to the old instance times out.
Last minor issue is that there remain active instances of XOPCModule and XOPCServer (that keep references to all drivers, services…) after a restart. They are however deleted after ~5-10 minutes (after someting times out internally?).
[quote=“chi”]
Last minor issue is that there remain active instances of XOPCModule and XOPCServer (that keep references to all drivers, services…) after a restart. They are however deleted after ~5-10 minutes (after someting times out internally?).[/quote]
Hmm, I’ll have to try profiling against an installed instance of Ignition rather than one running out of my IDE and see if that makes a difference.
So it actually turns out that BundleUtil leaks the ClassLoaders of:
a) any module that adds a bundle and doesn’t remove it.
b) any module that adds a PersistentRecord (the properties file associated with the record is automatically loaded when given to SchemaUpdater#updatePersistentRecords() but never unloaded).
So… that should be fixed for 7.5.7.