BadSecureChannelClosed: Missing decryption keys

[jraffeiner]

If the Client receives a OpenSecureChannelResponse, immediatly followed by a chunk encrypted under the new token, it leads to a race condition on the decryption keys, because it is not guaranteed that the new keys for the new Security Token will be derived, before attempting do decode further chunks.
Which leads to the error BadSecureChannelClosed: Missing decryption keys

As seen in the attached logs:
2025-11-17T15:25:07.725691Z TRACE opcua_core::comms::chunker: Received chunk with sequence number 788
2025-11-17T15:25:07.725779Z INFO decode{secure_channel=SecureChannel { role: Client, security_policy: Basic256Sha256, security_mode: SignAndEncrypt, secure_channel_id: 920869287, token_created_at: DateTime { date_time: 2025-11-17T15:21:21.031915600Z }, token_lifetime: 300000, token_id: 3, ..., remote_keys: {3: RemoteKeys { ... }, 2: RemoteKeys { ... } }, local_keys: Some( ... ), encoding_context: RwLock { ... }, ,expected_node_id=None}: opcua_core::comms::chunker: new

• Decoded chunk with OpenSecureChannelResponse:
  2025-11-17T15:25:07.725889Z INFO decode{secure_channel=SecureChannel { role: Client, security_policy: Basic256Sha256, security_mode: SignAndEncrypt, secure_channel_id: 920869287, token_created_at: DateTime { date_time: 2025-11-17T15:21:21.031915600Z }, token_lifetime: 300000, token_id: 3, ..., remote_keys: {3: RemoteKeys { ... }, 2: RemoteKeys { ... } }, local_keys: Some( ... ), encoding_context: RwLock { ... }, ,expected_node_id=None}: opcua_core::comms::chunker: return=OpenSecureChannel(OpenSecureChannelResponse { response_header: ResponseHeader { timestamp: DateTime { date_time: 2025-11-17T15:25:07.757915600Z }, request_handle: 790, service_result: Good (0), service_diagnostics: DiagnosticInfo { symbolic_id: None, namespace_uri: None, locale: None, localized_text: None, additional_info: None, inner_status_code: None, inner_diagnostic_info: None }, string_table: Some([]), additional_header: ExtensionObject { body: None } }, server_protocol_version: 0, security_token: ChannelSecurityToken { channel_id: 920869287, token_id: 4, created_at: DateTime { date_time: 2025-11-17T15:25:07.757915600Z }, revised_lifetime: 300000 }, server_nonce: ByteString { value: Some([226, 205, 69, 51, 62, 134, 70, 122, 248, 68, 245, 172, 47, 42, 65, 7, 170, 16, 49, 62, 232, 232, 91, 65, 61, 177, 12, 186, 49, 63, 238, 4]) } })
2025-11-17T15:25:07.725959Z INFO decode{secure_channel=SecureChannel { role: Client, security_policy: Basic256Sha256, security_mode: SignAndEncrypt, secure_channel_id: 920869287, token_created_at: DateTime { date_time: 2025-11-17T15:21:21.031915600Z }, token_lifetime: 300000, token_id: 3, ..., remote_keys: {3: RemoteKeys { ... }, 2: RemoteKeys { ... } }, local_keys: Some( ... ), encoding_context: RwLock { ... }, ,expected_node_id=None}: opcua_core::comms::chunker: close time.busy=138µs time.idle=43.2µs

• Missing (derive keys etc. for new security token)

• Tries to decrypt following block, who was encrypted with the new Keys (token_id:4):
  2025-11-17T15:25:07.726099Z TRACE opcua_core::comms::secure_channel: Decrypting block with signature info 0..272 and encrypt info 16..304
2025-11-17T15:25:07.726121Z TRACE opcua_core::comms::secure_channel: Got Security Header: SymmetricSecurityHeader { token_id: 4 }
2025-11-17T15:25:07.726140Z INFO opcua_core::comms::secure_channel: Get Keys for: 4
2025-11-17T15:25:07.726201Z ERROR opcua_types::encoding: BadSecureChannelClosed: Missing decryption keys
2025-11-17T15:25:07.726250Z WARN opcua_client::session::event_loop: session:1 Transport disconnected: BadSecureChannelClosed

Complete logs:
2025-11-17T15:25:07.725691Z TRACE opcua_core::comms::chunker: Received chunk with sequence number 788
2025-11-17T15:25:07.725779Z INFO decode{secure_channel=SecureChannel { role: Client, security_policy: Basic256Sha256, security_mode: SignAndEncrypt, secure_channel_id: 920869287, token_created_at: DateTime { date_time: 2025-11-17T15:21:21.031915600Z }, token_lifetime: 300000, token_id: 3, cert: Some([x509]), private_key: Some([pkey]), remote_cert: Some([x509]), remote_nonce: [159, 188, 189, 221, 23, 139, 35, 90, 219, 213, 159, 179, 205, 215, 107, 0, 238, 8, 195, 204, 118, 222, 18, 4, 162, 12, 158, 233, 255, 57, 217, 206], local_nonce: [189, 158, 228, 76, 104, 99, 60, 15, 214, 168, 36, 2, 207, 218, 116, 155, 91, 84, 212, 250, 33, 107, 22, 250, 28, 9, 182, 114, 125, 163, 128, 168], remote_keys: {3: RemoteKeys { keys: ([70, 226, 74, 127, 123, 137, 75, 206, 163, 30, 88, 152, 186, 143, 86, 162, 20, 237, 10, 64, 238, 248, 174, 33, 102, 235, 189, 48, 193, 212, 138, 95], AesKey { value: [212, 146, 187, 164, 3, 119, 2, 36, 138, 224, 65, 121, 215, 53, 17, 181, 239, 253, 129, 189, 224, 97, 198, 55, 170, 197, 17, 228, 51, 218, 182, 146], security_policy: Basic256Sha256 }, [92, 142, 89, 94, 175, 175, 39, 232, 11, 222, 37, 202, 26, 92, 41, 160]), expires_at: DateTime { date_time: 2025-11-17T15:27:36.031915600Z } }, 2: RemoteKeys { keys: ([10, 234, 63, 77, 42, 110, 59, 161, 72, 26, 102, 132, 116, 124, 229, 136, 146, 101, 27, 187, 6, 247, 49, 211, 75, 250, 206, 20, 177, 4, 162, 199], AesKey { value: [92, 232, 250, 22, 242, 157, 58, 81, 57, 191, 193, 40, 126, 19, 40, 251, 243, 106, 148, 82, 215, 33, 208, 173, 49, 247, 106, 128, 144, 160, 186, 33], security_policy: Basic256Sha256 }, [142, 203, 154, 6, 99, 224, 235, 174, 218, 160, 13, 27, 94, 85, 104, 94]), expires_at: DateTime { date_time: 2025-11-17T15:23:48.989015Z } }}, local_keys: Some(([22, 206, 86, 98, 169, 224, 171, 59, 37, 86, 31, 247, 13, 18, 153, 61, 155, 81, 245, 81, 97, 14, 212, 10, 42, 177, 247, 79, 36, 0, 91, 46], AesKey { value: [174, 28, 153, 249, 108, 239, 120, 50, 74, 196, 157, 97, 68, 41, 177, 181, 98, 241, 101, 241, 193, 87, 43, 135, 203, 145, 9, 134, 240, 35, 228, 15], security_policy: Basic256Sha256 }, [186, 224, 1, 26, 115, 84, 18, 59, 105, 155, 144, 140, 107, 94, 192, 112])), encoding_context: RwLock { data: ContextOwned { namespaces: NamespaceMap { known_namespaces: {"http://opcfoundation.org/UA/": 0} }, options: DecodingOptions { client_offset: TimeDelta { secs: -9, nanos: 16084400 }, max_message_size: 327675, max_chunk_count: 5, max_string_length: 65535, max_byte_string_length: 65535, max_array_length: 1000, decoding_depth_gauge: DepthGauge { max_depth: 10, current_depth: 0 } } } } } expected_node_id=None}: opcua_core::comms::chunker: new

2025-11-17T15:25:07.725889Z INFO decode{secure_channel=SecureChannel { role: Client, security_policy: Basic256Sha256, security_mode: SignAndEncrypt, secure_channel_id: 920869287, token_created_at: DateTime { date_time: 2025-11-17T15:21:21.031915600Z }, token_lifetime: 300000, token_id: 3, cert: Some([x509]), private_key: Some([pkey]), remote_cert: Some([x509]), remote_nonce: [159, 188, 189, 221, 23, 139, 35, 90, 219, 213, 159, 179, 205, 215, 107, 0, 238, 8, 195, 204, 118, 222, 18, 4, 162, 12, 158, 233, 255, 57, 217, 206], local_nonce: [189, 158, 228, 76, 104, 99, 60, 15, 214, 168, 36, 2, 207, 218, 116, 155, 91, 84, 212, 250, 33, 107, 22, 250, 28, 9, 182, 114, 125, 163, 128, 168], remote_keys: {3: RemoteKeys { keys: ([70, 226, 74, 127, 123, 137, 75, 206, 163, 30, 88, 152, 186, 143, 86, 162, 20, 237, 10, 64, 238, 248, 174, 33, 102, 235, 189, 48, 193, 212, 138, 95], AesKey { value: [212, 146, 187, 164, 3, 119, 2, 36, 138, 224, 65, 121, 215, 53, 17, 181, 239, 253, 129, 189, 224, 97, 198, 55, 170, 197, 17, 228, 51, 218, 182, 146], security_policy: Basic256Sha256 }, [92, 142, 89, 94, 175, 175, 39, 232, 11, 222, 37, 202, 26, 92, 41, 160]), expires_at: DateTime { date_time: 2025-11-17T15:27:36.031915600Z } }, 2: RemoteKeys { keys: ([10, 234, 63, 77, 42, 110, 59, 161, 72, 26, 102, 132, 116, 124, 229, 136, 146, 101, 27, 187, 6, 247, 49, 211, 75, 250, 206, 20, 177, 4, 162, 199], AesKey { value: [92, 232, 250, 22, 242, 157, 58, 81, 57, 191, 193, 40, 126, 19, 40, 251, 243, 106, 148, 82, 215, 33, 208, 173, 49, 247, 106, 128, 144, 160, 186, 33], security_policy: Basic256Sha256 }, [142, 203, 154, 6, 99, 224, 235, 174, 218, 160, 13, 27, 94, 85, 104, 94]), expires_at: DateTime { date_time: 2025-11-17T15:23:48.989015Z } }}, local_keys: Some(([22, 206, 86, 98, 169, 224, 171, 59, 37, 86, 31, 247, 13, 18, 153, 61, 155, 81, 245, 81, 97, 14, 212, 10, 42, 177, 247, 79, 36, 0, 91, 46], AesKey { value: [174, 28, 153, 249, 108, 239, 120, 50, 74, 196, 157, 97, 68, 41, 177, 181, 98, 241, 101, 241, 193, 87, 43, 135, 203, 145, 9, 134, 240, 35, 228, 15], security_policy: Basic256Sha256 }, [186, 224, 1, 26, 115, 84, 18, 59, 105, 155, 144, 140, 107, 94, 192, 112])), encoding_context: RwLock { data: ContextOwned { namespaces: NamespaceMap { known_namespaces: {"http://opcfoundation.org/UA/": 0} }, options: DecodingOptions { client_offset: TimeDelta { secs: -9, nanos: 16084400 }, max_message_size: 327675, max_chunk_count: 5, max_string_length: 65535, max_byte_string_length: 65535, max_array_length: 1000, decoding_depth_gauge: DepthGauge { max_depth: 10, current_depth: 0 } } } } } expected_node_id=None}: opcua_core::comms::chunker: return=OpenSecureChannel(OpenSecureChannelResponse { response_header: ResponseHeader { timestamp: DateTime { date_time: 2025-11-17T15:25:07.757915600Z }, request_handle: 790, service_result: Good (0), service_diagnostics: DiagnosticInfo { symbolic_id: None, namespace_uri: None, locale: None, localized_text: None, additional_info: None, inner_status_code: None, inner_diagnostic_info: None }, string_table: Some([]), additional_header: ExtensionObject { body: None } }, server_protocol_version: 0, security_token: ChannelSecurityToken { channel_id: 920869287, token_id: 4, created_at: DateTime { date_time: 2025-11-17T15:25:07.757915600Z }, revised_lifetime: 300000 }, server_nonce: ByteString { value: Some([226, 205, 69, 51, 62, 134, 70, 122, 248, 68, 245, 172, 47, 42, 65, 7, 170, 16, 49, 62, 232, 232, 91, 65, 61, 177, 12, 186, 49, 63, 238, 4]) } })

2025-11-17T15:25:07.725959Z INFO decode{secure_channel=SecureChannel { role: Client, security_policy: Basic256Sha256, security_mode: SignAndEncrypt, secure_channel_id: 920869287, token_created_at: DateTime { date_time: 2025-11-17T15:21:21.031915600Z }, token_lifetime: 300000, token_id: 3, cert: Some([x509]), private_key: Some([pkey]), remote_cert: Some([x509]), remote_nonce: [159, 188, 189, 221, 23, 139, 35, 90, 219, 213, 159, 179, 205, 215, 107, 0, 238, 8, 195, 204, 118, 222, 18, 4, 162, 12, 158, 233, 255, 57, 217, 206], local_nonce: [189, 158, 228, 76, 104, 99, 60, 15, 214, 168, 36, 2, 207, 218, 116, 155, 91, 84, 212, 250, 33, 107, 22, 250, 28, 9, 182, 114, 125, 163, 128, 168], remote_keys: {3: RemoteKeys { keys: ([70, 226, 74, 127, 123, 137, 75, 206, 163, 30, 88, 152, 186, 143, 86, 162, 20, 237, 10, 64, 238, 248, 174, 33, 102, 235, 189, 48, 193, 212, 138, 95], AesKey { value: [212, 146, 187, 164, 3, 119, 2, 36, 138, 224, 65, 121, 215, 53, 17, 181, 239, 253, 129, 189, 224, 97, 198, 55, 170, 197, 17, 228, 51, 218, 182, 146], security_policy: Basic256Sha256 }, [92, 142, 89, 94, 175, 175, 39, 232, 11, 222, 37, 202, 26, 92, 41, 160]), expires_at: DateTime { date_time: 2025-11-17T15:27:36.031915600Z } }, 2: RemoteKeys { keys: ([10, 234, 63, 77, 42, 110, 59, 161, 72, 26, 102, 132, 116, 124, 229, 136, 146, 101, 27, 187, 6, 247, 49, 211, 75, 250, 206, 20, 177, 4, 162, 199], AesKey { value: [92, 232, 250, 22, 242, 157, 58, 81, 57, 191, 193, 40, 126, 19, 40, 251, 243, 106, 148, 82, 215, 33, 208, 173, 49, 247, 106, 128, 144, 160, 186, 33], security_policy: Basic256Sha256 }, [142, 203, 154, 6, 99, 224, 235, 174, 218, 160, 13, 27, 94, 85, 104, 94]), expires_at: DateTime { date_time: 2025-11-17T15:23:48.989015Z } }}, local_keys: Some(([22, 206, 86, 98, 169, 224, 171, 59, 37, 86, 31, 247, 13, 18, 153, 61, 155, 81, 245, 81, 97, 14, 212, 10, 42, 177, 247, 79, 36, 0, 91, 46], AesKey { value: [174, 28, 153, 249, 108, 239, 120, 50, 74, 196, 157, 97, 68, 41, 177, 181, 98, 241, 101, 241, 193, 87, 43, 135, 203, 145, 9, 134, 240, 35, 228, 15], security_policy: Basic256Sha256 }, [186, 224, 1, 26, 115, 84, 18, 59, 105, 155, 144, 140, 107, 94, 192, 112])), encoding_context: RwLock { data: ContextOwned { namespaces: NamespaceMap { known_namespaces: {"http://opcfoundation.org/UA/": 0} }, options: DecodingOptions { client_offset: TimeDelta { secs: -9, nanos: 16084400 }, max_message_size: 327675, max_chunk_count: 5, max_string_length: 65535, max_byte_string_length: 65535, max_array_length: 1000, decoding_depth_gauge: DepthGauge { max_depth: 10, current_depth: 0 } } } } } expected_node_id=None}: opcua_core::comms::chunker: close time.busy=138µs time.idle=43.2µs

2025-11-17T15:25:07.726099Z TRACE opcua_core::comms::secure_channel: Decrypting block with signature info 0..272 and encrypt info 16..304
2025-11-17T15:25:07.726121Z TRACE opcua_core::comms::secure_channel: Got Security Header: SymmetricSecurityHeader { token_id: 4 }
2025-11-17T15:25:07.726140Z INFO opcua_core::comms::secure_channel: Get Keys for: 4
2025-11-17T15:25:07.726201Z ERROR opcua_types::encoding: BadSecureChannelClosed: Missing decryption keys
2025-11-17T15:25:07.726250Z WARN opcua_client::session::event_loop: session:1 Transport disconnected: BadSecureChannelClosed

[einarmo]

Hm. I think I see how this could happen. That's rather unfortunate. I suspect we'll need to shift the actual renewal logic from AsyncSecureChannel to the transport event loop itself... I'll look into it. I have some idea how this might happen, but I'd like to make a test that consistently reproduces it before I actually make a fix.

Right now we renew the token here. We can likely keep most of that, but move the actual call to end_issue_or_renew_secure_channel into the event loop...

[jraffeiner]

As far as I understand the problem, it seems to happen under the following circumstance:
-> transport event loop handles OpenSecureChannelResponse and sends it with the callback channel to AsyncSecureChannel awaiting the response
-> transport event loop receives next message encrypted with new keys
-> the transport event loop calls its handle_incoming_message method
-> acquires the write lock to the SecureChannel before the end_issue_or_renew_secure_channel can acquire the write lock to the SecureChannel
-> tries to decrypt data before the new keys have been derived

Creating a test to consistently trigger this race condition seems tricky...

[einarmo]

That matches my understanding, yeah.

Creating a test to consistently trigger this race condition seems tricky...

It sure does. I'll still try to reproduce it, but maybe I'll be content with just sprinkling some delays around the codebase to force a race.

[einarmo]

As you point out, it's rather hard to test this. If you've got a way to reproduce this semi-reliably, could you try #176? If we're right about the cause of this error, it should just go away with that change, since we now always update the secure channel before processing any more chunks.

[jraffeiner]

I do have a semi-reliable way to test it (normally it occurs within an 1hour, while connected to a specific PLC), I'll test #176 with it and report tomorrow my findings, and thanks for the fast response

[jraffeiner]

Good morning, I had two clients running over the night, one with #176 and one using the main branch:

• on the one using the main branch the error "Missing decryption keys", occurred ca. 3-4 times every hour
• on the one using Update secure channel params earlier #176 it never occured

=> #176 seems to fix the problem
Great work thanks 😄

[einarmo]

This is not only quite a severe issue, that is unlikely to be caught by tests, but you also made a real effort to make a good report that made fixing it relatively simple, so thanks a lot!