Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [milo-dev] Session goes inactive / failing to restart subscriptions
Johannes,

Is there any chance you can capture this happening with Wireshark recording?

Either way, it may be helpful to turn the log level for SessionFsm and ChannelFsm to DEBUG or TRACE and then share the logs when this occurs again.

On Tue, Oct 15, 2019 at 1:35 PM <Johannes.Mundorf@xxxxxxxxxxxxx> wrote:
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

Roseggerstr. 59
44137 Dortmund 

Mail: johannes.mundorf@xxxxxxxxxxxxx

_______________________________________________
milo-dev mailing list
milo-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://www.eclipse.org/mailman/listinfo/milo-dev

Back to the top