Transaction group misses data with subscribed trigger

Ignition
1

Sorry, it's me again with another problem.

I have an random problem with a transaction group missing triggers. Unfortunately i have not been able to reliable reproduce the issue, so i try to describe what happens:

The transaction has a 'active on value change' trigger. The same opc tag that is used for the trigger is used a second time in the group to log a converted value.

When the driver updates the subscription, the trigger value is sometimes one execution cycle behind the other values.
Here is a log that shows what happens:

At this point, the transaction group has executed the first time with 'null' as teh trigger value. The driver has been updating the subscription twice before.
In the DB, the logged trigger value is also null, but the second value that uses the same tag logged the correct value.

Here the transaction group executed the second time. This time the trigger tag has the correct value, but the group was not triggered. I would have expected an execution here, because the trigger changed from null to 1365013573276. It looks like the value stored after the first execution for the 'on change' comparison is not the value that actually triggered the first execution.
If the subscribed values had changed between the first and the second execution, i would have lost the record completely. To prevent this, i have the execution rate of the group set to 3 times the minimal data change rate.

2

Have you tried setting your group to read mode to see if that helps? Also in your on change settings do you only have the one tag selected to monitor for change or are you monitoring all the tags for change?

3

Here are the group settings:

When using read mode instead of subscribed i gets even worse, because it logs inconsistent data (i restartet the driver module to simulate a connection loss):

INFO   | jvm 1    | 2013/04/18 19:01:17 | INFO  [ModuleManager                 ] [19:01:17,438]: Starting up module "siemens-drivers"...
INFO   | jvm 1    | 2013/04/18 19:01:19 | INFO  [test_log                      ] [19:01:19,010]: Execute value1:7452 value2: 7452
INFO   | jvm 1    | 2013/04/18 19:01:23 | INFO  [test_log                      ] [19:01:23,016]: Execute value1: value2: 7452
INFO   | jvm 1    | 2013/04/18 19:01:25 | DEBUG [DriverVariableNode            ] [19:01:25,389]: MonitoredItem@4000 added to DriverVariableNode@97364a[nodeId=[S7]DB220,W2,nodeClass=Variable,dataType=ns=0:i=5]. ItemCount = 1.
INFO   | jvm 1    | 2013/04/18 19:01:25 | TRACE [DriverVariableNode            ] [19:01:25,690]: Driver setting value value=7453, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Apr 18 19:01:25 CEST 2013, server=null on NodeId [S7]DB220,W2
INFO   | jvm 1    | 2013/04/18 19:01:25 | TRACE [DriverVariableNode            ] [19:01:25,690]: Driver setting value value=7453, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Apr 18 19:01:25 CEST 2013, server=null on NodeId [S7]DB220,W2

Here the group executes with value=null (Value 2 is the last read value)
INFO   | jvm 1    | 2013/04/18 19:01:27 | INFO  [test_log                      ] [19:01:27,011]: Execute value1: value2: 7452

Driver updates value to 7454
INFO   | jvm 1    | 2013/04/18 19:01:29 | TRACE [DriverVariableNode            ] [19:01:29,695]: Driver setting value value=7454, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Apr 18 19:01:29 CEST 2013, server=null on NodeId [S7]DB220,W2

Two seconds later the group excutes again, the subscribed trigger value is 7453, even if the subscription update should have been received.
Now the group will log 7453 as value and 7454 as the read value.
INFO   | jvm 1    | 2013/04/18 19:01:31 | INFO  [test_log                      ] [19:01:31,027]: Execute value1:7453 value2: 7452
INFO   | jvm 1    | 2013/04/18 19:01:31 | TRACE [DriverVariableNode            ] [19:01:31,027]: Driver setting value value=7454, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Apr 18 19:01:31 CEST 2013, server=null on NodeId [S7]DB220,W4
INFO   | jvm 1    | 2013/04/18 19:01:31 | INFO  [test_log                      ] [19:01:31,027]: Trigger value: 7453

I think this is a different issue than what was described in my first post.
Generally i think it’s impossible to get consistent data when you have to log the value that is used as a trigger together with other data. Even if i add another opc-tag with the same address as the trigger tag, the group does not read this tag on execution, but uses the value from the subscription.

4

Hi,

Are these SQLTags in the group, or direct opc items? In your first post, how are you logging those messages?

I can believe that there may be something going on, but with so many layers, we have to be clear about what we’re seeing where… especially so I can try to mock it up.

The path looks like this:
[Device] <–4 sec poll?–> [Driver] <-- 4 sec subscription --> [Monitored Item] <-- 4 sec subscription -->…network… [UA Client] -> [SQL Tag] <-- group rate --> [Execution Item]

The messages for DriverVariableNode are happening between the driver and the opc server. There are at least two timers happening in between, a 4 second subscription rate, and the group rate (also 4 seconds I’d imagine). If “read” mode is being triggered by “V”, but is storing “V+1”, it probably means that the value has already changed by the time the trigger is seen, but hasn’t propagated yet. I guess for now, let’s focus on just “subscription” mode.

To be clear about the first post, Msg0/intVal[0] and Msg0/intVal[1] both use the same opc path? And they’re in the same scan class? But when used in the group, sometimes the values are different?

Regards,

5

I finally have been able to reproduce this problem. It is very hypothetical, so im not sure anyone else will ever experience this (i really should stop running stress tests…).

It needs a transaction group with subscribed mode and a trigger item that is also referenced in a run always expression. In addition, this expression has to be added to the group after all other elements. Then, after a gateway restart, the group will about half the time store a record with null values and ignore the first real trigger.
In fact it was my logging item, that caused the problem in my test case:

runScript("system.util.logger('tcpDrv').info('Execute Timestamp:"+toLong({[~]_Timestamp})+"')")

The problem with 1 value being null and the others have correct values was partly caused by my driver implementation. Somehow i had the wrong idea that subscribed items would be published as soon as the driver writes a new value, hence i updated subscribed items exactly with the subscription rate. That caused an additional time delay and a very unfavourable timing with the subscription publishing.
Thanks for giving the path example in the above post, it allowed me to see my mistake.

I think there will always be a situation where a driver updates subscription items exactly at the same time the server publishes the subscribed tags. To prevent this, a driver would need a way to lock the publishing service somehow while it updates the tags.

6

Hi,

I can’t say for certain that this would fix what you’re seeing, but we’ve recently noticed that the trigger in the group, and the same item in the group were operating off of different subscriptions to the same tag, meaning that it was possible at times that the value used for the trigger might not be the same value stored for the tag (in certain rare cases where the value changes right when the group is executing). 7.5.9 and 7.6.2 fix this issue so that the value seen for the trigger is what will be stored, or used for other references in the group.

Regards,