SubscriptionTransferFailed 挂钩在 Eclipse Milo 中未按预期工作
SubscriptionTransferFailed hook not working as expected in Eclipse Milo
我正在尝试管理与 OPC 服务器的重新连接，当它关闭一段时间并重新启动时。我的 milo 客户端无法自动重新连接，因为服务器不支持订阅传输，因此我添加了一个 SusbcriptionListener 以捕获 onSubscriptionTransferFailed 事件，因此我可以手动重新连接到服务器。问题似乎是我的代码没有捕捉到 onSubscriptionTransferFailed 事件，所以我无法知道服务器再次启动并尝试手动重新连接。我也尝试使用 SessionActivityListener 但 none 事件都没有收到。
这是 milo 尝试重新连接的日志文件：
2022-05-19 16:26:59,512 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientAcknowledgeHandler [milo-netty-event-loop-2] Received Acknowledge message on channel=[id: 0x8dc57c76, L:/134.145.242.91:49555 - R:/134.145.242.30:4840].
2022-05-19 16:26:59,513 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] OpenSecureChannel timeout scheduled for +5000ms
2022-05-19 16:26:59,513 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-5] Sent OpenSecureChannelRequest (Issue, id=0, currentToken=-1, previousToken=-1).
2022-05-19 16:26:59,515 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] OpenSecureChannel timeout canceled
2022-05-19 16:26:59,515 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-5] Received OpenSecureChannelResponse.
2022-05-19 16:26:59,516 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-5] SecureChannel id=17, currentTokenId=1, previousTokenId=-1, lifetime=3600000ms, createdAt=DateTime{utcTime=116444737603600000, javaDate=Thu Jan 01 01:02:40 CET 1970}
2022-05-19 16:26:59,516 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] 0 message(s) queued before handshake completed; sending now.
2022-05-19 16:26:59,516 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [2] S(Reconnecting) x E(ConnectSuccess) = S'(Connected)
2022-05-19 16:26:59,564 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-5] [3] S(ReconnectWait) x E(ReconnectDelayElapsed) = S'(Reconnecting)
2022-05-19 16:26:59,567 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientAcknowledgeHandler [milo-netty-event-loop-3] Sent Hello message on channel=[id: 0x311aec0a, L:/134.145.242.91:49556 - R:/134.145.242.30:4840].
2022-05-19 16:26:59,572 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientAcknowledgeHandler [milo-netty-event-loop-3] Received Acknowledge message on channel=[id: 0x311aec0a, L:/134.145.242.91:49556 - R:/134.145.242.30:4840].
2022-05-19 16:26:59,573 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-3] OpenSecureChannel timeout scheduled for +5000ms
2022-05-19 16:26:59,574 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-0] Sent OpenSecureChannelRequest (Issue, id=0, currentToken=-1, previousToken=-1).
2022-05-19 16:26:59,579 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-3] OpenSecureChannel timeout canceled
2022-05-19 16:26:59,580 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-0] Received OpenSecureChannelResponse.
2022-05-19 16:26:59,580 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-0] SecureChannel id=18, currentTokenId=1, previousTokenId=-1, lifetime=3600000ms, createdAt=DateTime{utcTime=116444737604250000, javaDate=Thu Jan 01 01:02:40 CET 1970}
2022-05-19 16:26:59,581 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-3] 0 message(s) queued before handshake completed; sending now.
2022-05-19 16:26:59,581 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-5] [3] S(Reconnecting) x E(ConnectSuccess) = S'(Connected)
2022-05-19 16:27:14,504 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [5] S(CreatingWait) x E(CreatingWaitExpired) = S'(Creating)
2022-05-19 16:27:14,505 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-0] [5] Sending CreateSessionRequest...
2022-05-19 16:27:14,512 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-5] [5] CreateSession succeeded: NodeId{ns=1, id=100016}
2022-05-19 16:27:14,512 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [5] S(Creating) x E(CreateSessionSuccess) = S'(Activating)
2022-05-19 16:27:14,513 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-0] [5] Sending ActivateSessionRequest...
2022-05-19 16:27:14,516 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-5] [5] Session activated: OpcUaSession{sessionId=NodeId{ns=1, id=100016}, sessionName=UaSession:Data Capture Automation:1652970434516}
2022-05-19 16:27:14,516 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [5] S(Activating) x E(ActivateSessionSuccess) = S'(Transferring)
2022-05-19 16:27:14,517 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-0] [5] Sending TransferSubscriptionsRequest...
2022-05-19 16:27:14,520 ERROR org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] [remote=/134.145.242.30:4840] errorMessage=ErrorMessage{error=StatusCode{name=Bad_ServiceUnsupported, value=0x800B0000, quality=bad}, reason=null}
2022-05-19 16:27:14,522 DEBUG com.digitalpetri.netty.fsm.ChannelFsmFactory [milo-netty-event-loop-2] [2] channelInactive() local=/134.145.242.91:49555, remote=/134.145.242.30:4840
2022-05-19 16:27:14,523 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-5] [2] S(Connected) x E(ChannelInactive) = S'(ReconnectWait)
2022-05-19 16:27:14,523 DEBUG org.eclipse.milo.opcua.stack.client.UaStackClient [milo-shared-thread-pool-0] sendRequest() failed, request=TransferSubscriptionsRequest, requestHandle=305
java.util.concurrent.CompletionException: UaException: status=Bad_ConnectionClosed, message=connection closed
at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:326)
at java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:338)
at java.util.concurrent.CompletableFuture.uniRelay(CompletableFuture.java:925)
at java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:913)
这是我尝试捕获 onSubscriptionTransferFailed 事件的代码：
@Override
public void onStatusChanged(UaSubscription subscription,
StatusCode status)
{
logger.warn("onStatusChanged event for {}, status = {}. Trying to setup new subscription", subscription.toString(), status.toString());
}
@Override
public void onSubscriptionTransferFailed(UaSubscription subscription, StatusCode statusCode) {
logger.warn("onStatusChanged event for {}, status = {}. Trying to setup new subscription", subscription.toString(), statusCode.toString());
Stack.sharedExecutor().execute(() -> {
try {
if(!isConnected()){
disconnect();
init(endpointUrl, securityPolicy.toString(), "AnonymousProvider");
}
subscribe(nodesToSubscribe);
logger.info("New subscription created");
} catch (Exception e) {
logger.error("Error creating Subscription: {}", e.getMessage(), e);
}
});
}
});
和 SessionActivityListener：
this.client.addSessionActivityListener(new SessionActivityListener() {
@Override
public void onSessionInactive(UaSession session) {
logger.warn("onSessionInactive event for {}. Trying to setup new subscription", session.toString());
}
@Override
public void onSessionActive(UaSession session) {
}
});
有人可以告诉我我的代码是否有问题或任何线索为什么我没有捕捉到这些侦听器的事件吗？
非常感谢。
I'm using milo 0.4.3
由于此服务器的实施缺陷以及 Milo 的 Session FSM 0.5.3 之前的 this issue，您需要将客户端使用的 Milo 版本至少升级到 0.5.3。
我建议直接使用今天刚刚发布的 0.6.6。移动到旧版本没有意义。
我正在尝试管理与 OPC 服务器的重新连接，当它关闭一段时间并重新启动时。我的 milo 客户端无法自动重新连接，因为服务器不支持订阅传输，因此我添加了一个 SusbcriptionListener 以捕获 onSubscriptionTransferFailed 事件，因此我可以手动重新连接到服务器。问题似乎是我的代码没有捕捉到 onSubscriptionTransferFailed 事件，所以我无法知道服务器再次启动并尝试手动重新连接。我也尝试使用 SessionActivityListener 但 none 事件都没有收到。 这是 milo 尝试重新连接的日志文件：
2022-05-19 16:26:59,512 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientAcknowledgeHandler [milo-netty-event-loop-2] Received Acknowledge message on channel=[id: 0x8dc57c76, L:/134.145.242.91:49555 - R:/134.145.242.30:4840].
2022-05-19 16:26:59,513 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] OpenSecureChannel timeout scheduled for +5000ms
2022-05-19 16:26:59,513 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-5] Sent OpenSecureChannelRequest (Issue, id=0, currentToken=-1, previousToken=-1).
2022-05-19 16:26:59,515 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] OpenSecureChannel timeout canceled
2022-05-19 16:26:59,515 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-5] Received OpenSecureChannelResponse.
2022-05-19 16:26:59,516 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-5] SecureChannel id=17, currentTokenId=1, previousTokenId=-1, lifetime=3600000ms, createdAt=DateTime{utcTime=116444737603600000, javaDate=Thu Jan 01 01:02:40 CET 1970}
2022-05-19 16:26:59,516 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] 0 message(s) queued before handshake completed; sending now.
2022-05-19 16:26:59,516 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [2] S(Reconnecting) x E(ConnectSuccess) = S'(Connected)
2022-05-19 16:26:59,564 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-5] [3] S(ReconnectWait) x E(ReconnectDelayElapsed) = S'(Reconnecting)
2022-05-19 16:26:59,567 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientAcknowledgeHandler [milo-netty-event-loop-3] Sent Hello message on channel=[id: 0x311aec0a, L:/134.145.242.91:49556 - R:/134.145.242.30:4840].
2022-05-19 16:26:59,572 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientAcknowledgeHandler [milo-netty-event-loop-3] Received Acknowledge message on channel=[id: 0x311aec0a, L:/134.145.242.91:49556 - R:/134.145.242.30:4840].
2022-05-19 16:26:59,573 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-3] OpenSecureChannel timeout scheduled for +5000ms
2022-05-19 16:26:59,574 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-0] Sent OpenSecureChannelRequest (Issue, id=0, currentToken=-1, previousToken=-1).
2022-05-19 16:26:59,579 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-3] OpenSecureChannel timeout canceled
2022-05-19 16:26:59,580 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-0] Received OpenSecureChannelResponse.
2022-05-19 16:26:59,580 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-shared-thread-pool-0] SecureChannel id=18, currentTokenId=1, previousTokenId=-1, lifetime=3600000ms, createdAt=DateTime{utcTime=116444737604250000, javaDate=Thu Jan 01 01:02:40 CET 1970}
2022-05-19 16:26:59,581 DEBUG org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-3] 0 message(s) queued before handshake completed; sending now.
2022-05-19 16:26:59,581 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-5] [3] S(Reconnecting) x E(ConnectSuccess) = S'(Connected)
2022-05-19 16:27:14,504 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [5] S(CreatingWait) x E(CreatingWaitExpired) = S'(Creating)
2022-05-19 16:27:14,505 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-0] [5] Sending CreateSessionRequest...
2022-05-19 16:27:14,512 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-5] [5] CreateSession succeeded: NodeId{ns=1, id=100016}
2022-05-19 16:27:14,512 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [5] S(Creating) x E(CreateSessionSuccess) = S'(Activating)
2022-05-19 16:27:14,513 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-0] [5] Sending ActivateSessionRequest...
2022-05-19 16:27:14,516 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-5] [5] Session activated: OpcUaSession{sessionId=NodeId{ns=1, id=100016}, sessionName=UaSession:Data Capture Automation:1652970434516}
2022-05-19 16:27:14,516 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-0] [5] S(Activating) x E(ActivateSessionSuccess) = S'(Transferring)
2022-05-19 16:27:14,517 DEBUG org.eclipse.milo.opcua.sdk.client.session.SessionFsmFactory [milo-shared-thread-pool-0] [5] Sending TransferSubscriptionsRequest...
2022-05-19 16:27:14,520 ERROR org.eclipse.milo.opcua.stack.client.transport.uasc.UascClientMessageHandler [milo-netty-event-loop-2] [remote=/134.145.242.30:4840] errorMessage=ErrorMessage{error=StatusCode{name=Bad_ServiceUnsupported, value=0x800B0000, quality=bad}, reason=null}
2022-05-19 16:27:14,522 DEBUG com.digitalpetri.netty.fsm.ChannelFsmFactory [milo-netty-event-loop-2] [2] channelInactive() local=/134.145.242.91:49555, remote=/134.145.242.30:4840
2022-05-19 16:27:14,523 DEBUG com.digitalpetri.strictmachine.StrictMachine$PollAndEvaluate [milo-shared-thread-pool-5] [2] S(Connected) x E(ChannelInactive) = S'(ReconnectWait)
2022-05-19 16:27:14,523 DEBUG org.eclipse.milo.opcua.stack.client.UaStackClient [milo-shared-thread-pool-0] sendRequest() failed, request=TransferSubscriptionsRequest, requestHandle=305
java.util.concurrent.CompletionException: UaException: status=Bad_ConnectionClosed, message=connection closed
at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:326)
at java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:338)
at java.util.concurrent.CompletableFuture.uniRelay(CompletableFuture.java:925)
at java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:913)
这是我尝试捕获 onSubscriptionTransferFailed 事件的代码：
@Override
public void onStatusChanged(UaSubscription subscription,
StatusCode status)
{
logger.warn("onStatusChanged event for {}, status = {}. Trying to setup new subscription", subscription.toString(), status.toString());
}
@Override
public void onSubscriptionTransferFailed(UaSubscription subscription, StatusCode statusCode) {
logger.warn("onStatusChanged event for {}, status = {}. Trying to setup new subscription", subscription.toString(), statusCode.toString());
Stack.sharedExecutor().execute(() -> {
try {
if(!isConnected()){
disconnect();
init(endpointUrl, securityPolicy.toString(), "AnonymousProvider");
}
subscribe(nodesToSubscribe);
logger.info("New subscription created");
} catch (Exception e) {
logger.error("Error creating Subscription: {}", e.getMessage(), e);
}
});
}
});
和 SessionActivityListener：
this.client.addSessionActivityListener(new SessionActivityListener() {
@Override
public void onSessionInactive(UaSession session) {
logger.warn("onSessionInactive event for {}. Trying to setup new subscription", session.toString());
}
@Override
public void onSessionActive(UaSession session) {
}
});
有人可以告诉我我的代码是否有问题或任何线索为什么我没有捕捉到这些侦听器的事件吗？
非常感谢。
I'm using milo 0.4.3
由于此服务器的实施缺陷以及 Milo 的 Session FSM 0.5.3 之前的 this issue，您需要将客户端使用的 Milo 版本至少升级到 0.5.3。
我建议直接使用今天刚刚发布的 0.6.6。移动到旧版本没有意义。