Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
NoTuxNoBux opened this issue Mar 19, 2024 · 2 comments
Closed

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

NoTuxNoBux opened this issue Mar 19, 2024 · 2 comments
Labels
bug Something isn't working
Milestone
2.9.9

Comments

@NoTuxNoBux
Copy link

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 marcschier added the bug Something isn't working label Mar 19, 2024
@marcschier marcschier mentioned this issue Apr 19, 2024
Closed
@marcschier marcschier added this to the 2.9.9 milestone Jun 3, 2024
@marcschier
Copy link
Collaborator

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
Copy link
Collaborator

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
2.9.9
Development

No branches or pull requests
2 participants
@marcschier @NoTuxNoBux