| [milo-dev] Session goes inactive / failing to restart subscriptions |
Hey, we have a problem with the session going inactive and failing to restart subscriptions with our client based upon milo and an external opc ua server. So after around 1 hour of successfully keeping subscriptions up the following happens, session goes inactive, we try to transfer/restart the subscriptions but get lots of errors about the sessionId : [...] 2019-10-15 14:05:21.518 WARN 1 --- [-thread-pool-27] o.e.milo.opcua.sdk.client.SessionFsm : [2] Keep Alive failureCount=2 exceeds failuresAllowed=1 2019-10-15 14:05:21.519 INFO 1 --- [-thread-pool-25] d.sourcewerk.opcua.client.SwOpcUaClient : Session inactive 2019-10-15 14:05:25.726 WARN 1 --- [-thread-pool-17] o.e.m.o.s.c.t.u.UascClientMessageHandler : No pending request with requestId=8911 for ReadResponse 2019-10-15 14:05:25.726 WARN 1 --- [-thread-pool-26] o.e.m.o.s.c.t.u.UascClientMessageHandler : No pending request with requestId=8912 for ReadResponse 2019-10-15 14:05:25.728 WARN 1 --- [-thread-pool-26] e.m.o.s.c.s.InsecureCertificateValidator : Skipping validation for certificate: CN=... 2019-10-15 14:05:25.728 WARN 1 --- [-thread-pool-26] e.m.o.s.c.s.InsecureCertificateValidator : Skipping trust chain verification for certificate: CN=... 2019-10-15 14:05:25.832 DEBUG 1 --- [-thread-pool-27] d.sourcewerk.opcua.client.SwOpcUaClient : SessionInitializer: DataTypeDictionary 2019-10-15 14:05:25.832 DEBUG 1 --- [-thread-pool-27] d.sourcewerk.opcua.client.SwOpcUaClient : SessionInitializer: NamespaceTable 2019-10-15 14:05:25.832 ERROR 1 --- [-thread-pool-25] d.sourcewerk.opcua.client.SwOpcUaClient : Subscription manager transfer Failed for Subscription Subscription=ns=3;s=V:0.3.212.0.28 with Status Code StatusCode{name=Bad_ServiceUnsupported, value=0x800B0000, quality=bad} 2019-10-15 14:05:25.833 INFO 1 --- [-thread-pool-25] d.sourcewerk.opcua.client.SwOpcUaClient : Start subscription SubscriptionRequest([left out…]) 2019-10-15 14:05:25.912 INFO 1 --- [-thread-pool-27] d.sourcewerk.opcua.client.SwOpcUaClient : Session active, starting subscriptionRequests 2019-10-15 14:05:25.921 ERROR 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : Subscription manager publish failure status=Bad_SessionClosed, description=The session was closed by the client. org.eclipse.milo.opcua.stack.core.UaServiceFaultException: status=Bad_SessionClosed, description=The session was closed by the client. at org.eclipse.milo.opcua.stack.client.UaStackClient.lambda$deliverResponse$5(UaStackClient.java:273) ~[stack-client-0.3.3.jar:0.3.3] at org.eclipse.milo.opcua.stack.core.util.ExecutionQueue$Task.run(ExecutionQueue.java:119) ~[stack-core-0.3.3.jar:0.3.3] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:na] at java.base/java.lang.Thread.run(Unknown Source) ~[na:na] 2019-10-15 14:05:25.921 DEBUG 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : Notifying 1 ServiceFaultListeners 2019-10-15 14:05:25.923 INFO 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : Session inactive 2019-10-15 14:05:26.945 WARN 1 --- [-thread-pool-26] e.m.o.s.c.s.InsecureCertificateValidator : Skipping validation for certificate: ... 2019-10-15 14:05:26.945 WARN 1 --- [-thread-pool-26] e.m.o.s.c.s.InsecureCertificateValidator : Skipping trust chain verification for certificate: ... 2019-10-15 14:05:26.964 DEBUG 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : SessionInitializer: DataTypeDictionary 2019-10-15 14:05:26.965 DEBUG 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : SessionInitializer: NamespaceTable 2019-10-15 14:05:27.011 INFO 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : Session active, starting subscriptionRequests 2019-10-15 14:05:27.017 DEBUG 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : Notifying 1 ServiceFaultListeners 2019-10-15 14:05:27.017 INFO 1 --- [-thread-pool-26] d.sourcewerk.opcua.client.SwOpcUaClient : Session inactive 2019-10-15 14:05:27.018 ERROR 1 --- [-thread-pool-25] d.sourcewerk.opcua.client.SwOpcUaClient : Error while trying to subscribe monitored items UaServiceFaultException: status=Bad_SessionIdInvalid, message=The session id is not valid. java.util.concurrent.ExecutionException: UaServiceFaultException: status=Bad_SessionIdInvalid, message=The session id is not valid. at java.base/java.util.concurrent.CompletableFuture.reportGet(Unknown Source) ~[na:na] There seems to be first a problem with the session going inactive, or is this something that can just happen frequently?! And second continuing from that, we already implemented the onSubscriptionTransferFailed (as described here https://stackoverflow.com/questions/38301171/how-are-disconnects-re-connects-handled-in-eclipse-milo-on-the-client-side ) to restart the subscriptions and monitoredItems but it does not seem to work because of the sessionId. Does anyone have a guess on what could be the root of this problem and how to fix it? With kind regards Johannes Mundorf --------------------------- sourcewerk GmbH Johannes Mundorf Software Developer |