Getting disconnected after channel renewal #1574
Replies: 5 comments 4 replies
-
|
Any chance you can get a Wireshark capture of this? It does look like right after the renewal the server closes the connection. You would have to use no security for the capture to be useful. Secure channel renewal still happens even without security. |
Beta Was this translation helpful? Give feedback.
-
Also seems the clock on the server is ~40 minutes ahead of your client? Not sure if that's the issue here or not, but it's something to be wary of. |
Beta Was this translation helpful? Give feedback.
-
|
Thanks for the quick response! As a test I switched from I did not spot that difference in clock's, good one! I will check if I can adjust it (or otherwise maybe adjust my laptops clock) and post the results here. So it looks like I will only be able to create a wireshark capture with Thanks! |
Beta Was this translation helpful? Give feedback.
-
|
If you must use security, try MessageSecurityMode.Sign instead of MessageSecurityMode.SignAndEncrypt. If I had to guess right now, I think the server may have some issue with receiving requests in between receiving OpenSecureChannelRequest and sending OpenSecureChannelResponse (there are 3 method calls that seem to happen in your logs in this time). It's perfectly allowed, but maybe it has some issue. I'm not sure if I can prove anything one way or the other without a usable capture though. |
Beta Was this translation helpful? Give feedback.
-
|
Adjusting the clock didn't solve it, but my first impression is the log is now a little different from all my previous logs. 2025-08-27 18:49:59.448 [milo-shared-thread-pool-0] DEBUG o.g.e.o.MiloOpcUaConnectionHandler - Server current time changed to Variant{value=DateTime{date=Wed Aug 27 18:49:54 CEST 2025, instant=2025-08-27T16:49:54.125285Z}}
2025-08-27 18:49:59.448 [milo-shared-thread-pool-0] DEBUG o.e.m.o.s.c.s.PublishingManager - getTimeoutHint() maxKeepAlive=60000.0 maxPendingPublishes=2 timeoutHint=180000.0
2025-08-27 18:49:59.448 [milo-shared-thread-pool-0] DEBUG o.e.m.o.s.c.s.PublishingManager - Sending PublishRequest, requestHandle=933, acknowledgements=[id=1/seq=450]
2025-08-27 18:49:59.449 [milo-netty-event-loop-1] TRACE o.e.m.o.s.t.c.t.OpcTcpClientTransport - Write succeeded, request=PublishRequest, requestId=936
2025-08-27 18:49:59.458 [Thread-0] DEBUG c.m.opcua.MdsOpcUaClient - GetAllEventDetails requested
2025-08-27 18:49:59.458 [Thread-0] DEBUG o.g.edge.opcua.AbstractOpcUaClient - Calling method, object id = NodeId{ns=1, id=537919488}, method id = NodeId{ns=1, id=GetAllEventDetails}
2025-08-27 18:49:59.460 [milo-netty-event-loop-1] TRACE o.e.m.o.s.t.c.t.OpcTcpClientTransport - Write succeeded, request=CallRequest, requestId=937
2025-08-27 18:49:59.496 [Thread-1] DEBUG o.g.e.o.MiloOpcUaConnectionHandler - Method succesfully called
2025-08-27 18:50:00.374 [milo-netty-event-loop-1] DEBUG o.e.m.o.s.t.c.u.UascClientMessageHandler - Sent OpenSecureChannelRequest (Renew, id=21, currentToken=38, previousToken=37).
2025-08-27 18:50:00.459 [Thread-0] DEBUG c.m.opcua.MdsOpcUaClient - GetAllEventDetails requested
2025-08-27 18:50:00.459 [Thread-0] DEBUG o.g.edge.opcua.AbstractOpcUaClient - Calling method, object id = NodeId{ns=1, id=537919488}, method id = NodeId{ns=1, id=GetAllEventDetails}
2025-08-27 18:50:00.461 [milo-netty-event-loop-1] TRACE o.e.m.o.s.t.c.t.OpcTcpClientTransport - Write succeeded, request=CallRequest, requestId=939
2025-08-27 18:50:01.459 [Thread-0] DEBUG c.m.opcua.MdsOpcUaClient - GetAllEventDetails requested
2025-08-27 18:50:01.459 [Thread-0] DEBUG o.g.edge.opcua.AbstractOpcUaClient - Calling method, object id = NodeId{ns=1, id=537919488}, method id = NodeId{ns=1, id=GetAllEventDetails}
2025-08-27 18:50:02.471 [Thread-0] DEBUG c.m.opcua.MdsOpcUaClient - GetAllEventDetails requested
2025-08-27 18:50:02.471 [Thread-0] DEBUG o.g.edge.opcua.AbstractOpcUaClient - Calling method, object id = NodeId{ns=1, id=537919488}, method id = NodeId{ns=1, id=GetAllEventDetails}
2025-08-27 18:50:02.673 [milo-netty-event-loop-1] DEBUG o.e.m.o.s.t.c.u.UascClientMessageHandler - Received OpenSecureChannelResponse.
2025-08-27 18:50:02.673 [milo-netty-event-loop-1] DEBUG o.e.m.o.s.t.c.u.UascClientMessageHandler - SecureChannel id=21, currentTokenId=39, previousTokenId=38, lifetime=300000ms, createdAt=DateTime{date=Wed Aug 27 18:49:56 CEST 2025, instant=2025-08-27T16:49:56.649584Z}
2025-08-27 18:50:02.673 [milo-netty-event-loop-1] DEBUG o.e.m.o.s.c.c.ChunkDecoder$SymmetricDecoder - Attempting to use SecurityKeys from previousTokenId=38
2025-08-27 18:50:02.673 [milo-shared-thread-pool-0] DEBUG o.e.m.o.s.c.s.PublishingManager - Received PublishResponse, requestHandle=931, sequenceNumber=451
2025-08-27 18:50:02.673 [milo-shared-thread-pool-0] DEBUG o.e.m.o.s.c.s.OpcUaSubscription - id=1 watchdog timer scheduled for +15150ms
2025-08-27 18:50:02.673 [milo-shared-thread-pool-0] TRACE o.e.m.o.s.c.s.OpcUaSubscription - id=1, watchdog timer reset
2025-08-27 18:50:02.673 [milo-shared-thread-pool-3] DEBUG o.e.m.o.s.c.s.PublishingManager - Processing PublishResponse, subscriptionId=1, isKeepAlive=false, lastSequenceNumber=450, receivedSequenceNumber=451, expectedSequenceNumber=451
2025-08-27 18:50:02.673 [milo-shared-thread-pool-0] DEBUG o.g.e.o.MiloOpcUaConnectionHandler - Server current time changed to Variant{value=DateTime{date=Wed Aug 27 18:49:55 CEST 2025, instant=2025-08-27T16:49:55.125275Z}}
2025-08-27 18:50:02.674 [milo-shared-thread-pool-0] DEBUG o.e.m.o.s.c.s.PublishingManager - getTimeoutHint() maxKeepAlive=60000.0 maxPendingPublishes=2 timeoutHint=180000.0
2025-08-27 18:50:02.674 [milo-shared-thread-pool-0] DEBUG o.e.m.o.s.c.s.PublishingManager - Sending PublishRequest, requestHandle=936, acknowledgements=[id=1/seq=451]
2025-08-27 18:50:02.674 [milo-netty-event-loop-1] DEBUG o.e.m.opcua.stack.client.ChannelFsm - channelInactive() local=/192.168.1.114:57394, remote=/192.168.1.247:4840
2025-08-27 18:50:02.676 [milo-netty-event-loop-1] DEBUG o.e.m.o.s.t.c.t.OpcTcpClientTransport - Write failed, request=PublishRequest, requestHandle=940
2025-08-27 18:50:02.676 [milo-shared-thread-pool-4] DEBUG o.e.m.opcua.stack.client.ChannelFsm - S(Connected) x E(ChannelInactive) = S'(ReconnectWait)
2025-08-27 18:50:02.676 [milo-shared-thread-pool-4] TRACE o.e.m.opcua.stack.client.ChannelFsm - found 2 matching TransitionActions
2025-08-27 18:50:02.676 [milo-shared-thread-pool-4] TRACE o.e.m.opcua.stack.client.ChannelFsm - executing TransitionAction: com.digitalpetri.fsm.dsl.ActionBuilder$PredicatedTransitionAction@7256a281
2025-08-27 18:50:02.676 [milo-shared-thread-pool-4] TRACE o.e.m.opcua.stack.client.ChannelFsm - executing TransitionAction: com.digitalpetri.netty.fsm.ChannelFsm$1@4096f572
2025-08-27 18:50:02.677 [milo-shared-thread-pool-4] DEBUG o.e.m.opcua.sdk.client.SessionFsm - ChannelFsm transition from=Connected to=ReconnectWait via=ChannelInactive
2025-08-27 18:50:02.677 [milo-shared-thread-pool-5] DEBUG o.e.m.opcua.sdk.client.SessionFsm - S(Active) x E(ConnectionLost) = S'(ReactivatingWait)
2025-08-27 18:50:02.677 [milo-shared-thread-pool-5] TRACE o.e.m.opcua.sdk.client.SessionFsm - found 4 matching TransitionActions
2025-08-27 18:50:02.677 [milo-shared-thread-pool-5] TRACE o.e.m.opcua.sdk.client.SessionFsm - executing TransitionAction: com.digitalpetri.fsm.dsl.ActionBuilder$PredicatedTransitionAction@56e308f
2025-08-27 18:50:02.677 [milo-shared-thread-pool-5] TRACE o.e.m.opcua.sdk.client.SessionFsm - executing TransitionAction: com.digitalpetri.fsm.dsl.ActionBuilder$PredicatedTransitionAction@ba9ce52
2025-08-27 18:50:02.678 [milo-shared-thread-pool-5] TRACE o.e.m.opcua.sdk.client.SessionFsm - executing TransitionAction: com.digitalpetri.fsm.dsl.ActionBuilder$PredicatedTransitionAction@4a94c469
2025-08-27 18:50:02.678 [milo-shared-thread-pool-5] TRACE o.e.m.opcua.sdk.client.SessionFsm - executing TransitionAction: com.digitalpetri.fsm.dsl.ActionBuilder$PredicatedTransitionAction@3e0a7ffc
2025-08-27 18:50:02.678 [milo-shared-thread-pool-4] INFO o.g.e.o.MiloOpcUaConnectionHandler - onSessionInactive() called by milo client
2025-08-27 18:50:02.678 [milo-shared-thread-pool-4] DEBUG o.e.m.o.s.c.s.OpcUaSubscription - id=1, watchdog timer cancelled via onSessionInactive()
2025-08-27 18:50:02.700 [Thread-1] ERROR o.g.e.o.MiloOpcUaConnectionHandler - Exception while calling method:
org.eclipse.milo.opcua.stack.core.UaException: connection closed
at org.eclipse.milo.opcua.stack.transport.client.AbstractUascClientTransport.handleChannelInactive(AbstractUascClientTransport.java:189)
at org.eclipse.milo.opcua.stack.transport.client.uasc.InboundUascResponseHandler$DelegatingUascResponseHandler.handleChannelInactive(InboundUascResponseHandler.java:103)
at org.eclipse.milo.opcua.stack.transport.client.uasc.InboundUascResponseHandler.channelInactive(InboundUascResponseHandler.java:68)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:412)
at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:377)
at io.netty.handler.codec.ByteToMessageCodec.channelInactive(ByteToMessageCodec.java:118)
at org.eclipse.milo.opcua.stack.transport.client.uasc.UascClientMessageHandler.channelInactive(UascClientMessageHandler.java:149)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1352)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:850)
at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:811)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:998)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at java.base/java.lang.Thread.run(Thread.java:1583)
2025-08-27 18:50:02.701 [milo-shared-thread-pool-3] DEBUG o.e.m.opcua.sdk.client.SessionFsm - S(ReactivatingWait) x E(GetSession) = S'(ReactivatingWait)
...For now at least I have a workaround (this is a small application for a demo), and it's starting to look like it's not a milo problem. But I will try to create a wireshark capture with your suggestions, I think this company will probably also be curious if their server is maybe causing this. Thanks for your help! |
Beta Was this translation helpful? Give feedback.
-
|
Hmm, yeah, very interested to see a capture if you can get one. What company/device is this? and if you happen to know what SDK they use, that's useful too, though I might be able to find out as well given the company/device info. |
Beta Was this translation helpful? Give feedback.
-
|
I think I should be able to have more info about the servers SDK tomorrow, but I will probably send you this in the email mentioned in your profile, I am not sure if I can share this publicly. |
Beta Was this translation helpful? Give feedback.
-
|
I just sent you an email with some additional info. In short: It's a open62541 based server, the controller I am using is probably a dev/test unit from someone's desk and we're not really sure what versions are on here, so we will first see if we can reproduce it with other controllers. I would be surprised if it's being caused by milo. Thanks again for your help! |
Beta Was this translation helpful? Give feedback.
-
|
Ok sounds good, if this pops up again the future with other units feel free to get in touch. |
Beta Was this translation helpful? Give feedback.
Uh oh!
There was an error while loading. Please reload this page.
-
This is my first time working with milo and I thought I had everything working pretty well, except that I am getting connection problems after a few minutes and as far as I can see it seems I am being disconnected after a secure channel renewal (all still pretty new to me).
This is a log I just recorded, at 17:17:43.436 I am getting a channelInactive() and I am wondering if the server is closing the connection or if it is the client. Anybody have any ideas?
I am using milo 1.0.4 and the server is running on a embedded device, I don't know yet what is used for the server. UaExpert stays connected without problems with this server.
Beta Was this translation helpful? Give feedback.
All reactions