Sending commands over OPC Twin takes long the first time

[NoTuxNoBux]

Describe the bug
When sending commands through the OPC Twin, we're noticing delays from 8 to 30 seconds before the first command is delivered after connection was previously lost.

To Reproduce

1. Register OPC Twin with a server that supports commands.
2. Send a command the first time.
3. Reboot the OPC UA server.
4. Wait long enough for the OPC Twin to lose its connection (at least ~60 seconds, I believe).
5. Send a command through the OPC Twin.
6. Notice how the twin starts reconnecting because the previous connection went bad, after which it sends the command, but the authentication flow can take up to half a minute on slower servers.

Expected behavior
I'm not sure; perhaps (a flag to) make the OPC Twin reconnect as soon as possible instead of on demand.

Additional context
As part of a demo application, we send a command that reboots the device running the OPC UA server. After the device comes back, the OPC Publisher reconnect ASAP to send back data, but it appears the OPC Twin does not follow this behaviour. Instead, it only seems to reconnect 'on demand' when the first command is passed to it afterwards, which makes sending the command incur a rather large delay.

After this happened, sending the next command (when not rebooting) is much faster, likely because the existing connection is intact.

We are sending commands to the OPC Twin through the IoT Hub API, in case it is relevant.

OPC Twin version 2.8.3.

[NoTuxNoBux]

Wondering if this might be fixed with OPC Twin 2.8.4 (I am on 2.8.3) because of #1910.

(I'll test with latest 2.8.6 and report back.)

[NoTuxNoBux]

Tested with 2.8.6, but the behaviour is similar: according to the logs, the twin does now notice after a minute or so that it lost connection:

Force reconnect reason=BadConnectionClosed 'Remote side closed connection'

But then it doesn't proceed to automatically reconnect until the first command is sent again, after which it goes through the connection and authentication flow.

[NoTuxNoBux]

Hmmm, I'm not sure if this is the OPC Twin at fault, but the last few weeks (the only thing that changed is the update to 2.8.6 from 2.8.3) the connection gets closed after about a minute or so after sending the last command.

[2023-06-16 13:58:49.521 INF OpcUa] ChannelId 76: in Closing state. 
[2023-06-16 13:58:50.522 WRN OpcUa] ChannelId 76: Force reconnect reason=BadConnectionClosed 'Remote side closed connection' 
[2023-06-16 13:58:50.522 INF OpcUa] ChannelId 76: in Closed state. 
[2023-06-16 13:58:50.523 INF OpcUa] ChannelId 76: CLIENTCHANNEL SOCKET CLOSED: 0300A612 

'Remote side' implies the twin isn't causing it, but as far as we know there has been no changes on the network or OPC UA server that could be causing it. Possibly a new regression?

I can't freely downgrade to test as our application is used by a customer, but I'll try to get some time allocated to test downgrading to 2.8.3.

[marcschier]

Please could you try with OPC Publisher 2.9.0-preview3? In 2.9 we support calling the API through IOT hub directly (we only support calling through the REST API in 2.8). The client handling in 2.9 was a complete rewrite and now uses a reference count mechanism to determine connect vs. disconnect. In addition it uses the official "reconnect handler" in the OPC UA stack, instead of the home grown different ones in 2.8 twin and publisher.

A configurable linger timeout allows you to keep active connections (sessions) "lingering" around for a configurable time (--cl) after reference count hits 0. That gives you a quick start with the next call within the timeout period. Also, should the configured IoT Hub request timeout expire (default 10 seconds) we cancel the call (e.g., in cases where the session cannot be connected and the calling thread has to wait).

[NoTuxNoBux]

I can confirm it doesn't happen in 2.8.3.

Please could you try with OPC Publisher 2.9.0-preview3?

I would like to, but I don't immediately find any upgrade notes (possibly because the documentation updates are pending as mentioned in the release notes).

Am I correct in assuming that, since opc-twin:2.9.0-preview3 doesn't exist, the twin been merged into the opc-publisher image? Secondly, we have two publishers running right now with different back-ends, if it is merged into the publisher, will they be conflicting when relaying commands passed on by the IoT Hub since the endpoint URL is only passed in EndpointApiModel (and not the IoT Hub module name)?

Assuming a 'yes' to the first question and keeping the second publisher on the old version for now, I immediately hit an exception on startup that seems to be due to configuration I'm not manually passing - but I could be wrong or missing some sort of migration:

[08:42:15.9048] info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
      => HTTP POST unix:///var/run/iotedge/workload.sock/modules/OPC-Publisher/genid/537955643018451501/decrypt?api-version=2021-12-07
      Start processing HTTP request POST unix:///var/run/iotedge/workload.sock/modules/OPC-Publisher/genid/537955643018451501/decrypt?api-version=2021-12-07
[08:42:15.9119] info: System.Net.Http.HttpClient.Default.ClientHandler[100]
      => HTTP POST unix:///var/run/iotedge/workload.sock/modules/OPC-Publisher/genid/537955643018451501/decrypt?api-version=2021-12-07
      Sending HTTP request POST unix:///var/run/iotedge/workload.sock/modules/OPC-Publisher/genid/537955643018451501/decrypt?api-version=2021-12-07
[08:42:15.9271] fail: Azure.IIoT.OpcUa.Publisher.Storage.PublishedNodesConverter[0]
      failed to convert the published nodes.
      System.NotSupportedException: The 'unix' scheme is not supported.
         at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.<SendAsync>g__Core|5_0(HttpRequestMessage request, CancellationToken cancellationToken)
         at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.<SendAsync>g__Core|5_0(HttpRequestMessage request, CancellationToken cancellationToken)
         at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
         at Microsoft.Azure.Devices.Edge.Util.Edged.Version20190130.GeneratedCode.HttpWorkloadClient.DecryptAsync(String api_version, String name, String genid, DecryptRequest payload, CancellationToken cancellationToken)
         at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientBase.ExecuteAsync[T](Func`1 func, String operation)
         at Microsoft.Azure.Devices.Edge.Util.Edged.Version20190130.WorkloadClient.HandleException(Exception ex, String operation)
         at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientBase.ExecuteAsync[T](Func`1 func, String operation)
         at Microsoft.Azure.Devices.Edge.Util.Edged.Version20190130.WorkloadClient.DecryptAsync(String initializationVector, String encryptedText)
         at Furly.Azure.IoT.Edge.Services.IoTEdgeWorkloadApi.DecryptAsync(String initializationVector, ReadOnlyMemory`1 ciphertext, CancellationToken ct)
         at Azure.IIoT.OpcUa.Publisher.Storage.PublishedNodesConverter.ToUserNamePasswordCredentialAsync(PublishedNodesEntryModel entry) in /home/vsts/work/1/s/src/Azure.IIoT.OpcUa.Publisher/src/Storage/PublishedNodesConverter.cs:line 700
         at Azure.IIoT.OpcUa.Publisher.Storage.PublishedNodesConverter.ToConnectionModel(PublishedNodesEntryModel model) in /home/vsts/work/1/s/src/Azure.IIoT.OpcUa.Publisher/src/Storage/PublishedNodesConverter.cs:line 448
         at System.Linq.Lookup`2.Create[TSource](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)
         at System.Linq.GroupedEnumerable`3.ToList()
         at Azure.IIoT.OpcUa.Publisher.Storage.PublishedNodesConverter.ToWriterGroups(IEnumerable`1 items, PublisherOptions configuration) in /home/vsts/work/1/s/src/Azure.IIoT.OpcUa.Publisher/src/Storage/PublishedNodesConverter.cs:line 262

[marcschier]

Cool, you found a bug :-). (#1998). Looks like you have a published nodes configuration file with encrypted username and password fields in there. Is this the case?

You are correct, there is no opc twin and opc discovery module in 2.9, everything is merged into 2.9 opc publisher.

With device methods in IoT Hub you are directing the method call request at the module you want the method to execute in, so the module name is passed to IOT hub. This should allow you to distinguish both publishers and then just pass the endpoint url.

[NoTuxNoBux]

Cool, you found a bug :-). (#1998). Looks like you have a published nodes configuration file with encrypted username and password fields in there. Is this the case?

The password in the configuration file itself is in plain text, but maybe UseSecurity is doing something else behind the scenes except making the connection use SSL?

"UseSecurity": true,
"OpcAuthenticationMode": "UsernamePassword",
"OpcAuthenticationUsername": "foo",
"OpcAuthenticationPassword": "bar",

You are correct, there is no opc twin and opc discovery module in 2.9, everything is merged into 2.9 opc publisher.

👍

With device methods in IoT Hub you are directing the method call request at the module you want the method to execute in, so the module name is passed to IOT hub. This should allow you to distinguish both publishers and then just pass the endpoint url.

Yep, that makes sense, I forgot that I was already passing that in 👍 .