Writing on a node fails after a while

[Raumsog]

Hello,

I'm currently using Milo sdk-client v0.4.0 to communicate with many OPC UA servers (one client is created for each server and managed independently).

A simple lifesign mechanism is made between the client & the server to make sure they see each other : every minute, the client writes 120 on this node, and every second the server reduces this value by 1. Simple, but it does the job.

Everything runs smooth for days on most clients. The servers are dispatched remotely on a pretty large (city) network so I get disconnections here and there but most of the time it's not a problem :

• I let the OPCUA client deal with reconnecting & transferring subscriptions, and thanks to the subscriptionListener,
• I recreate the subscriptions when notfied by onSubscriptionTransferFailed. This (re)subscription is made asynchronously (1-3 seconds after) since a couple of posts from Kevin mentioned it could create a deadlock if done straight into the callback.

Problem is as follows : sometimes after days, it suddenly becomes impossible to write on this lifesign variable.
When it happens I get the following notifications :

2021-06-18 15:12:44,793 WARN OpcUaEclipseMiloClient:405 [milo-shared-thread-pool-287] - *** onSessionInactive sur IP 10.208.145.122
2021-06-18 15:12:44,799 ERROR UascClientMessageHandler:170 [milo-netty-event-loop-8] - [remote=/10.208.145.122:16664] Exception caught: An existing connection was forcibly closed by the remote host

2021-06-18 15:12:48,815 ERROR OpcUaEclipseMiloClient:418 [milo-shared-thread-pool-287] - *** onSubscriptionTransferFailed => re-creating subscriptions soon...
2021-06-18 15:12:48,817 WARN OpcUaEclipseMiloClient:394 [milo-shared-thread-pool-287] - *** onSessionActive sur IP 10.208.145.122 => statusConnexion true
2021-06-18 15:12:50,533 INFO OpcUaEclipseMiloClient:468 [thread-opcua-requestsprocessing-7] - Re-creating subscriptions done.

I get the messages above from time to time but usually the client reconnects smoothly.
When the problem happens, the client tries to write the lifesign variable (every minute), seems to write but crashes when trying to read the statusCode :

java.util.concurrent.TimeoutException
at java.util.concurrent.CompletableFuture.timedGet(Unknown Source)
at java.util.concurrent.CompletableFuture.get(Unknown Source)

// write asynchronously....
CompletableFuture f = client.writeValue(varId, dv); etape = 4;
// ...but block for the results so we write in order
f.get(timeoutMs, TimeUnit.MILLISECONDS); <----- code crashes here ; note that I put a 10 seconds timeout when I was hunting deadlocks but I also had the problem even without this timeout

Some seconds after I get a
2021-06-18 15:13:16,822 ERROR OpcUaEclipseMiloClient:418 [milo-shared-thread-pool-287] - *** onSubscriptionTransferFailed => recreating subscriptions in 1-3 seconds...
2021-06-18 15:13:16,824 WARN OpcUaEclipseMiloClient:394 [milo-shared-thread-pool-287] - *** onSessionActive
2021-06-18 15:13:16,825 WARN OpcUaEclipseMiloClient:385 [milo-shared-thread-pool-287] - *** onServiceFault sur IP 10.208.145.122 : ServiceFault(responseHeader=ResponseHeader(timestamp=DateTime{utcTime=0, javaDate=Mon Jan 01 01:00:00 CET 1601}, requestHandle=22774, serviceResult=StatusCode{name=Bad_NoSubscription, value=0x80790000, quality=bad}, serviceDiagnostics=null, stringTable=null, additionalHeader=ExtensionObject{encoded=ByteString{bytes=null}, encodingId=NodeId{ns=0, id=0}}))
2021-06-18 15:13:16,825 WARN OpcUaEclipseMiloClient:385 [milo-shared-thread-pool-287] - *** onServiceFault sur IP 10.208.145.122 : ServiceFault(responseHeader=ResponseHeader(timestamp=DateTime{utcTime=0, javaDate=Mon Jan 01 01:00:00 CET 1601}, requestHandle=22775, serviceResult=StatusCode{name=Bad_NoSubscription, value=0x80790000, quality=bad}, serviceDiagnostics=null, stringTable=null, additionalHeader=ExtensionObject{encoded=ByteString{bytes=null}, encodingId=NodeId{ns=0, id=0}}))

Then I get a couple of onKeepAlive messages and then nothing.

After that, I observed the following symptoms :

1. it's impossible to update the lifesign node anymore,
2. After this crash above, I dont get any other errors/notifications but the lifesign is frozen
3. if I disconnect().get() then connect().get() and recreate my subscriptions, it doesn't help. Note that I don't recreate the listeners (serviceFaultListener & subscriptionListeners) but I re-use the old ones
4. if I stop my client software totally and restart it, the client reconnects smoothly and it can write again on this lifesign node,
5. the weirdest thing for me : if I use an OPCUA client software like UAExpert to connect to the server and write on this node, then everything starts to work again : I can read the value again, write again and so on...

I've been struggling with this for days and I'm totally stuck here.
Any help is welcome, thank you!

[kevinherron]

I think it would be interesting if you could run a Wireshark capture in the background and see if writes are happening at all at the network layer when this is happening.

It would also be wise to upgrade to the latest Milo version to see if that solves the issue.

I'm not sure what else to suggest from the information here, from the last error messages it seems that maybe your subscriptions fail to get re-created after one of the reconnects. I don't know why that would have any effect on your write heartbeat.