Connecting to a server with certificate RSA (4096 Bits)

I try to connect to a server (Softing OPC UA Toolkit) with a certificate with public key length of 4096 Bits, it always returns BadInvalidArgrument when OpenSecureChannelRequest is send from client.

If I change the certficate to a certificate with RSA Keylength of 2048, everything works. Tried following security polices: Basic256Sha256, Aes256Sha256RsaPss, Aes128Sha256RsaOaep all have the same problem.

It might be a chunk size issue, or an issue with the keylength itself.

The code does enforce key sizes in security_policy.rs, is_valid_keylength() but only according to the spec, so Basic256Sha256, Aes256_Sha256_RsaPss and Aes128_Sha256_RsaOaep should accept key lengths between 2048 & 4096.

The other option is perhaps there is some kind of chunking issue on the server.

If you have logging enabled (e.g. setting RUST_OPCUA_LOG=debug when you have the console logger setup), then you should capture the debug level to see if you can isolate if the client is complaining about the handshake for a more specific reason than BadInvalidArgument.

I attached the log, but the server only response with BadInvalidArgument. If I have time I will try to test it against an open62451 server with a rsa 4096 cert.

Here is the log:

05:45:07 [WARN] Endpoint config contains no endpoints
05:45:07 [INFO] Connect
05:45:07 [INFO] Security policy = None
05:45:07 [INFO] Security mode = None
05:45:07 [DEBUG] (1) opcua_client::comms::tcp_transport: Creating a connection task to connect to [::1]:4840 with url opc.tcp://localhost:4840/
05:45:07 [DEBUG] (1) opcua_core::runtime: registering component connection-task, 1
05:45:07 [DEBUG] (1) opcua_client::comms::tcp_transport: Waiting for a connect (or failure to connect)
05:45:07 [DEBUG] (2) opcua_client::comms::tcp_transport: Client tokio tasks are starting for connection
05:45:07 [DEBUG] (2) opcua_core::runtime: registering component client-connection-thread-ThreadId(2)
05:45:07 [DEBUG] (3) opcua_client::comms::tcp_transport: Sending HELLO
05:45:07 [DEBUG] (3) opcua_core::runtime: registering component finished-monitor-task, 1
05:45:07 [DEBUG] (3) opcua_core::runtime: registering component read-task, 1
05:45:07 [DEBUG] (3) opcua_core::runtime: registering component write-task, 1
05:45:07 [DEBUG] (3) opcua_core::runtime: deregistering component connection-task, 1
05:45:07 [DEBUG] (5) opcua_client::comms::tcp_transport: Reader got ack AcknowledgeMessage { message_header: MessageHeader { message_type: Acknowledge, message_size: 28 }, protocol_version: 0, receive_buffer_size: 65536, send_buffer_size: 65536, max_message_size: 65536, max_chunk_count: 0 }
05:45:07 [DEBUG] (1) opcua_client::comms::tcp_transport: Connected
05:45:07 [DEBUG] (1) opcua_client::session: session:1 open_secure_channel
05:45:07 [INFO] Making secure channel request
05:45:07 [INFO] security_mode = None
05:45:07 [INFO] security_policy = None
05:45:07 [DEBUG] (4) opcua_client::comms::tcp_transport: About to write
05:45:07 [DEBUG] (4) opcua_core::comms::secure_channel: AsymmetricSecurityHeader = AsymmetricSecurityHeader { security_policy_uri: UAString { value: Some("http://opcfoundation.org/UA/SecurityPolicy#None") }, sender_certificate: ByteString { value: None }, receiver_certificate_thumbprint: ByteString { value: None } }
05:45:07 [DEBUG] (4) opcua_client::message_queue: Request 1 was processed by the server
05:45:07 [DEBUG] (4) opcua_client::message_queue: Response to Request 1 has been stored
05:45:08 [DEBUG] (1) opcua_client::session_state: Client offset set to -PT0.049072800S
05:45:08 [DEBUG] (1) opcua_client::session_state: Setting transport's security token
05:45:08 [INFO] Connect was successful
05:45:08 [DEBUG] (1) opcua_client::session: session:1 get_endpoints
05:45:08 [DEBUG] (5) opcua_client::comms::tcp_transport: About to write
05:45:08 [DEBUG] (5) opcua_client::message_queue: Request 2 was processed by the server
05:45:08 [DEBUG] (5) opcua_client::message_queue: Response to Request 2 has been stored
05:45:08 [DEBUG] (1) opcua_client::session: session:1 get_endpoints, success
05:45:08 [DEBUG] (1) opcua_client::message_queue: Sending a quit to the message receiver
05:45:08 [DEBUG] (1) opcua_client::comms::tcp_transport: Waiting for a disconnect
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: About to write
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: Writer is about to send a CloseSecureChannelRequest which means it should close in a moment
05:45:08 [DEBUG] (4) opcua_client::message_queue: Request 3 was processed by the server
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: Writer is setting the connection state to finished(good)
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: Write bytes task received a close, so closing connection after this send
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: Writer loop is finished with an error
05:45:08 [DEBUG] (4) opcua_core::runtime: deregistering component write-task, 1
05:45:08 [INFO] WriteState has dropped
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: Read loop is terminating due to finished state
05:45:08 [INFO] ReadState has dropped
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: Read loop ended with an error
05:45:08 [DEBUG] (4) opcua_core::runtime: deregistering component read-task, 1
05:45:08 [DEBUG] (4) opcua_client::comms::tcp_transport: finished monitor task detects finished state and has set a finished flag
05:45:08 [INFO] Timer for finished is finished
05:45:08 [DEBUG] (4) opcua_core::runtime: deregistering component finished-monitor-task, 1
05:45:08 [DEBUG] (2) opcua_client::comms::tcp_transport: Client tokio tasks have stopped for connection
05:45:08 [DEBUG] (2) opcua_client::session_state: Session was closed with status = BadCommunicationError
05:45:08 [DEBUG] (2) opcua_core::runtime: deregistering component client-connection-thread-ThreadId(2)
05:45:08 [DEBUG] (1) opcua_client::comms::tcp_transport: Disconnected
05:45:08 [INFO] Session has dropped
05:45:08 [INFO] TcpTransport has dropped
05:45:08 [INFO] SessionState has dropped
05:45:08 [INFO] Connect
05:45:08 [INFO] Security policy = Basic256Sha256
05:45:08 [INFO] Security mode = SignAndEncrypt
05:45:08 [DEBUG] (1) opcua_client::comms::tcp_transport: Creating a connection task to connect to [::1]:4840 with url opc.tcp://localhost:4840/
05:45:08 [DEBUG] (1) opcua_core::runtime: registering component connection-task, 2
05:45:08 [DEBUG] (1) opcua_client::comms::tcp_transport: Waiting for a connect (or failure to connect)
05:45:08 [DEBUG] (7) opcua_client::comms::tcp_transport: Client tokio tasks are starting for connection
05:45:08 [DEBUG] (7) opcua_core::runtime: registering component client-connection-thread-ThreadId(7)
05:45:08 [DEBUG] (8) opcua_client::comms::tcp_transport: Sending HELLO
05:45:08 [DEBUG] (8) opcua_core::runtime: registering component finished-monitor-task, 2
05:45:08 [DEBUG] (8) opcua_core::runtime: registering component read-task, 2
05:45:08 [DEBUG] (8) opcua_core::runtime: registering component write-task, 2
05:45:08 [DEBUG] (8) opcua_core::runtime: deregistering component connection-task, 2
05:45:08 [DEBUG] (8) opcua_client::comms::tcp_transport: Reader got ack AcknowledgeMessage { message_header: MessageHeader { message_type: Acknowledge, message_size: 28 }, protocol_version: 0, receive_buffer_size: 65536, send_buffer_size: 65536, max_message_size: 65536, max_chunk_count: 0 }
05:45:08 [DEBUG] (1) opcua_client::comms::tcp_transport: Connected
05:45:08 [DEBUG] (1) opcua_client::session: session:2 open_secure_channel
05:45:08 [INFO] Making secure channel request
05:45:08 [INFO] security_mode = SignAndEncrypt
05:45:08 [INFO] security_policy = Basic256Sha256
05:45:08 [DEBUG] (8) opcua_client::comms::tcp_transport: About to write
05:45:08 [DEBUG] (8) opcua_core::comms::secure_channel: AsymmetricSecurityHeader = AsymmetricSecurityHeader { security_policy_uri: UAString { value: Some("http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256") }, sender_certificate: ByteString { value: Some([...]) }, receiver_certificate_thumbprint: ByteString { value: Some([47, 128, 31, 198, 66, 94, 240, 145, 132, 47, 46, 207, 139, 2, 78, 56, 82, 27, 158, 64]) } }
05:45:08 [DEBUG] (8) opcua_client::message_queue: Request 1 was processed by the server
05:45:08 [ERROR] Expecting a chunk, got an error message BadInvalidArgument
05:45:08 [ERROR] Reader is putting connection into a finished state with status BadInvalidArgument
05:45:08 [DEBUG] (11) opcua_client::comms::tcp_transport: Reader is sending a quit to the writer
05:45:08 [ERROR] Read loop error Kind(ConnectionReset)
05:45:08 [INFO] ReadState has dropped
05:45:08 [DEBUG] (11) opcua_client::comms::tcp_transport: Read loop ended with an error
05:45:08 [DEBUG] (11) opcua_core::runtime: deregistering component read-task, 2
05:45:08 [DEBUG] (8) opcua_client::comms::tcp_transport: Write task received a quit
05:45:08 [DEBUG] (8) opcua_client::comms::tcp_transport: Writer loop is finished
05:45:08 [DEBUG] (8) opcua_core::runtime: deregistering component write-task, 2
05:45:08 [INFO] WriteState has dropped
05:45:08 [DEBUG] (9) opcua_client::comms::tcp_transport: finished monitor task detects finished state and has set a finished flag
05:45:08 [INFO] Timer for finished is finished
05:45:08 [DEBUG] (9) opcua_core::runtime: deregistering component finished-monitor-task, 2
05:45:08 [DEBUG] (7) opcua_client::comms::tcp_transport: Client tokio tasks have stopped for connection

Against an the open62451 example server_encryption.exe with an rsa 4096 cert i get the following log, looks like the padding is wrong.

[2021-06-23 11:13:32.587 (UTC+0200)] warn/server        AccessControl: Unconfigured AccessControl. Users have all permissions.
[2021-06-23 11:13:32.588 (UTC+0200)] info/server        AccessControl: Anonymous login is enabled
[2021-06-23 11:13:32.595 (UTC+0200)] info/network       TCP network layer listening on opc.tcp://PC001619D:4840/
[2021-06-23 11:17:12.880 (UTC+0200)] info/network       Connection 548 | New connection over TCP from ::1
[2021-06-23 11:17:12.979 (UTC+0200)] info/channel       Connection 548 | SecureChannel 1 | SecureChannel opened with SecurityPolicy http://opcfoundation.org/UA/SecurityPolicy#None and a revised lifetime of 60.00s
[2021-06-23 11:17:13.081 (UTC+0200)] info/channel       Connection 548 | SecureChannel 1 | CloseSecureChannel
[2021-06-23 11:17:13.081 (UTC+0200)] info/network       Connection 548 | Closed
[2021-06-23 11:17:13.185 (UTC+0200)] info/network       Connection 248 | New connection over TCP from ::1
[2021-06-23 11:17:13.408 (UTC+0200)] warn/channel       Connection 248 | SecureChannel 0 | Impossible padding value
[2021-06-23 11:17:13.408 (UTC+0200)] info/network       Connection 248 | Processing the message failed with error BadSecurityChecksFailed
[2021-06-23 11:17:13.410 (UTC+0200)] info/network       Connection 248 | Closed

Maybe it has something to do with ExtraPaddingSize parameter of MessageChunk Footer:

ExtraPaddingSize: The most significant byte of a two-byte integer used to specify the padding size when the key used to encrypt the message chunk is larger than 2 048 bits. This field is omitted if the key length is less than or equal to 2 048 bits.

The open62541 log with fulltrace, they assume the padding is 20048 bits:

[2021-06-23 11:42:07.724 (UTC+0200)] trace/network      Connection 156 | Activity on the socket
[2021-06-23 11:42:07.725 (UTC+0200)] trace/network      Connection 156 | Received a packet.
[2021-06-23 11:42:07.725 (UTC+0200)] trace/channel      Connection 156 | SecureChannel 1 | Generating new local keys
[2021-06-23 11:42:07.727 (UTC+0200)] trace/channel      Connection 156 | SecureChannel 1 | Generating new remote keys
[2021-06-23 11:42:07.728 (UTC+0200)] trace/channel      Connection 156 | SecureChannel 1 | Process a MSG
[2021-06-23 11:42:07.729 (UTC+0200)] debug/session      SecureChannel 1 | Session g=00000000-0000-0000-0000-000000000000 | Processing GetEndpointsRequest with endpointUrl "opc.tcp://localhost:4840/"
[2021-06-23 11:42:07.730 (UTC+0200)] debug/session      SecureChannel 1 | Session g=00000000-0000-0000-0000-000000000000 | Sending response for RequestId 1002 of type GetEndpointsResponse
[2021-06-23 11:42:07.733 (UTC+0200)] trace/channel      Connection 156 | SecureChannel 1 | Send from a symmetric message buffer of length 65535 a message of header+payload length of 17929
[2021-06-23 11:42:07.739 (UTC+0200)] trace/channel      Connection 156 | SecureChannel 1 | Send from a symmetric message buffer of length 65535 a message of length 17929
[2021-06-23 11:42:07.775 (UTC+0200)] trace/network      Connection 156 | Activity on the socket
[2021-06-23 11:42:07.775 (UTC+0200)] trace/network      Connection 156 | Received a packet.
[2021-06-23 11:42:07.776 (UTC+0200)] trace/channel      Connection 156 | SecureChannel 1 | Process a CLO
[2021-06-23 11:42:07.782 (UTC+0200)] info/channel       Connection 156 | SecureChannel 1 | CloseSecureChannel
[2021-06-23 11:42:07.786 (UTC+0200)] trace/network      Connection 156 | Activity on the socket
[2021-06-23 11:42:07.795 (UTC+0200)] info/network       Connection 156 | Closed
[2021-06-23 11:42:07.879 (UTC+0200)] trace/network      Connection 212 | New TCP connection on server socket 344
[2021-06-23 11:42:07.880 (UTC+0200)] info/network       Connection 212 | New connection over TCP from ::1
[2021-06-23 11:42:07.881 (UTC+0200)] trace/network      Connection 212 | Activity on the socket
[2021-06-23 11:42:07.882 (UTC+0200)] trace/network      Connection 212 | Received a packet.
[2021-06-23 11:42:07.883 (UTC+0200)] trace/channel      Connection 212 | SecureChannel 0 | Process a HEL message
[2021-06-23 11:42:07.987 (UTC+0200)] trace/network      Connection 212 | Activity on the socket
[2021-06-23 11:42:07.988 (UTC+0200)] trace/network      Connection 212 | Received a packet.
[2021-06-23 11:42:08.103 (UTC+0200)] trace/channel      Connection 212 | SecureChannel 0 | Verifying chunk signature
[2021-06-23 11:42:08.104 (UTC+0200)] trace/channel      Connection 212 | SecureChannel 0 | Calculated padding size to be 20048
[2021-06-23 11:42:08.105 (UTC+0200)] warn/channel       Connection 212 | SecureChannel 0 | Impossible padding value
[2021-06-23 11:42:08.106 (UTC+0200)] info/network       Connection 212 | Processing the message failed with error BadSecurityChecksFailed
[2021-06-23 11:42:08.109 (UTC+0200)] trace/network      Connection 212 | Activity on the socket
[2021-06-23 11:42:08.110 (UTC+0200)] info/network       Connection 212 | Closed

Just in case it has something to do with the default buffer size I have changed the client buffers from 65536 to 65535 since there was a bug a long time ago server side with a similar cause. Can you pull and try again and see if it makes a difference?

Changing the buffer size doesn't make any difference. I debugged a bit, the server wants to read the extrapadding bit, because his key is 4096 Bits long. But there was no extrapadding send from the client.

That could be the reason. There is code to calculate the extra padding byte in secure_channel.rs in padding_size() and add_space_for_padding_and_signature() . The logic is there to add extra padding and it goes off the signature length, assuming if the signature > 256 bytes to include extra padding.

"The most significant byte of a two-byte integer used to specify the padding size when the key used to encrypt the message chunk is larger than 2 048 bits. This field is omitted if the key length is less than or equal to 2 048 bits."

I won't have time to test the reason until tonight but you could try this in the meantime, change this line:

let extra_padding_byte = ((padding_size - 2) >> 8) as u8;

let extra_padding_byte = (padding_size >> 8) as u8;

I'll see if I can produce some unit tests (since it has none) that tries padding a message with a variety of key sizes to see if I can isolate & fix the issue and give it some coverage.

The extra_padding_byte calculation is not the problem. As I see the client asymmetric keylength of the client cert is used, in this case 2024(256 bytes), so no extra padding byte. The server uses his certificates keylength to expect extra padding, in this case 4048(512 Bytes) and wants to read extra padding byte.

locka99 / opcua

Connecting to a server with certificate RSA (4096 Bits) #113