Azure / Industrial-IoT

Azure Industrial IoT Platform
MIT License
523 stars 214 forks source link

Error during command sending results in publisher getting in erroneous state #2203

Closed NoTuxNoBux closed 3 months ago

NoTuxNoBux commented 6 months ago

Describe the bug Sending a command to an OPC UA server the publisher 2.9.4 is connected to, and the connection unexpectedly dropping (the machine stopped responding) resulted in the publisher getting into a permanent exception state where it spams the same exception every time.

This has the same result as and might be related to #2189, but is caused in a different way.

To Reproduce I can't always reproduce this in the exact same fashion, but this is what happened:

  1. Ensure OPC UA server is up and running.
  2. Get the publisher connected to it.
  3. Send a command over the REST API to the OPC UA server.
  4. Disconnect the OPC UA server whilst the command is executing.

Expected behavior The publisher recovers and treats the connection to the server as disconnected, trying to reconnect (and not throw exceptions).

Additional context Logs of what happened when I sent the command (beginning), resulting in the exceptions (end):

Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:19.6866] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Request starting HTTP/1.1 POST https://REMOVED-IP-OF-HOST:8080/v2/write - application/json;+charset=utf-8 314
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:19.8827] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Executing endpoint 'Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)'
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:19.9227] info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[102]
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:19 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Route matched with {action = "ValueWrite", controller = "General"}. Executing controller action with signature System.Threading.Tasks.Task`1[Azure.IIoT.OpcUa.Publisher.Models.ValueWriteResponseModel] ValueWriteAsync(Azure.IIoT.OpcUa.Publisher.Models.RequestEnvelope`1[Azure.IIoT.OpcUa.Publisher.Models.ValueWriteRequestModel], System.Threading.CancellationToken) on controller Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController (Azure.IIoT.OpcUa.Publisher.Module).
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.0927] info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[101]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Executing action method Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module) - Validation state: Valid
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.0982] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClientManager[0]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       New client opc.tcp://robot.beacon.internal:4880/Staubli_69B8C685 [state:Disconnected|refs:0] created.
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.0991] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Session opc.tcp://robot.beacon.internal:4880/Staubli_69B8C685 with opc.tcp://robot.beacon.internal:4880/Staubli changed from Disconnected to Connecting
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.0997] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Connecting Client opc.tcp://robot.beacon.internal:4880/Staubli_69B8C685 [state:Connecting|refs:1] to opc.tcp://robot.beacon.internal:4880/Staubli...
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.9691] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Selecting endpoint opc.tcp://robot.beacon.internal:4880/Staubli with SecurityMode SignAndEncrypt and any SecurityPolicyUri from:
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:             #001: opc.tcp://robot.beacon.internal:4880/Staubli|None [http://opcfoundation.org/UA/SecurityPolicy#None]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:             #007: opc.tcp://robot.beacon.internal:4880/Staubli|Sign [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:             #012: opc.tcp://robot.beacon.internal:4880/Staubli|Sign [http://opcfoundation.org/UA/SecurityPolicy#Basic256]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:             #052: opc.tcp://robot.beacon.internal:4880/Staubli|Sign [http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:             #008: opc.tcp://robot.beacon.internal:4880/Staubli|SignAndEncrypt [http://opcfoundation.org/UA/SecurityPolicy#Basic128Rsa15]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:             #013: opc.tcp://robot.beacon.internal:4880/Staubli|SignAndEncrypt [http://opcfoundation.org/UA/SecurityPolicy#Basic256]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:             #053: opc.tcp://robot.beacon.internal:4880/Staubli|SignAndEncrypt [http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.9710] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Endpoint #053: opc.tcp://robot.beacon.internal:4880/Staubli|SignAndEncrypt [http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256] selected!
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.9885] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       #1: Creating session opc.tcp://robot.beacon.internal:4880/Staubli_69B8C685 with endpoint opc.tcp://robot.beacon.internal:4880/Staubli...
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:20.9940] warn: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClientManager[0]
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:20 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Accepting untrusted peer certificate 2EA65FD9AAD516A204D8587384832C7DEB59D538, 'L=Faverges, CN=cs9, OU=Staubli, O=Staubli Faverges SA, S=France, C=FR' due to AutoAccept(UntrustedCertificates) set!
Mar 19 11:40:23 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:23.7892] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:23 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       #1/100: Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 is missing keep alive.
Mar 19 11:40:24 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:24.0882] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:24 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:24 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:24.6381] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:24 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:25 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:25.1891] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:25 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:25 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:25.7408] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:25 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:26 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:26.2874] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:26 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:26 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:26.8398] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:26 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:27 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:27.3886] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:27 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:27 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:27.9402] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:27 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:28 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:28.4887] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:28 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:29 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:29.0406] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:29 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:29 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:29.5877] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:29 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:30 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:30.1403] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:30 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:30 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:30.6872] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:30 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:31 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:31.2397] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:31 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:31 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:31.7897] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:31 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.3388] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4714] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #683, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4765] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Reconnecting session opc.tcp://robot.beacon.internal:4880/Staubli_0E4A11C9_<<UnknownWriterGroup>> due to error BadSecureChannelClosed 'BadSecureChannelClosed'...
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4786] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #679, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4799] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Session opc.tcp://robot.beacon.internal:4880/Staubli_0E4A11C9_<<UnknownWriterGroup>> with opc.tcp://robot.beacon.internal:4880/Staubli changed from Ready to Connecting
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4832] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #680, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4800] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #684, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4904] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #681, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4908] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #682, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4914] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Unexpected keep alive error occurred: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4915] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #687, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4917] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #688, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4917] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #686, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4918] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #689, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4919] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #690, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4919] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #691, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4920] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #692, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4920] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #693, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4921] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #694, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4921] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #695, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4923] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #696, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4923] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #685, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4925] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #697, Reconnecting=False, Error: BadSecureChannelClosed
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4828] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSession[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Session  disposed.
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4944] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Session opc.tcp://robot.beacon.internal:4880/Staubli_69B8C685 with opc.tcp://robot.beacon.internal:4880/Staubli changed from Connecting to NoTrust
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.4950] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaClient[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       => SpanId:5e980f0d671fc53b, TraceId:0f7feb9e39c9502e37f9d58b58cccc65, ParentId:657af900a3f5d520 => ConnectionId:0HN2800MLJBLV => RequestPath:/v2/write RequestId:0HN2800MLJBLV:00000001 => Azure.IIoT.OpcUa.Publisher.Module.Controllers.GeneralController.ValueWriteAsync (Azure.IIoT.OpcUa.Publisher.Module)
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       #2: Failed to connect opc.tcp://robot.beacon.internal:4880/Staubli_69B8C685 [state:NoTrust|refs:1] to opc.tcp://robot.beacon.internal:4880/Staubli: BadSecureChannelClosed...
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.8877] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.8987] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Publish #698, Reconnecting=False, Error: Error establishing a connection: BadNotConnected
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:32.8995] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       PUBLISH #698 - Unhandled error BadNotConnected during Publish.
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Opc.Ua.ServiceResultException: Error establishing a connection: BadNotConnected
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Bindings.ChannelAsyncOperation`1.End(Int32 timeout, Boolean throwOnError)
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Bindings.UaSCUaBinaryClientChannel.EndSendRequest(IAsyncResult result)
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.SessionClient.EndPublish(IAsyncResult result, UInt32& subscriptionId, UInt32Collection& availableSequenceNumbers, Boolean& moreNotifications, NotificationMessage& notificationMessage, StatusCodeCollection& results, DiagnosticInfoCollection& diagnosticInfos)
Mar 19 11:40:32 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Client.Session.OnPublishComplete(IAsyncResult result)
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:33.0020] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Unexpected error sending publish request.
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Opc.Ua.ServiceResultException: BadConnectionClosed
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Bindings.UaSCUaBinaryClientChannel.BeginSendRequest(IServiceRequest request, Int32 timeout, AsyncCallback callback, Object state)
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Client.Session.BeginPublish(Int32 timeout)
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:33.4401] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:33.4408] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Unexpected error sending publish request.
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Opc.Ua.ServiceResultException: BadConnectionClosed
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Bindings.UaSCUaBinaryClientChannel.BeginSendRequest(IServiceRequest request, Int32 timeout, AsyncCallback callback, Object state)
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Client.Session.BeginPublish(Int32 timeout)
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:33.9901] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:33.9903] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Unexpected error sending publish request.
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Opc.Ua.ServiceResultException: BadConnectionClosed
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Bindings.UaSCUaBinaryClientChannel.BeginSendRequest(IServiceRequest request, Int32 timeout, AsyncCallback callback, Object state)
Mar 19 11:40:33 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Client.Session.BeginPublish(Int32 timeout)
Mar 19 11:40:34 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:34.5388] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
Mar 19 11:40:34 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Subscription <<UnknownDataSet>>_($e1822db470e60d090affd0956d743cb0e7cdf113):2324744767 STOPPED!
Mar 19 11:40:34 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:34.5391] fail: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaStack[0]
Mar 19 11:40:34 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Unexpected error sending publish request.
Mar 19 11:40:34 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:       Opc.Ua.ServiceResultException: BadConnectionClosed
Mar 19 11:40:34 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Bindings.UaSCUaBinaryClientChannel.BeginSendRequest(IServiceRequest request, Int32 timeout, AsyncCallback callback, Object state)
Mar 19 11:40:34 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]:          at Opc.Ua.Client.Session.BeginPublish(Int32 timeout)
Mar 19 11:40:35 Azure-IoT-Edge-Ubuntu-Host 6081cab9195c[770]: [24-03-19 10:40:35.0872] info: Azure.IIoT.OpcUa.Publisher.Stack.Services.OpcUaSubscription[0]
marcschier commented 3 months ago

Unfortunately the OPC UA stack logs the exception, which actually are just indications of the service result status of the last publish request (since subscriptions are active). I cannot disable the error logs from the stack, and that unfortunately includes the exception stack trace.

The problem with MQTT transport is that the MQTT RPC call hangs forever on the reconnect (#2213), but the HTTP call should actually respond with error (at least after a while). Is this the case @NoTuxNoBux ?

marcschier commented 3 months ago

On hung calls, see resolution on the linked issue. No way I can work around the publish exception logs though.