Device starts sampling and publishing at slower intervals after reconnection in 2.9.0 (preview)

NoTuxNoBux commented 1 year ago

Describe the bug On 2.9.0 (preview), I'm seeing strange behaviour where I ask a sample and publishing interval of 50 ms for multiple properties, and after a reconnection to the server, this gets somehow changed to a slower interval. The initial rate (after publisher start-up) is always correct.

To Reproduce Steps to reproduce the behavior:

Add a few property subscriptions with sampling and publishing intervals of 50 ms.
Connect to the server, observe data coming through at the requested rate.
Let the server reboot or go offline and the publisher pick this up.
Put the server back online and the publisher reconnect.
Observe (most times) that updates come in at a slower rate than 50 ms.

Expected behavior Updates come in at 50 ms.

Additional context I'm not sure if this is the OPC Publisher that is at fault - it could also be a weird OPC UA server, but if not, hopefully I'll get an idea as to how this can happen.

Other things I've verified:

Use 0 as publication interval; the server always negotiates 4, so 50 is certainly not too much for it.
Publisher still reports "50/50" as requested and expected publishing interval when the problem occurs.
The rate at which MessageTriggerMessageReceived is triggered is also slower, so it happens earlier in the publisher (or is caused by the server).
The amount it becomes slower is random; usually updates suddenly start getting published after 5 seconds, sometimes 300 ms, sometimes 1 second, and so on.
If just the publishing interval became wrong, I'd expect multiple values to show up in the data as the sampling interval is still low, but that's not the case; I still get only one sample per publication, which implies both values got slower somehow.
There are no other properties in published-nodes.json that have different publishing intervals that may mistakenly get used; they are all 50 ms.
Restarting the publisher fixes it.
No noticeable errors or warnings are reported, except DataChange for monitored item 107 subscription '50'/'opc.tcp://THE_SERVER:853/FOO' has unexpected sequenceNumber 1 missing 2, 3, 4, 5, 6, 7, 8, 9, 10, 11 which were already received, probably because the server starts over with 1 after a reboot and the publisher tries to maintain the previous state on reconnection?

Is there some timing logic somewhere that may get confused in the OPC Publisher? I couldn't find any, but I may have missed it.

I cannot test with a stable version because I'm using the 2.9.0 (preview) with a custom SignalR back end. This custom back end is similar to the new MQTT one and I didn't touch any of the logic related to data subscriptions; as mentioned the problem also seems to happen before the back end is involved.

NoTuxNoBux commented 1 year ago

Doing some more testing for this, I just encountered this problem happening mid-runtime. The publisher reconnected when the server came back and then this happened:

Got a bunch of messages with the expected publishing interval; timestamps of messages are mostly on the same second, which is accurate.
... Changing monitoring mode from Disabled to Reporting and some other logging happening.
More messages come in, but now they are all spaced apart at least a second (and I also visibly saw this happening).

The publishing interval is still reported as being 50/50, as expected.

Can the change of monitoring mode somehow be affecting this?

Logs

[2023-04-24 13:19:16.097 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.098 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 69-04/24/2023 13:19:16 
[2023-04-24 13:19:16.099 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.118 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.196 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.197 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 70-04/24/2023 13:19:16 
[2023-04-24 13:19:16.199 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.222 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.300 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.302 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 71-04/24/2023 13:19:16 
[2023-04-24 13:19:16.303 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.326 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.392 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.392 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 72-04/24/2023 13:19:16 
[2023-04-24 13:19:16.392 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.429 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.491 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.492 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 73-04/24/2023 13:19:16 
[2023-04-24 13:19:16.493 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.534 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.553 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.555 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 74-04/24/2023 13:19:16 
[2023-04-24 13:19:16.555 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.586 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 522 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.647 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.648 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.649 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 75-04/24/2023 13:19:16 
[2023-04-24 13:19:16.691 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.746 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.747 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.747 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 76-04/24/2023 13:19:16 
[2023-04-24 13:19:16.794 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:16.813 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:16.814 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 77-04/24/2023 13:19:16 
[2023-04-24 13:19:16.816 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:16.846 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 318 bytes to IoTDataUpdate 
[2023-04-24 13:19:17.652 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:17.652 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 78-04/24/2023 13:19:17 
[2023-04-24 13:19:17.652 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:17.677 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate 
[2023-04-24 13:19:18.434 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:19.651 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive  
[2023-04-24 13:19:19.651 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Refreshing session 'opc.tcp://THE_SERVER/FOO' 
[2023-04-24 13:19:19.656 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:19.656 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 79-04/24/2023 13:19:19 
[2023-04-24 13:19:19.657 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:19.667 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubesInGripper:bTubesInGripper[0]' with server id 1395299280 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.668 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[0]' with server id 1395299281 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.669 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[1]' with server id 1395299282 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.670 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[2]' with server id 1395299283 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.671 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[3]' with server id 1395299284 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.672 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[4]' with server id 1395299285 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.673 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[5]' with server id 1395299286 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.674 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[6]' with server id 1395299287 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.675 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[7]' with server id 1395299288 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.675 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[8]' with server id 1395299289 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.676 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState1:bTubeState1[9]' with server id 1395299290 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.676 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[0]' with server id 1395299291 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.677 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[1]' with server id 1395299292 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.677 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[2]' with server id 1395299293 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.678 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[3]' with server id 1395299294 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.678 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[4]' with server id 1395299295 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.679 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[5]' with server id 1395299296 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.679 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[6]' with server id 1395299297 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.680 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[7]' with server id 1395299298 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.680 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[8]' with server id 1395299299 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.681 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState2:bTubeState2[9]' with server id 1395299300 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.681 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[0]' with server id 1395299301 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.682 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[1]' with server id 1395299302 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.682 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[2]' with server id 1395299303 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.683 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[3]' with server id 1395299304 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.683 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[4]' with server id 1395299305 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.684 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[5]' with server id 1395299306 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.684 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[6]' with server id 1395299307 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.685 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[7]' with server id 1395299308 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.685 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[8]' with server id 1395299309 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.686 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:bool:bTubeState3:bTubeState3[9]' with server id 1395299310 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.686 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'ns=1;s=:Robot:Applications:IO:string:sJoints:sJoints[0]' with server id 1395299311 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.687 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.MonitoredItemWrapper] Item 'i=2258' with server id 1395299312 - created: Changing monitoring mode from Disabled to Reporting 
[2023-04-24 13:19:19.688 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Refreshing done for session 'opc.tcp://THE_SERVER/FOO' 
[2023-04-24 13:19:19.705 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate 
[2023-04-24 13:19:21.550 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:21.551 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 80-04/24/2023 13:19:21 
[2023-04-24 13:19:21.552 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:21.579 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate 
[2023-04-24 13:19:22.496 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:22.496 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 81-04/24/2023 13:19:22 
[2023-04-24 13:19:22.496 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:22.515 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate 
[2023-04-24 13:19:23.655 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:23.655 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 82-04/24/2023 13:19:23 
[2023-04-24 13:19:23.655 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:23.659 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate 
[2023-04-24 13:19:24.403 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker StandalonePublisher_0 sending heartbeat... 
[2023-04-24 13:19:24.403 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.StandaloneJobOrchestrator] Worker update with Keep instruction for job null. 
[2023-04-24 13:19:25.641 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:25.641 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 83-04/24/2023 13:19:25 
[2023-04-24 13:19:25.641 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:25.686 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate 
[2023-04-24 13:19:26.561 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:26.562 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 84-04/24/2023 13:19:26 
[2023-04-24 13:19:26.562 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:26.571 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 911 bytes to IoTDataUpdate 
[2023-04-24 13:19:27.565 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:27.565 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 85-04/24/2023 13:19:27 
[2023-04-24 13:19:27.565 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:27.610 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate 
[2023-04-24 13:19:28.436 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:28.551 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Keepalive received from session 'opc.tcp://THE_SERVER/FOO': server current state: Running 
[2023-04-24 13:19:28.551 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Notification for session 'opc.tcp://THE_SERVER/FOO', subscription '50' - sequence# 86-04/24/2023 13:19:28 
[2023-04-24 13:19:28.552 DBG Microsoft.Azure.IIoT.OpcUa.Edge.Publisher.Engine.DataFlowProcessingEngine] Message trigger for opc.tcp://THE_SERVER/FOO received message with sequenceNumber 0 
[2023-04-24 13:19:28.599 DBG Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Publishing 205 bytes to IoTDataUpdate

NoTuxNoBux commented 1 year ago

I'm now wondering if this is somehow related to #1890: the properties involved are all 'application properties' on the OPC UA server; the server is a robot that has certain system properties that are always available, and application properties that only are available once a specific program is loaded.

I also subscribe to the system time (system property) in the publisher, which samples every second (and also publishes every 50 ms along with the rest whenever it is sampled), but - even when this problem occurs -, it doesn't seem to experience this specific issue.

I'm still not sure who's at fault here - the server or the client - but it may be linked to certain application properties being reloaded on the server and the publisher getting confused somehow because of this:

Robot starts up, system properties are available.
Publisher connects, subscribes to all system properties, application properties fail due to application still starting.
Robot starts application.
Publisher updates its subscriptions once properties become available, reporting mode changes.

Perhaps it's some sort of race condition.

marcschier commented 1 year ago

Hi @NoTuxNoBux, this looks like an interesting project :-). But first off, I cannot really see anything wrong in the logs. How OPC UA subscriptions work is that when the subscription is created all values are being sent. After that only value changes are sent. So even if you sample the changes every 50 ms, if nothing changed from previous sample, then nothing is sent. The publishing interval decides the timing of when data goes over the wire, and if there is nothing ready to package into a publish response, nothing is returned. Setting publishing interval to higher means more values are packaged, but latency increases. So if this does not explain what you are seeing, my suggestion is to take a closer look at the server here (even though I cannot fully exclude publisher, but the area we are talking about has been very well in use over the past years and has not changed in preview 1). What server are you connecting to?

Out of curiosity, you mention signalr backend, are you looking at pumping data through signalR from MQTT or directly from OPC Publisher?

NoTuxNoBux commented 1 year ago

The publishing interval decides the timing of when data goes over the wire, and if there is nothing ready to package into a publish response

Thanks for the response, you mentioning this helps - the troublesome property is an 'application' property on the OPC UA server, so perhaps it's not the publishing interval timing that's incorrect, perhaps the property (due to a bug on the server application side) is simply not being changed at the same interval any more when this problem occurs.

I'm going to see if I can verify if this is what is happening and come back to this issue once I do.

1). What server are you connecting to?

It's the OPC UA server on a Stäubli CS9 box for a TX2-60L mechanical robot arm. We're connecting over OPC UA TCP with both authentication (username and password) and encryption active (which works great :+1:).

Out of curiosity, you mention signalr backend, are you looking at pumping data through signalR from MQTT or directly from OPC Publisher?

The latter - we had problems with the Azure IoT Hub resulting in sporadic random delays of several seconds or more (apparently a known issue because it is shared tenant, so there's not really much Microsoft support can do about it), and we have a minor subset of the properties we are interested in that need to be sent at a more consistent pace and with lower latency than most others.

We were already using SignalR to push updates to client applications, and saw 2.9.0 preview has multiple back ends (IoT Hub and MQTT), so building a SignalR back end based on the new MQTT one seemed like a good approach - we didn't choose MQTT directly because - If I understood correctly - it would require introducing an additional intermediary (queuing server/implementation) that can in turn introduce make latency more erratic again.

(In case you're curious, the SignalR part seems to be working really well so far and was relatively straightforward to get this in the codebase.)

NoTuxNoBux commented 1 year ago

I'm going to see if I can verify if this is what is happening and come back to this issue once I do.

I'm not 100% sure yet, but it's becoming more and more likely that the server is at fault here. I can also reproduce this issue with other tooling such as UA Expert; the publishing interval remains the same, but the update rate of the property itself tanks, so it's not sending any more updates because the property simply wasn't updated, not because the publishing interval is incorrect.

Since it's also reproducible with other tools, I think this can be closed as not a bug in OPC Publisher. I will reopen in case new information appears that implicates the publisher again for some reason.

Thanks for the valuable tip and assistance!

NoTuxNoBux commented 1 year ago

I just wanted to cycle back and confirm that it was indeed a server issue; turns out the server in question has a quirk where it can only publish at a single interval, so if multiple independent (yes, that's right) clients connect (doesn't matter if it's an OPC Publisher or not), even for separate properties, and use different publication intervals, only the last one is used - the first one then gets updates at a slower rate without it being renegotiated in OPC UA; the property just updates at at a slower pace.

The sample rate can still vary just fine for these properties, weirdly enough, it's only about the publishing interval in this server - the workaround/fix for me was thus to set all publication intervals in all clients to the lowest value I need for any one property; the other ones still won't be included if they don't change as their sample intervals are higher.

Might be useful to know for others experiencing similar issues.

Azure / Industrial-IoT

Device starts sampling and publishing at slower intervals after reconnection in 2.9.0 (preview) #1969

Logs