Milo OPC UA - unable to connect to server from client when server restarts. server is set to 'USER_TOKEN_POLICY_USERNAME'

0
votes

I am having milo opcua server with USER_TOKEN_POLICY_USERNAME enabled and used UsernameIdentityValidator to set username and password.

From milo client side, I have used UsernameProvider to set setIdentityProvider.

When I run this setup everything works fine.

But when I restart opcua server, milo client won't reconnect. I'm getting below exception:

[milo-shared-thread-pool-2] Skipping validation for certificate: C=DE, ST=" ", L=Locality, OU=OrganizationUnit, O=Organization, CN=AggrServer@7aaf488fd8d6

29.01.2021 09:25:48.282+0000 INFO [m.o.serv.KafkaConsumer(1bc715b8)] [org.springframework.kafka.KafkaListenerEndpointContainer#0-0-C-1] Sent record successfully to topic : NSCH_TEST_Data. 29.01.2021 09:26:55.681+0000 WARN [o.e.m.opcua.sdk.client.SessionFsm] [milo-shared-thread-pool-3] [2] Keep Alive failureCount=4 exceeds failuresAllowed=3 29.01.2021 09:26:55.681+0000 WARN [o.e.m.opcua.sdk.client.SessionFsm] [milo-shared-thread-pool-3] [2] Keep Alive failureCount=5 exceeds failuresAllowed=3 29.01.2021 09:26:55.682+0000 INFO [m.o.MiloConnectorRemote(7b76b59d)] [milo-shared-thread-pool-6] opc.tcp://192.168.56.101:4840: onSessionInactive: OpcUaSession{sessionId=NodeId{ns=1, id=Session:fc6fdb4f-0e8a-441d-ba25-45d067d434e7}, sessionName=OpcUa@0b8bc292754c} 29.01.2021 09:26:55.682+0000 INFO [m.o.MiloConnectorRemote(7b76b59d)] [milo-shared-thread-pool-6] opc.tcp://192.168.56.101:4840: sessionInactive: OpcUaSession{sessionId=NodeId{ns=1, id=Session:fc6fdb4f-0e8a-441d-ba25-45d067d434e7}, sessionName=OpcUa@0b8bc292754c} 29.01.2021 09:26:55.682+0000 INFO [m.o.MiloConnectorRemote(7b76b59d)] [milo-shared-thread-pool-6] opc.tcp://192.168.56.101:4840: notify Observer-opc.tcp://192.168.56.101:4840 about ConnectionEvent(state=Connecting, prevState=Connected, label=opc.tcp://192.168.56.101:4840) 29.01.2021 09:26:55.683+0000 INFO [m.opcua.OpcUaObserverImpl(754d0f4a)] [milo-shared-thread-pool-6] Observer-opc.tcp://192.168.56.101:4840: handle the event ConnectionEvent(state=Connecting, prevState=Connected, label=opc.tcp://192.168.56.101:4840) 29.01.2021 09:26:55.683+0000 INFO [m.o.OpcUaObserverImpl$ModelReadyChangeChecker(3dd6dea0)] [milo-shared-thread-pool-6] OpcUaObserverImpl-opc.tcp://192.168.56.101:4840: stop 29.01.2021 09:26:55.683+0000 INFO [m.opcua.OpcUaObserverImpl(754d0f4a)] [milo-shared-thread-pool-6] Observer-opc.tcp://192.168.56.101:4840: notify 2 listeners about ModelUnavailableEvent@1791022155[uri=opc.tcp://192.168.56.101:4840,nodesCount=0,label=Observer-opc.tcp://192.168.56.101:4840] 29.01.2021 09:26:55.683+0000 INFO [m.opcua.OpcUaObserverImpl(754d0f4a)] [DefaultDispatcher-worker-1] Observer-opc.tcp://192.168.56.101:4840: notify Subscriber-opc.tcp://192.168.56.101:4840 about ModelUnavailableEvent@1791022155[uri=opc.tcp://192.168.56.101:4840,nodesCount=0,label=Observer-opc.tcp://192.168.56.101:4840] 29.01.2021 09:26:55.683+0000 INFO [opcua.MiloSubscriber(364cd1b9)] [DefaultDispatcher-worker-1] Subscriber-opc.tcp://192.168.56.101:4840: unsubscribe 1 subscriptions 29.01.2021 09:26:55.683+0000 INFO [m.opcua.OpcUaObserverImpl(754d0f4a)] [DefaultDispatcher-worker-2] Observer-opc.tcp://192.168.56.101:4840: notify SyncProcessor-opc.tcp://192.168.56.101:4840 about ModelUnavailableEvent@1791022155[uri=opc.tcp://192.168.56.101:4840,nodesCount=0,label=Observer-opc.tcp://192.168.56.101:4840] 29.01.2021 09:26:55.683+0000 INFO [m.opcua.serv.SyncProcessor(2474528)] [DefaultDispatcher-worker-2] SyncProcessor: ignore the event ModelUnavailableEvent@1791022155[uri=opc.tcp://192.168.56.101:4840,nodesCount=0,label=Observer-opc.tcp://192.168.56.101:4840] 29.01.2021 09:26:55.686+0000 INFO [opcua.MiloSubscriber(364cd1b9)] [DefaultDispatcher-worker-1] SyncExecutor-Subscriber(364cd1b9)-opc.tcp://192.168.56.101:4840: SyncExecutor-Subscriber(364cd1b9)-opc.tcp://192.168.56.101:4840: unsubscribe, subscriptionId=1 29.01.2021 09:26:55.686+0000 INFO [opcua.MiloSubscriber(364cd1b9)] [DefaultDispatcher-worker-1] Subscriber-opc.tcp://192.168.56.101:4840: delete subscription SyncExecutor-Subscriber(364cd1b9)-opc.tcp://192.168.56.101:4840(SyncExecutor-Subscriber(364cd1b9)-opc.tcp://192.168.56.101:4840) 29.01.2021 09:27:11.685+0000 WARN [opcua.MiloSubscriber(364cd1b9)] [DefaultDispatcher-worker-1] [Subscriber-opc.tcp://192.168.56.101:4840: deleteSubscription(1) of SyncExecutor-Subscriber(364cd1b9)-opc.tcp://192.168.56.101:4840] return null, because of UaException: status=Bad_ConnectionRejected, message=io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /192.168.56.101:4840 29.01.2021 09:27:27.703+0000 WARN [o.e.m.o.s.c.s.ClientCertificateValidator$InsecureValidator] [milo-shared-thread-pool-5] Skipping validation for certificate: C=DE, ST=" ", L=Locality, OU=OrganizationUnit, O=Organization, CN=AggrServer@7aaf488fd8d6 29.01.2021 09:27:31.782+0000 WARN [o.e.m.o.s.c.s.ClientCertificateValidator$InsecureValidator] [milo-shared-thread-pool-2] Skipping validation for certificate: C=DE, ST=" ", L=Locality, OU=OrganizationUnit, O=Organization, CN=AggrServer@7aaf488fd8d6 29.01.2021 09:27:39.806+0000 WARN [o.e.m.o.s.c.s.ClientCertificateValidator$InsecureValidator] [milo-shared-thread-pool-6] Skipping validation for certificate: C=DE, ST=" ", L=Locality, OU=OrganizationUnit, O=Organization, CN=AggrServer@7aaf488fd8d6 29.01.2021 09:27:55.830+0000 WARN [o.e.m.o.s.c.s.ClientCertificateValidator$InsecureValidator] [milo-shared-thread-pool-3] Skipping validation for certificate: C=DE, ST=" ", L=Locality, OU=OrganizationUnit, O=Organization, CN=AggrServer@7aaf488fd8d6

NEW LOGS

02.02.2021 18:32:55.541+0000 WARN [opcua.MiloSubscriber(3c5d9688)] [DefaultDispatcher-worker-3] [Subscriber-opc.tcp://192.168.56.101:4840: deleteSubscription(1) of SyncExecutor-Subscriber(3c5d9688)-opc.tcp://192.168.56.101:4840] return null, because of UaException: status=Bad_ConnectionRejected, message=io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /192.168.56.101:4840 02.02.2021 18:32:55.542+0000 INFO [opcua.MiloBrowser(1d141b2d)] [DefaultDispatcher-worker-2] idNameTypeSet.nodes.size 02.02.2021 18:32:55.542+0000 INFO [m.o.OpcUaObserverImpl$ModelReadyChangeChecker(3c8bf12c)] [DefaultDispatcher-worker-2] OpcUaObserverImpl-opc.tcp://192.168.56.101:4840: exit model checking, because stopped externally 02.02.2021 18:33:59.790+0000 INFO [m.o.MiloConnectorRemote(74c9951c)] [milo-shared-thread-pool-3] opc.tcp://192.168.56.101:4840: onSessionActive: OpcUaSession{sessionId=NodeId{ns=1, id=Session:d27e7db7-4401-4f08-8c17-7bfaf9075fe4}, sessionName=OpcUa@154c9f72aa09} 02.02.2021 18:33:59.790+0000 INFO [m.o.MiloConnectorRemote(74c9951c)] [milo-shared-thread-pool-3] opc.tcp://192.168.56.101:4840: notify Observer-opc.tcp://192.168.56.101:4840 about ConnectionEvent(state=Connected, prevState=Connecting, label=opc.tcp://192.168.56.101:4840) 02.02.2021 18:33:59.790+0000 INFO [m.opcua.OpcUaObserverImpl(ff09afd)] [milo-shared-thread-pool-3] Observer-opc.tcp://192.168.56.101:4840: handle the event ConnectionEvent(state=Connected, prevState=Connecting, label=opc.tcp://192.168.56.101:4840) 02.02.2021 18:33:59.790+0000 INFO [m.o.OpcUaObserverImpl$ModelReadyChangeChecker(3c8bf12c)] [milo-shared-thread-pool-3] OpcUaObserverImpl-opc.tcp://192.168.56.101:4840: start 02.02.2021 18:33:59.790+0000 INFO [m.o.OpcUaObserverImpl$ModelReadyChangeChecker(3c8bf12c)] [milo-shared-thread-pool-3] OpcUaObserverImpl-opc.tcp://192.168.56.101:4840: modelReadyChecking=MinMaxInterval(min=10, max=30, timeUnit=SECONDS, current=10, step=3), modelChangeChecking=MinMaxInterval(min=60, max=1800, timeUnit=SECONDS, current=60, step=180), modelReadyMinNodesCount=0 02.02.2021 18:33:59.804+0000 INFO [m.o.OpcUaObserverImpl$ModelReadyChangeChecker(3c8bf12c)] [DefaultDispatcher-worker-2] OpcUaObserverImpl-opc.tcp://192.168.56.101:4840: -> check(modelReadyMinNodesCount=0,modelChangeCheckingRunning=false) 02.02.2021 18:33:59.804+0000 INFO [opcua.MiloBrowser(1d141b2d)] [DefaultDispatcher-worker-2] In nodesCount method 02.02.2021 18:33:59.817+0000 INFO [opcua.MiloBrowser(1d141b2d)] [DefaultDispatcher-worker-2] nodesCount=3605

2
milo
This isn’t an exception and isn’t related to whatever is causing it not to reconnect. You’ll have to provide more information or logs. - Kevin Herron
just added '.setIdentityProvider(UsernameProvider(getSystemEnv("USERNAME"), getSystemEnv("PASSWORD")))' to client part and it stopped working - Amit Gawande
"onSessionActive:" was not getting triggered - Amit Gawande
You'll have to provide more logs or a Wireshark capture or something. - Kevin Herron
@KevinHerron added few more logs - Amit Gawande

2 Answers

0
votes

Seems there is an issue with client/server certificate validation.

UA PKI, X509 and other is complex and hard to understand and even harder to configure properly, can't answer this with few words. If you are just starting with OPC UA, try to skip server policies and user identification until you have learned about.

Server and client will need certificates in order the decrypt or encrypt the user authentification.

But do some checks:

  • Check, if the client has the server certificate in its trusted path.
  • Check, if the server certificate has altered. The server should not regenerate its self signed certificate with each server start, but only with installation setup or administration.

Workarounds:

0
votes

I think the meaningful Exception to extract from your new logs is this:

io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /192.168.56.101:4840

Simple networking error. The server isn't there, isn't running, a firewall is in the way, etc...

It's not anything you're doing wrong in client code right now.