Eclipse Milo - ClosedChannelException when using SecurityPolicy

Question

I am connecting from an Eclipse Milo client to an Eclipse Milo server. Everything works fine but as soon as I try connecting with any SecurityPolicy except "None" I get the following error:

17:28:18.365 [main] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - connect(), currentState=NotConnected
17:28:18.365 [main] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - connect() while NotConnected
java.lang.Exception: null
    at org.eclipse.milo.opcua.stack.client.ClientChannelManager.connect(ClientChannelManager.java:67) [stack-client-0.2.3.jar:0.2.3]
    at org.eclipse.milo.opcua.stack.client.UaTcpStackClient.connect(UaTcpStackClient.java:127) [stack-client-0.2.3.jar:0.2.3]
    at org.eclipse.milo.opcua.sdk.client.OpcUaClient.connect(OpcUaClient.java:312) [sdk-client-0.2.3.jar:0.2.3]
    at de.dlh.lht.ticc.esa.opcua.client.lib.LhtOpcUaClient.connect(LhtOpcUaClient.java:86) [classes/:?]
    at de.dlh.lht.ticc.esa.opcua.client.lib.TestTools.runWithCredentials(TestTools.java:41) [test-classes/:?]
    at de.dlh.lht.ticc.esa.opcua.client.lib.ConnectAgainstMiloServerTest.credentialsTest(ConnectAgainstMiloServerTest.java:48) [test-classes/:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_101]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_101]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_101]
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) [junit-4.12.jar:4.12]
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [junit-4.12.jar:4.12]
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) [junit-4.12.jar:4.12]
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) [junit-4.12.jar:4.12]
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) [junit-4.12.jar:4.12]
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363) [junit-4.12.jar:4.12]
    at org.junit.runner.JUnitCore.run(JUnitCore.java:137) [junit-4.12.jar:4.12]
    at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) [junit-rt.jar:?]
    at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) [junit-rt.jar:?]
    at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) [junit-rt.jar:?]
    at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) [junit-rt.jar:?]
17:28:18.367 [ua-shared-pool-0] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - Channel bootstrap failed: null
java.nio.channels.ClosedChannelException: null

de.dlh.lht.ticc.esa.opcua.client.lib.exceptions.ClientExecutionException: java.util.concurrent.ExecutionException: java.nio.channels.ClosedChannelException

    at de.dlh.lht.ticc.esa.opcua.client.lib.LhtOpcUaClient.connect(LhtOpcUaClient.java:88)
    at de.dlh.lht.ticc.esa.opcua.client.lib.TestTools.runWithCredentials(TestTools.java:41)
    at de.dlh.lht.ticc.esa.opcua.client.lib.ConnectAgainstMiloServerTest.credentialsTest(ConnectAgainstMiloServerTest.java:48)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
    at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
    at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
    at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
    at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
Caused by: java.util.concurrent.ExecutionException: java.nio.channels.ClosedChannelException
    at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
    at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
    at de.dlh.lht.ticc.esa.opcua.client.lib.LhtOpcUaClient.connect(LhtOpcUaClient.java:86)
    ... 24 more
Caused by: java.nio.channels.ClosedChannelException

Any idea?

This happens when I am using a certificate with private key as well as with username/password credentials. The server side logs

DEBUG o.e.m.o.s.s.h.UaTcpServerAsymmetricHandler - Received CloseSecureChannelRequest

so i think the client is the problem here. The same problem occurs with other opc-ua servers too.

EDIT: I created a minimal example where the error occures

package de.dlh.lht.ticc.esa.opcua.client.lib;

import org.eclipse.milo.opcua.sdk.client.OpcUaClient;
import org.eclipse.milo.opcua.sdk.client.api.config.OpcUaClientConfig;
import org.eclipse.milo.opcua.sdk.client.api.config.OpcUaClientConfigBuilder;
import org.eclipse.milo.opcua.sdk.client.api.identity.UsernameProvider;
import org.eclipse.milo.opcua.stack.client.UaTcpStackClient;
import org.eclipse.milo.opcua.stack.core.security.SecurityPolicy;
import org.eclipse.milo.opcua.stack.core.types.structured.EndpointDescription;
import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.util.Arrays;

public class SmokeTest {

    private static final Logger log = LoggerFactory.getLogger(SmokeTest.class);

    private static EndpointDescription getEndpointDescriptions(String endpoint, SecurityPolicy securityPolicy) throws Exception {

        EndpointDescription[] endpoints;

        try {
            endpoints = UaTcpStackClient
                    .getEndpoints(endpoint)
                    .get();
        } catch (Exception ex) {
            log.warn("failed to get endpoints", ex);
            log.warn("will try to explicitly discover endpoints");
            String discoveryUrl = endpoint + "/discovery";
            log.info("Trying explicit discovery URL: {}", discoveryUrl);
            endpoints = UaTcpStackClient
                    .getEndpoints(discoveryUrl)
                    .get();
        }
        EndpointDescription endpointDescription = Arrays.stream(endpoints)
                .filter(e -> e.getSecurityPolicyUri().equals(securityPolicy.getSecurityPolicyUri()))
                .findFirst().orElseThrow(() -> new Exception("no valid endpoint found for '" + endpoint + "'"));

        return endpointDescription;

    }

    @Test
    public void runTest() throws Exception {
        OpcUaClientConfigBuilder builder = OpcUaClientConfig.builder();
        EndpointDescription endpointDescription =
                getEndpointDescriptions("opc.tcp://127.0.0.1:12686/example", SecurityPolicy.Basic128Rsa15);

        builder
                .setEndpoint(endpointDescription);

        builder.setIdentityProvider(new UsernameProvider(
                "user",
                "password1"
        ));

        OpcUaClient client = new OpcUaClient(builder.build());
        client.connect().get();
        Thread.sleep(1000 * 10);
        client.disconnect().get();


    }

}

This test runs against the eclipse milo example server: https://github.com/eclipse/milo/blob/master/milo-examples/server-examples/src/main/java/org/eclipse/milo/examples/server/ExampleServer.java

Another update: what irritates me most is the following behavior

09:19:09.040 [ua-shared-pool-0] DEBUG org.eclipse.milo.opcua.stack.client.handlers.UaTcpClientMessageHandler - Received OpenSecureChannelResponse.
09:19:09.040 [ua-shared-pool-0] DEBUG org.eclipse.milo.opcua.stack.client.handlers.UaTcpClientMessageHandler - SecureChannel id=4, currentTokenId=4, previousTokenId=-1, lifetime=3600000ms, createdAt=DateTime{utcTime=131860523490250000, javaDate=Wed Nov 07 09:19:09 CET 2018}
09:19:09.040 [ua-netty-event-loop-0] DEBUG org.eclipse.milo.opcua.stack.client.handlers.UaTcpClientMessageHandler - 0 message(s) queued before handshake completed; sending now.
09:19:09.040 [ua-shared-pool-1] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - Channel bootstrap succeeded: localAddress=/127.0.0.1:50437, remoteAddress=/127.0.0.1:12686
09:19:09.134 [ua-shared-pool-0] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - disconnect(), currentState=Connected
09:19:09.134 [ua-shared-pool-1] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - Sending CloseSecureChannelRequest...

it seems that client connection succeeds, but then the client from the smoketest above imediately disconnects again by itself, which it does not do when using no SecurityPolicy.

Even weirder, after that, the log continues with:

09:28:12.283 [ua-netty-event-loop-0] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - channelInactive(), disconnect complete
09:28:12.283 [ua-netty-event-loop-0] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - disconnect complete, state set to Idle
09:28:12.299 [main] INFO  org.eclipse.milo.opcua.sdk.client.OpcUaClient - Eclipse Milo OPC UA Stack version: 0.2.4
09:28:12.299 [main] INFO  org.eclipse.milo.opcua.sdk.client.OpcUaClient - Eclipse Milo OPC UA Client SDK version: 0.2.4
09:28:12.315 [main] DEBUG org.eclipse.milo.opcua.sdk.client.OpcUaClient - Added ServiceFaultListener: org.eclipse.milo.opcua.sdk.client.session.SessionFsm$FaultListener@333d4a8c
09:28:12.330 [main] DEBUG org.eclipse.milo.opcua.sdk.client.OpcUaClient - Added SessionActivityListener: org.eclipse.milo.opcua.sdk.client.subscriptions.OpcUaSubscriptionManager$1@71687585
09:28:12.440 [main] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - connect(), currentState=NotConnected
09:28:12.440 [main] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - connect() while NotConnected
java.lang.Exception: null
    at org.eclipse.milo.opcua.stack.client.ClientChannelManager.connect(ClientChannelManager.java:67) [stack-client-0.2.4.jar:0.2.4]
    at org.eclipse.milo.opcua.stack.client.UaTcpStackClient.connect(UaTcpStackClient.java:127) [stack-client-0.2.4.jar:0.2.4]
    at org.eclipse.milo.opcua.sdk.client.OpcUaClient.connect(OpcUaClient.java:312) [sdk-client-0.2.4.jar:0.2.4]
    at de.dlh.lht.ticc.esa.opcua.client.lib.SmokeManualTest.run(SmokeManualTest.java:95) [test-classes/:?]
    at de.dlh.lht.ticc.esa.opcua.client.lib.SmokeManualTest.credentialsTest(SmokeManualTest.java:104) [test-classes/:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_101]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_101]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_101]
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) [junit-4.12.jar:4.12]
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [junit-4.12.jar:4.12]
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) [junit-4.12.jar:4.12]
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) [junit-4.12.jar:4.12]
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) [junit-4.12.jar:4.12]
    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) [junit-4.12.jar:4.12]
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) [junit-4.12.jar:4.12]
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) [junit-4.12.jar:4.12]
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363) [junit-4.12.jar:4.12]
    at org.junit.runner.JUnitCore.run(JUnitCore.java:137) [junit-4.12.jar:4.12]
    at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) [junit-rt.jar:?]
    at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) [junit-rt.jar:?]
    at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) [junit-rt.jar:?]
    at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) [junit-rt.jar:?]
09:28:12.440 [ua-shared-pool-0] DEBUG org.eclipse.milo.opcua.stack.client.ClientChannelManager - Channel bootstrap failed: null
java.nio.channels.ClosedChannelException: null

So it looks like the ClientChannelManager tries to connect after the disconnect it triggered by itself.

Another thing I tried was

builder.setCertificateValidator( new InsecureCertificateValidator());

assuming that the self-signed server cert is rejected, but it did not help. Not even the logging from that class is printed, so I assume the certificate validator is not called and the error happens even earlier.

Just for fun, i also added

static {
    CryptoRestrictions.remove();
    Security.addProvider(new BouncyCastleProvider());
}

to my smoke test. still no luck

Can you share a little bit of your client code? And which version of Milo are you using? — Kevin Herron, Nov 02 '18 at 17:01
0.2.3, i tried it with 0.2.4. today too, but it does not make a difference. i'll try to create a minimal example where the error occurs today — Magnus Lutz, Nov 05 '18 at 08:32
slowly i am running out of ideas, but i added much more of the things i found out since two days ago to the question. See anything obvious maybe @KevinHerron ? Still hoping that i just forgot to give something to one of the builder setters that is security related. Do I have to provide the SecurityPolicy somewhere apart from filtering the endpoints by myself? — Magnus Lutz, Nov 07 '18 at 08:45
ok, one more update, i start thinking that my error is simply thinking one cert is enough, but as you described in https://stackoverflow.com/questions/46411925/understanding-opc-ua-security-using-eclipse-milo there seems to be one cert required for authentication and one for encrypted message transfer that has to match the application uri of the client. ill try that out — Magnus Lutz, Nov 07 '18 at 11:47

score 1 · Accepted Answer · answered Nov 07 '18 at 13:19

Of course it was a quite simple issue. The other errors in the log did not have that much to do with it.

Having another look into Understanding OPC-UA Security using Eclipse Milo helped quite much.

See, you always need an application certificate when using a SecurityPolicy that is not "None" as that certificate is used for message encryption and signing. It is also a somewhat special certificate, since it contains an application uri that must match the application uri that you configure for your client via builder.setApplicationUri()

When using authentication via certificate, you provide a second certificate (and private key) which is used to confirm your identity at the server. Thats also the reason why you can authenticate via cert or username/password while having no message encryption and signing at all

Eclipse Milo - ClosedChannelException when using SecurityPolicy

1 Answers1