Inconsistent data logged by transaction group

chi · November 2, 2017, 8:53pm

I am having an occasional problem with a transaction group that mixes data from two different subscription updates.
The data (a series of process data for a specific machined part) is received by a custom OPC-UA driver that makes sure that all subscribed values are updated consecutive and consistent. The driver also updates a special trigger tag only after all other data tags.
My expectation was that the transaction group would log the data that was received by the last subscription update before the change of the trigger value. This works ok most of the time, but every few hours (logging rate is about 1 part per second) data from two consecutive parts is mixed. I also tried read instead of sucscribe mode, but with this setting the problem gets worse.

The following log shows an example from a test system running Ignition7.8.5. Sorry if it gets a bit complicated .
At timestamp 20:15:58,658 the trigger tag _MessageCount is updated by the driver.
At 20:15:58,678 the transaction group evaluates the trigger but still sees the old value
At 20:15:58,857 the ua client seems to receive the updated values
At 20:15:58,881 the transaction group evaluates the trigger with a new value. At this point i expected the value -6526 to be stored to the database for all tags. In this case, one of the values in the database contained the previous value -6527.

INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,657]: Subscription updating tag DATEN1/_Timestamp Value:value=1509650158447, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=null
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/_MessageCount Value:value=55802, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=null
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Daten1 Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[24] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[22] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[21] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[7] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[20] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[42] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[41] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[40] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[6] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[3] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[4] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[1] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[2] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Array1[0] Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/Daten2 Value:value=-6526, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=Thu Nov 02 12:28:20 CET 2017
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/_Timestamp Value:value=1509650158447, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=null
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Subscription                  ] [20:15:58,658]: Subscription updating tag DATEN1/_MessageCount Value:value=55802, status=StatusCode[Severity=Good, Subcode=NotSpecified], source=Thu Nov 02 20:15:58 CET 2017, server=null
INFO   | jvm 1    | 2017/11/02 20:15:58 | INFO  [Daten2                        ] [20:15:58,662]: Trigger did not evaluate - source item currently has bad quality [[0, Unknown, Thu Nov 02 12:28:20 CET 2017]].
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [Daten1                        ] [20:15:58,678]: Trigger evaluated. Value: [55801, Good, Thu Nov 02 20:15:58 CET 2017], Active evaluation: false, Return value: false, First exec cancellation: false
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [Daten1                        ] [20:15:58,768]: Historical forward transaction completed successfully.
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [OpcUaSubscriptionManager      ] [20:15:58,856]: Received PublishResponse, sequenceNumber=55858
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [OpcUaSubscriptionManager      ] [20:15:58,856]: Sending PublishRequest, requestHandle=67415, acknowledgements=[id=3/seq=55856, id=3/seq=55857]
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [OpcUaSubscriptionManager      ] [20:15:58,856]: onPublishComplete() response for subscriptionId=3
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [OpcUaSubscriptionManager      ] [20:15:58,856]: [id=3] PublishResponse sequence=55858, available sequences=[id=3/seq=55857, id=3/seq=55858]
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [OpcUaSubscriptionManager      ] [20:15:58,857]: onNotificationMessage(), subscriptionId=3, sequenceNumber=55858, publishTime=DateTime{utcTime=131541237588560000, javaDate=Thu Nov 02 20:15:58 CET 2017}
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [OpcUaSubscriptionManager      ] [20:15:58,857]: Received 18 MonitoredItemNotifications
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=31, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=32, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=33, value=DataValue{value=Variant{value=55802}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237586530000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=34, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=35, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=36, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=19, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=20, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=21, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=22, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=23, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=24, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=25, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=26, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [OpcUaSubscriptionManager      ] [20:15:58,857]: MonitoredItemNotification: clientHandle=27, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [+SubscriptionManager          ] [20:15:58,880]: Notify global listeners of tag change: com.inductiveautomation.ignition.common.sqltags.model.event.TagChangeEvent@1aed18[tagPath=[__GROUP__]_MessageCount,prop=Value,indexes=<null>]
INFO   | jvm 1    | 2017/11/02 20:15:58 | TRACE [Daten1                        ] [20:15:58,881]: Trigger received subscription update: [55802, Good, Thu Nov 02 20:15:58 CET 2017]
INFO   | jvm 1    | 2017/11/02 20:15:58 | DEBUG [Daten1                        ] [20:15:58,881]: Trigger evaluated. Value: [55802, Good, Thu Nov 02 20:15:58 CET 2017], Active evaluation: true, Return value: true, First exec cancellation: false

Can somebody from IA please explain the internal timings of a triggered transaction group with OPC-UA subscriptions? Or maybe someone has a tip or a how to for logging consistent data from an OPC-UA server?

pturmel · November 2, 2017, 9:28pm

Use the “Read” OPC mode in your transaction. Then the transaction manager will only subscribe to the trigger OPC item, and will issue a bulk read for the other items when the trigger is satisfied. Your driver cannot control the order of execution of subscribed data items, so it must not subscribe to items that can change with the trigger. You can subscribe to items that you know would change before the trigger, but that is hard to guarantee.

chi · November 2, 2017, 9:52pm

Thank you for your answer. As i have written above, using read mode is even worse. There is a load depending delay between the trigger and the read, so this way i am logging old data more often. I have thought about a change in the driver to delay value updates until a read command has been issued by the client, but i really want to avoid that.
Another option would be using the transaction groups handshake option together with a read, but i still have to find a way to prevent deadlocks without risking a data loss.

Your driver cannot control the order of execution of subscribed data items

I am not sure that i understand this statement. My driver can control the order in which it sends updates to the server. But i agree that the server or the client changes this order, that can be seen in the log.

My problem is, that according to the logs everything should be working, but it doesn't. I would expect the transaction group to take a snapshot of the subscribed data when the trigger is evaluated. There would still be the problem that the trigger item might not be updated by the ua server in the order the updates where received, but that may be handled by a simple delay.
I have the suspicion that the trigger evaluation is not synchronized with the subscription rate, or even worse that the trigger starts the data handling in a delayed runnable. That's why i asked for the internal timings.

Colby.Clegg · November 2, 2017, 10:39pm

Hi,

In pretty simple setups, Phil’s answer is pretty much always the correct answer. I’m curious as to how the problem could get worse with read mode- unless you’ve also set all of the items to be triggers in the “only evaluate when values have changed” (which defaults to “all tags”). Any potential trigger tag is subscribed, so this setting effectively negates the read mode setting.

As for timing, the group runs on the timer, and at that time it evaluates the trigger, and then, if active, “latches” in the most recent values from OPC. To be clear- these values are direct OPC items in the group (settings for opc path and so on defined in the group), and not references to tags defined in the tag provider, right?

Just for a little more information about values and timing, try looking for the logger “TransactionGroups.Evaluation.OneWayComparison” (or TwoWayComparison, if the group or item is bi-directional) and set it to trace. That will print out exactly which two values are being compared when the group executes- we can see if it appears that a set of them simply haven’t been updated yet.

chi · November 3, 2017, 10:29am

Hi,

the problem with read mode is that there is a delay between the trigger and the read. During this delay, the plc might have sent new data, so the driver answers the read with this new data (or mixed data of two parts when the read happens during the plc update).
On the production system, there are about 30 groups which receive updates every 500ms in worst case. When using the read mode, i have missing or bad data about 10 times more often than in subscribed mode. Maybe more cpu cores would help here, but i really like to have a system that is safe by design.

Anyway, Phil’s answer helped me to find the problem when analyzing the logs again. The key is the sequence of events where the trigger is evaluated right in the middle of the subscription update. As you wrote, the group “latches” the values at this point, so the new values after the trigger evaluation are not logged.

I had the wrong idea, that subscribed items would arrive in the same order they were sent by the driver, so that the data items would always arrive before the trigger. But that seems not to be the case, so i will have to find another solution for this. Maybe delay the trigger update in the driver or use a handshake.

Thanks for your input!

[20:15:58,857]: MonitoredItemNotification: clientHandle=27, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}
[20:15:58,880]: Notify global listeners of tag change: com.inductiveautomation.ignition.common.sqltags.model.event.TagChangeEvent@1aed18[tagPath=[__GROUP__]_MessageCount,prop=Value,indexes=<null>]
[20:15:58,881]: Trigger received subscription update: [55802, Good, Thu Nov 02 20:15:58 CET 2017]
[20:15:58,881]: Trigger evaluated. Value: [55802, Good, Thu Nov 02 20:15:58 CET 2017], Active evaluation: true, Return value: true, First exec cancellation: false
[20:15:58,883]: MonitoredItemNotification: clientHandle=28, value=DataValue{value=Variant{value=-6526}, status=StatusCode{name=Good, value=0x00000000, quality=good}, sourceTime=DateTime{utcTime=131541237584470000, javaDate=Thu Nov 02 20:15:58 CET 2017}, serverTime=DateTime{utcTime=131541237586570000, javaDate=Thu Nov 02 20:15:58 CET 2017}}

pturmel · November 3, 2017, 2:29pm

Glad you found it. FWIW, I designed my Ethernet/IP driver to be as compatible as possible with the “read after subscribed trigger” approach once I understood how all of this stuff worked together. The key to success in my case is that the read items are actually present in the driver itself – no comms traffic is required to read them – and entire packets of incoming data are applied in the driver before any affected subscription items are notified. This approach doesn’t prevent a random OPC read from getting inconsistent data, but it ensures that triggered reads are consistent with with the subscribed trigger.
I haven’t traced it, but I would expect the thread executing the driver’s call to item.setValue() on the trigger produces the transaction group’s call to readItems() before the item.setValue() call returns.
Keep in mind that this approach can fail if the execution of the transaction group can get backlogged on the database or store-and-forward side. My driver addresses this case by offering packet arrival scripting events that snapshot the packet data before placing the events on the queue of Runnables.