search

apache / plc4x

PLC4X The Industrial IoT adapter
https://plc4x.apache.org/
Apache License 2.0
1.26k stars 401 forks source link

[Bug]: Secure channel does not automatically reestablish after its lifetime expires. #1732

Closed gustavoschewinski closed 1 month ago

gustavoschewinski commented 1 month ago

What happened?

I'm experiencing an issue where a secure channel is not reestablished after reaching channel lifetime limit while using PLC4Xj with certificates for both the client and server. The initial connection works perfectly, with a secure channel being established and data being received via OPC UA. However, once the channel's lifetime expires, it closes and is not automatically reestablished.

I've read that simply increasing the channel lifetime indefinitely is not a viable solution. I also attempted to use tcp.keep-alive=true, but this did not resolve the issue.

Is there a solution or configuration that I might be overlooking to address this problem?

Additional Information:

Here is the connection string I'm using:

String username = "admin";
String password = "admin";
String securityPolicy = "Basic256Sha256";
String keyStoreFile = "/home/digilab/help/test2/demo_2/test/client/client_cert.p12";
String serverCertificate = "/home/digilab/help/test2/demo_2/test/SimulationServer@Yoshi_2048.der";
String keyStorePassword = "gustavo";
String messageSecurity = "SIGN_ENCRYPT";

String connectionString = String.format("opcua:tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer?discovery=false");

connectionString += (username.isBlank()) ? "" : String.format("&username=%s", username);
connectionString += (password.isBlank()) ? "" : String.format("&password=%s", password);
connectionString += (securityPolicy.isBlank()) ? "" : String.format("&security-policy=%s", securityPolicy);
connectionString += (messageSecurity.isBlank()) ? "" : String.format("&message-security=%s", messageSecurity);
connectionString += (serverCertificate.isBlank()) ? "" : String.format("&server-certificate-file=%s", serverCertificate);
connectionString += (keyStoreFile.isBlank()) ? "" : String.format("&key-store-file=%s", keyStoreFile);
connectionString += (keyStorePassword.isBlank()) ? "" : String.format("&key-store-password=%s", keyStorePassword);
connectionString += String.format("&channel-lifetime=%d", 3600000);
connectionString += "&tcp.keep-alive=true";

Maybe it is related to https://github.com/apache/plc4x/pull/1684?

Is there a configuration setting or a different approach that can help with automatically reestablishing the secure channel once it closes?

Thanks!

Best, Gustavo.

Version

v.0.12.0

Programming Languages

Protocols

splatch commented 1 month ago

I believe this report is duplicate of #1364, which was fixed via #1684. Can you check if issue remains with 0.13-SNAPSHOT?

gustavoschewinski commented 1 month ago

Hi @splatch,

Thanks a lot for your help—I really appreciate it.

I suspected the issue might be the same, so I'm using the 0.13-SNAPSHOT version for everything, but still didn't make any difference.

<dependency>
    <groupId>org.apache.plc4x</groupId>
    <artifactId>plc4j-api</artifactId>
    <version>0.13.0-SNAPSHOT</version>
</dependency>
<dependency>
    <groupId>org.apache.plc4x</groupId>
    <artifactId>plc4j-driver-opcua</artifactId>
    <version>0.13.0-SNAPSHOT</version>
</dependency>
<dependency>
      <groupId>org.apache.plc4x</groupId>
      <artifactId>plc4j-transport-tcp</artifactId>
      <version>0.13.0-SNAPSHOT</version>
</dependency>

I have a few other ideas that might be causing the problem, so I’ll share all the information I’ve gathered:

  1. The issue always occurs when the channel lifetime is about to expire, and the secure channel should be renewed. For example, when I set the channel lifetime to 1 minute, the problem occurs within that 1-minute period. This is one reason I believe it’s not related to resource leaks, as mentioned in this issue.

As mentioned earlier, I tried adding tcp.keep-alive in hopes of facilitating the reconnection, but it’s still not working. Unfortunately, I’m still unable to pinpoint where the error is coming from.

  1. When I check the Prosys OPCUA simulator logs, I can see that it doesn’t attempt to renew the connection; instead, it just closes the channel. Do I need to enable something in the simulator? I’m attaching the logs for your reference.
08/21/2024 09:27:55.596 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-2]      com.prosysopc.ua.stack.transport.tcp.nio.f  [] - OpcTcpServer(opc.tcp(/[0:0:0:0:0:0:0:0]:53530, (opc.tcp://Yoshi.lab.mtu-digilab.io:53530 [[http://opcfoundation.org/UA/SecurityPolicy#None,None]])(opc.tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer [[http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256,SignAndEncrypt]]))): /10.1.10.92:47938 connected
08/21/2024 09:27:56.502 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-4]      com.prosysopc.ua.stack.transport.tcp.nio.f  [] - OpcTcpServer(opc.tcp(/[0:0:0:0:0:0:0:0]:53530, (opc.tcp://Yoshi.lab.mtu-digilab.io:53530 [[http://opcfoundation.org/UA/SecurityPolicy#None,None]])(opc.tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer [[http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256,SignAndEncrypt]]))): /10.1.10.92:47950 connected
08/21/2024 09:27:57.376 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.432 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.444 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.451 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.460 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - Certificate '332E73BEB6F91AD8A6779EDB866FDFE332F3DE09' added to trusted certificates.
08/21/2024 09:27:57.486 INFO  [OPC-UA-Stack-Blocking-Work-Executor-1]      com.prosysopc.ua.stack.transport.tcp.nio.h  [] - SecureChannel opened; SecurityToken(Id=1, secureChannelId=1, creationTime=21.08.2024, 09:27:57, lifetime=50000)
08/21/2024 09:27:57.759 INFO  [OPC-UA-Stack-Blocking-Work-Executor-2]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.765 INFO  [OPC-UA-Stack-Blocking-Work-Executor-2]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.769 INFO  [OPC-UA-Stack-Blocking-Work-Executor-2]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.775 INFO  [OPC-UA-Stack-Blocking-Work-Executor-2]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:27:57.777 INFO  [OPC-UA-Stack-Blocking-Work-Executor-2]                   com.prosysopc.ua.stack.cert.d  [] - Certificate '332E73BEB6F91AD8A6779EDB866FDFE332F3DE09' added to trusted certificates.
08/21/2024 09:27:57.800 INFO  [OPC-UA-Stack-Blocking-Work-Executor-2]                      com.prosysopc.ua.server.ab  [] - Session created: UaSession:OPCUA client for the Apache PLC4X:PLC4J project:dzQ381Tfp8FvZtKLUZ11 (ID=ns=1;g=e6b02fa6-6e6a-4aa6-b3e8-4e986030ae9e Token=b=F/3BaxFLVRA/5jaBUaZB+7ooRmFWFn3BOACcoOJVC4Q= Channel=(SecureChannelId=1 State=Open URL=opc.tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer SecurityPolicy=http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256 RemoteAddress=/10.1.10.92:47950))
08/21/2024 09:27:58.107 INFO  [OPC-UA-Stack-Blocking-Work-Executor-4]                      com.prosysopc.ua.server.ab  [] - Session activated: UaSession:OPCUA client for the Apache PLC4X:PLC4J project:dzQ381Tfp8FvZtKLUZ11 (ID=ns=1;g=e6b02fa6-6e6a-4aa6-b3e8-4e986030ae9e Token=b=F/3BaxFLVRA/5jaBUaZB+7ooRmFWFn3BOACcoOJVC4Q= Channel=(SecureChannelId=1 State=Open URL=opc.tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer SecurityPolicy=http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256 RemoteAddress=/10.1.10.92:47950))
08/21/2024 09:28:35.814 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:28:35.820 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:28:35.826 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:28:35.831 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - CRL initialized from C:\Users\gustavo.schewinski\.prosysopc\prosys-opc-ua-simulation-server\PKI\CA\issuers\crl\ca.crl: no revoked certificates
08/21/2024 09:28:35.832 INFO  [OPC-UA-Stack-Non-Blocking-Work-Executor-8]                   com.prosysopc.ua.stack.cert.d  [] - Certificate '332E73BEB6F91AD8A6779EDB866FDFE332F3DE09' added to trusted certificates.
08/21/2024 09:28:35.837 INFO  [OPC-UA-Stack-Blocking-Work-Executor-14]      com.prosysopc.ua.stack.transport.tcp.nio.h  [] - Secure Channel closed, token=SecurityToken(Id=1, secureChannelId=1, creationTime=21.08.2024, 09:27:57, lifetime=50000)
08/21/2024 09:28:35.838 INFO  [OPC-UA-Stack-Blocking-Work-Executor-14]            com.prosysopc.ua.stack.transport.a.a  [] - Channel closed: Id=1
  1. Below is the full code I’m using to establish the connection and retrieve data. Perhaps I’m missing some important configuration:
import org.apache.plc4x.java.DefaultPlcDriverManager;
import org.apache.plc4x.java.api.PlcConnection;
import org.apache.plc4x.java.api.messages.PlcReadRequest;
import org.apache.plc4x.java.api.messages.PlcReadResponse;
import java.util.concurrent.TimeUnit;

public class App {
    public static void main(String[] args) {
        DefaultPlcDriverManager driverManager = new DefaultPlcDriverManager();

        String username = "admin";
        String password = "admin";
        String securityPolicy = "Basic256Sha256";
        String keyStoreFile = "/home/digilab/help/test2/demo_2/test/client/client_cert.p12";
        String serverCertificate = "/home/digilab/help/test2/demo_2/test/SimulationServer@Yoshi_2048.der";
        String keyStorePassword = "gustavo";
        String messageSecurity = "SIGN_ENCRYPT";

        String connectionString = String.format(
            "opcua:tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer?discovery=false"
        );

        connectionString += !username.isBlank() ? String.format("&username=%s", username) : "";
        connectionString += !password.isBlank() ? String.format("&password=%s", password) : "";
        connectionString += !securityPolicy.isBlank() ? String.format("&security-policy=%s", securityPolicy) : "";
        connectionString += !messageSecurity.isBlank() ? String.format("&message-security=%s", messageSecurity) : "";
        connectionString += !serverCertificate.isBlank() ? String.format("&server-certificate-file=%s", serverCertificate) : "";
        connectionString += !keyStoreFile.isBlank() ? String.format("&key-store-file=%s", keyStoreFile) : "";
        connectionString += !keyStorePassword.isBlank() ? String.format("&key-store-password=%s", keyStorePassword) : "";
        connectionString += String.format("&tcp.keep-alive=%b", true);
        connectionString += String.format("&channel-lifetime=%d", 50000);

        System.out.println("Connection String: " + connectionString);

        try (PlcConnection plcConnection = driverManager.getConnection(connectionString)) {
            System.out.println("Connected to the server");
            System.out.println("Connection metadata: " + plcConnection.getMetadata());

            while (true) {
                PlcReadRequest.Builder builder = plcConnection.readRequestBuilder();
                System.out.println("Builder: " + builder);
                System.out.println("Builder: " + builder.getClass());
                System.out.println("Builder: " + plcConnection);

                builder.addTagAddress("constant", "ns=3;i=1002");
                PlcReadRequest readRequest = builder.build();
                PlcReadResponse response = readRequest.execute().get(5000, TimeUnit.MILLISECONDS);

                for (String tagName : response.getTagNames()) {
                    System.out.println("Value[" + tagName + "]: " + response.getObject(tagName));
                }

                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        } catch (Exception e) {
            System.out.println("" + e);
        }
    }
}
  1. The PLC4x Java logs don’t indicate any issues. Since the logs are quite extensive, I’m attaching them in case you might know where to look.

java_log.txt

but we can see when it enters the stall mode in here:

09:24:16.254 [plc4x-tm-thread-3] DEBUG org.apache.plc4x.java.opcua.context.Conversation - Submitting Transaction to TransactionManager 41, security channel 8, token 1
09:23:15.300 [nioEventLoopGroup-3-1] DEBUG org.apache.plc4x.java.opcua.context.Conversation - Received response made of 66 bytes for message id: 39, channel id:8, token:1
09:23:16.146 [plc4x-tm-thread-2] DEBUG org.apache.plc4x.java.opcua.context.SecureChannel - Sending open secure channel message to opc.tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer

That's all. Thank again for your support! I hope we can find a solution together

Best, Gustavo.

splatch commented 1 month ago

Hello Gustavo, Configuration looks ok. I've tested renew logic against prosys and s7, and it worked in my case. I will check using Basic256Sha256 to see if issue is reproducible.

gustavoschewinski commented 1 month ago

Hi @splatch,

Which security policy you're currently using? If you have any suggestions, I could try them out to help identify the issue.

Best, Gustavo

splatch commented 1 month ago

I usually test basic128, however you can give a spin to mix of security modes and see if security mode=none and message security=none makes any difference. There are some aspects of nonce management which might be softened by server if you use anonymous authentication with no security. I've recently found that in some cases our client can't negotiate session with node-opcua based server which means we still have some gaps in coverage of specs.

gustavoschewinski commented 1 month ago

Hi @splatch,

It is interesting because when I set both NONE for security, I’m also having the same problem. So, it doesn’t seem to be a certificate security issue, which is really strange.

Which Prosys version are you using? If my code is correct, I suspect it could be something related to the simulator.

Here’s what I did:

String messageSecurity = "NONE";
String securityPolicy = "NONE";

String connectionString = String.format("opcua:tcp://Yoshi.lab.mtu-digilab.io:53530/OPCUA/SimulationServer?discovery=false");
connectionString += (securityPolicy.isBlank()) ? "" : String.format("&security-policy=%s", securityPolicy);
connectionString += (messageSecurity.isBlank()) ? "" : String.format("&message-security=%s", messageSecurity);
connectionString += String.format("&channel-lifetime=%d", 20000);
splatch commented 1 month ago

I'm on v5.4.6-148. Anyhow, will try to test to see what's going on. If session dies around lifetime its definitely related to the token renewal.

gustavoschewinski commented 1 month ago

Hi @splatch,

I'm also using the same version of Prosys. I also just tried connecting PLC4x to a Python OPC UA server with no security, and it worked well without any channel lifetime issues, even with a channel lifetime set to 10 seconds.

I'm curious about how your setup with Prosys is configured. Are you using any security settings? And are you using a short channel lifetime to test the token renewal?

Thanks so much for your assistance!

gustavoschewinski commented 1 month ago

Hi @splatch,

I used Wireshark to intercept the communication between the Client and Server and identified an issue. I may be forgetting to configure something properly. Here's the relevant log:

-------
1593 31.497876 10.1.10.84 10.1.10.92 OpcUa 120 **UA Secure Conversation Message: ReadResponse**
Frame 1593: 120 bytes on wire (960 bits), 120 bytes captured (960 bits) on interface \Device\NPF_{6839540B-0248-4AF4-B69B-804BBD4B9E58}, id 0
Ethernet II, Src: ASUSTekCOMPU_11:8b:55 (fc:34:97:11:8b:55), Dst: ProxmoxServe_6c:38:01 (bc:24:11:6c:38:01)
Internet Protocol Version 4, Src: 10.1.10.84, Dst: 10.1.10.92
Transmission Control Protocol, Src Port: 53530, Dst Port: 58392, Seq: 23338, Ack: 3608, Len: 66
    Source Port: 53530
    Destination Port: 58392
    [Stream index: 12]
    [Conversation completeness: Complete, WITH_DATA (31)]
    [TCP Segment Len: 66]
    Sequence Number: 23338 (relative sequence number)
    Sequence Number (raw): 3843291716
    [Next Sequence Number: 23404 (relative sequence number)]
    Acknowledgment Number: 3608 (relative ack number)
    Acknowledgment number (raw): 3854563992
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x018 (PSH, ACK)
    Window: 8210
    [Calculated window size: 2101760]
    [Window size scaling factor: 256]
    Checksum: 0x290e [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
    [SEQ/ACK analysis]
    TCP payload (66 bytes)
    [PDU Size: 66]
OpcUa Binary Protocol
    Message Type: MSG
    Chunk Type: F
    Message Size: 66
    SecureChannelId: 5
    Security Token Id: 1
    Security Sequence Number: 103
    Security RequestId: 25
    OpcUa Service: Encodeable Object
-------

1625 32.140503 10.1.10.92 10.1.10.84 OpcUa 223 **OpenSecureChannel message: OpenSecureChannelRequest**
Frame 1625: 223 bytes on wire (1784 bits), 223 bytes captured (1784 bits) on interface \Device\NPF_{6839540B-0248-4AF4-B69B-804BBD4B9E58}, id 0
Ethernet II, Src: ProxmoxServe_6c:38:01 (bc:24:11:6c:38:01), Dst: ASUSTekCOMPU_11:8b:55 (fc:34:97:11:8b:55)
Internet Protocol Version 4, Src: 10.1.10.92, Dst: 10.1.10.84
Transmission Control Protocol, Src Port: 58392, Dst Port: 53530, Seq: 3608, Ack: 23404, Len: 169
    Source Port: 58392
    Destination Port: 53530
    [Stream index: 12]
    [Conversation completeness: Complete, WITH_DATA (31)]
    [TCP Segment Len: 169]
    Sequence Number: 3608 (relative sequence number)
    Sequence Number (raw): 3854563992
    [Next Sequence Number: 3777 (relative sequence number)]
    Acknowledgment Number: 23404 (relative ack number)
    Acknowledgment number (raw): 3843291782
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x018 (PSH, ACK)
    Window: 501
    [Calculated window size: 64128]
    [Window size scaling factor: 128]
    Checksum: 0x896c [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
    [SEQ/ACK analysis]
    TCP payload (169 bytes)
    [PDU Size: 169]
OpcUa Binary Protocol
    Message Type: OPN
    Chunk Type: F
    Message Size: 169
    SecureChannelId: 0
    SecurityPolicyUri: http://opcfoundation.org/UA/SecurityPolicy#None
    SenderCertificate: <MISSING>[OpcUa Null ByteString]
    ReceiverCertificateThumbprint: <MISSING>[OpcUa Null ByteString]
    SequenceNumber: 26
    RequestId: 26
    Message: Encodeable Object
-------

1626 32.140956 10.1.10.84 10.1.10.92 **OpcUa 178 Error message**
Frame 1626: 178 bytes on wire (1424 bits), 178 bytes captured (1424 bits) on interface \Device\NPF_{6839540B-0248-4AF4-B69B-804BBD4B9E58}, id 0
Ethernet II, Src: ASUSTekCOMPU_11:8b:55 (fc:34:97:11:8b:55), Dst: ProxmoxServe_6c:38:01 (bc:24:11:6c:38:01)
Internet Protocol Version 4, Src: 10.1.10.84, Dst: 10.1.10.92
Transmission Control Protocol, Src Port: 53530, Dst Port: 58392, Seq: 23404, Ack: 3777, Len: 124
    Source Port: 53530
    Destination Port: 58392
    [Stream index: 12]
    [Conversation completeness: Complete, WITH_DATA (31)]
    [TCP Segment Len: 124]
    Sequence Number: 23404 (relative sequence number)
    Sequence Number (raw): 3843291782
    [Next Sequence Number: 23528 (relative sequence number)]
    Acknowledgment Number: 3777 (relative ack number)
    Acknowledgment number (raw): 3854564161
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x018 (PSH, ACK)
    Window: 8210
    [Calculated window size: 2101760]
    [Window size scaling factor: 256]
    Checksum: 0x2948 [unverified]
    [Checksum Status: Unverified]
    Urgent Pointer: 0
    [Timestamps]
    [SEQ/ACK analysis]
    TCP payload (124 bytes)
    [PDU Size: 124]
OpcUa Binary Protocol
    Message Type: ERR
    Chunk Type: F
    Message Size: 124
    Error: 0x80220000 [BadSecureChannelIdInvalid]
    Reason: Bad_SecureChannelIdInvalid (code=0x80220000, description="The specified secure channel is no longer valid.")

From the first log, it appears that the communication occurs normally until the final message, where a new channel is attempted, but the process encounters a Bad_SecureChannelIdInvalid error. If you look closely, the last message uses SecureChannelId: 5 in the OpcUa binary protocol, but the subsequent request has SecureChannelId: 0, leading to this error.

This issue seems similar to https://github.com/apache/plc4x/issues/1213. I had already taken that into consideration and used the plc4j-transport-tcp with 0.13.0-SNAPSHOT, and I have enabled tcp.keep-alive. However, it didn't help at all.

Can you identify and issue or a potential solution?

Thanks for your help!

Best regards,
Gustavo

splatch commented 1 month ago

From the first log, it appears that the communication occurs normally until the final message, where a new channel is attempted, but the process encounters a Bad_SecureChannelIdInvalid error. If you look closely, the last message uses SecureChannelId: 5 in the OpcUa binary protocol, but the subsequent request has SecureChannelId: 0, leading to this error.

The tcp keep alive won't help in this case, transport level communication is fine, so all packets are flying both directions. Issue comes from application protocol and some gap in our implementation of security protocol. Below quote from the the spec:

requestType: The type of SecurityToken request: An enumeration that shall be one of the following:

  • ISSUE_0 creates a new SecurityToken for a new SecureChannel
  • RENEW_1 creates a new SecurityToken for an existing SecureChannel secureChannelId: The identifier for the SecureChannel that the new token should belong to. This parameter shall be null when creating a new SecureChannel.

This means that for initial (issue) call, we send 0 for secure channel id, while for renewing we need to send id of channel we got earlier (you will find it in open secure channel response). I can just assume that secure channel 5 was negotiated earlier. I looked at code while writing answer, and this part of specification is satisfied.

gustavoschewinski commented 1 month ago

Hi @splatch,

Exactly, that is the issue.

In frame 1539, we can see that the SecureChannel ID is 5. However, when the client tries to renew the SecureChannel in frame 1625, it uses 0 as the SecureChannel ID instead of 5. As I understood, it should be only zero when issuing a new SecureChannel, and that's not the case here.

Is there a way to fix this?

Thanks for all you support in this!

splatch commented 1 month ago

You need to have a look inside org.apache.plc4x.java.opcua.context.SecureChannel#renewToken. I believe that you might be still using 0.12, cause this was essentially fix provided in PR we discussed few comments above. Just open secure channel class and check if line 470 looks like this: onConnectOpenSecureChannel(SecurityTokenRequestType.securityTokenRequestTypeRenew, securityChannelId, requestId)

gustavoschewinski commented 1 month ago

Hi @splatch,

It turns out the issue was related to the version of PLC4x. It’s strange because it seemed like the system was caching the old version instead of using the new one, even though the dependency tree showed the correct version.

Here’s what I did to resolve the problem:

mvn clean
mvn dependency:purge-local-repository  #(this step was crucial!)
mvn install

Thanks so much for all your help!

splatch commented 1 month ago

@gustavoschewinski You're welcome, glad you got it covered. Tooling we use sometimes make things harder.

Enjoy OPC-UA! :-)