laumann
commented
2 years ago I was also wondering if this is related to #145 (the type of the n1 node is Variant)
Closed laumann closed 2 years ago
laumann
commented
2 years ago I was also wondering if this is related to #145 (the type of the n1 node is Variant)
laumann
commented
2 years ago Sorry, I just realised the patch attached won't work on master. I'll rework it and post an update.
laumann
commented
2 years ago 0001-samples-Simple-client-to-read-nodes.patch.txt
This one should work.
schroeder-
commented
2 years ago I think the problem is simple, currently there is no support for Variants containing other Variants. That is why you get "Unrecognized encoding mask", because in the EncodingMask case there is no match for Variant (24u8).
laumann
commented
2 years ago Yes - I'm fine with the support lacking though. What I don't want is the client closing the connection when it fails to decode a server reply. I would like that to be handled more gracefully, by an Err(_) being returned to the caller.
I'm happy to author a patch and open a PR, but I think I would need some guidance on where the behavior needs changing.
schroeder-
commented
2 years ago At this point the error is getting converted. For better diagnoses we should forward the error there. https://github.com/locka99/opcua/blob/64844b9e6de7c2dbd8aacfa48a4c2d57aa3e96ac/core/src/comms/chunker.rs#L248-L262
And here is the code where the connection is terminated, when decoding a message fails. https://github.com/locka99/opcua/blob/64844b9e6de7c2dbd8aacfa48a4c2d57aa3e96ac/client/src/comms/tcp_transport.rs#L604-L619 Here there should be some recovery or better handling of the decoding error.
On the other hand I am working on a pr for implementing Variant::Variant.
laumann
commented
2 years ago So I'm with you this far:
chunker.rs, we have SupportedMessage::decode_by_object_id() that fails (we see the message "Cannot decode message ..." in the logs)tcp_transport.rs I don't see the error messages in the logs that I would expect. For example, "Expecting a chunk, got an error message" does not appear. AFAICT in all error cases, some kind of mesage is logged, but I'm missing that in the logs I provided. I'll try to debug this further tomorrow, thanks for the pointers @schroeder- 
locka99
commented
2 years ago I've merged this so retest and see if it fixes the issue here. Weird for the server to nest variants in variants though
schroeder-
commented
2 years ago Nested variants are used if you accept any datatype, or many datatypes, so you use BaseDataType as datatype for the variable. My patch fixes only one problem. When there is a decoding error on the client side, the session will be terminated without the call knows about it and panic on the next request. And decoding errors can happen, for example if the server sends request that exceeds the decoding limits.
laumann
commented
2 years ago I'll test it right away.
When there is a decoding error on the client side, the session will be terminated without the call knows about it and panic on the next request.
This is what I'm trying to get at - is this the desired behaviour?
laumann
commented
2 years ago I've merged this so retest and see if it fixes the issue here. Weird for the server to nest variants in variants though
Tested and works, so I guess we can close this. I'll open another issue if I want to work on the "client failed to decode server response, session terminated" thing.
FWIW it's not a nested Variant types, it's an Array of Variant, I think. Here's the log output:
2022-03-01 08:52:14.037 - DEBUG - opcua_client::session::session - session:2 read() requested to read nodes [ReadValueId { node_id: NodeId { namespace: 5, identifier: String(UAString { value: Some("DataAccess_AnalogType_Array_Variant") }) }, attribute_id: 13, index_range: UAString { value: None }, data_encoding: QualifiedName { namespace_index: 0, name: UAString { value: None } } }]
2022-03-01 08:52:14.038 - DEBUG - opcua_client::message_queue - Request 4 was processed by the server
2022-03-01 08:52:14.242 - DEBUG - opcua_client::message_queue - Response to Request 4 has been stored
2022-03-01 08:52:14.242 - DEBUG - opcua_client::session::session - session:2 read(), success
Got value: [DataValue { value: Some(Array(Array { value_type: Variant, values: [Variant(Int32(10)), Variant(Int32(11)), Variant(Int32(12)), Variant(Int32(13)), Variant(Int32(14)), Variant(Int32(15)), Variant(Int32(16)), Variant(Int32(17)), Variant(Int32(18)), Variant(Int32(19))], dimensions: [] })), status: None, source_timestamp: None, source_picoseconds: None, server_timestamp: None, server_picoseconds: None }]
2022-03-01 08:52:14.242 - DEBUG - opcua_client::session::session - session:2 read() requested to read nodes [ReadValueId { node_id: NodeId { namespace: 5, identifier: String(UAString { value: Some("DataAccess_AnalogType_Array_UInt64") }) }, attribute_id: 13, index_range: UAString { value: None }, data_encoding: QualifiedName { namespace_index: 0, name: UAString { value: None } } }]All the variants are then Int32, for whatever reason...
This takes a little explaining, so I'll start with the steps to reproduce:
Steps to reproduce
$ docker run --rm -d --net host --name opcplc mcr.microsoft.com/iotedge/opc-plc:latest --pn=50000 --ph=localhost --autoaccept --sph --sn=5 --sr=10 --st=uint --fn=5 --fr=1 --ft=uint --ctb --lsn --ref --gn=5 -utcd samples/read-clientRUST_OPCUA_LOG=debug cargo runI get the following log:
output log
``` warning: field is never read: `max_chunk_count` --> core/src/comms/message_writer.rs:29:5 | 29 | max_chunk_count: usize, | ^^^^^^^^^^^^^^^^^^^^^^ | = note: `#[warn(dead_code)]` on by default warning: `opcua-core` (lib) generated 1 warning warning: unused imports: `Arc`, `RwLock` --> samples/read-client/src/main.rs:10:17 | 10 | use std::sync::{Arc, RwLock}; | ^^^ ^^^^^^ | = note: `#[warn(unused_imports)]` on by default warning: `opcua-read-client` (bin "opcua-read-client") generated 1 warning Finished dev [unoptimized + debuginfo] target(s) in 0.07s Running `/home/tj/omnioiot/opcua/target/debug/opcua-read-client` 2022-02-28 13:58:36.480 - INFO - opcua_console_logging - Logging is enabled, use RUST_OPCUA_LOG environment variable to control filtering, logging level 2022-02-28 13:58:36.480 - WARN - opcua_client::config - Endpoint config contains no endpoints 2022-02-28 13:58:36.482 - INFO - opcua_client::session::session - Connect 2022-02-28 13:58:36.482 - INFO - opcua_client::session::session - Security policy = None 2022-02-28 13:58:36.482 - INFO - opcua_client::session::session - Security mode = None 2022-02-28 13:58:36.482 - DEBUG - opcua_client::comms::tcp_transport - Waiting for a connect (or failure to connect) 2022-02-28 13:58:36.483 - DEBUG - opcua_client::comms::tcp_transport - Client tokio tasks are starting for connection 2022-02-28 13:58:36.483 - DEBUG - opcua_core::runtime - registering component client-connection-thread-ThreadId(1) 2022-02-28 13:58:36.483 - DEBUG - opcua_client::comms::tcp_transport - Creating a connection task to connect to [::1]:50000 with url opc.tcp://localhost:50000 2022-02-28 13:58:36.483 - DEBUG - opcua_core::runtime - registering component connection-task, 1 2022-02-28 13:58:36.483 - DEBUG - opcua_client::comms::tcp_transport - Sending HELLO 2022-02-28 13:58:36.483 - DEBUG - opcua_core::runtime - deregistering component connection-task, 1 2022-02-28 13:58:36.483 - DEBUG - opcua_core::runtime - registering component finished-monitor-task, 1 2022-02-28 13:58:36.483 - DEBUG - opcua_core::runtime - registering component read-task, 1 2022-02-28 13:58:36.483 - DEBUG - opcua_core::runtime - registering component write-task, 1 2022-02-28 13:58:36.483 - DEBUG - opcua_client::comms::tcp_transport - Reader got ack AcknowledgeMessage { message_header: MessageHeader { message_type: Acknowledge, message_size: 28 }, protocol_version: 0, receive_buffer_size: 65535, send_buffer_size: 65535, max_message_size: 4194304, max_chunk_count: 0 } 2022-02-28 13:58:36.583 - DEBUG - opcua_client::comms::tcp_transport - Connected 2022-02-28 13:58:36.583 - DEBUG - opcua_client::session::session - session:1 open_secure_channel 2022-02-28 13:58:36.583 - INFO - opcua_client::session::session_state - Making secure channel request 2022-02-28 13:58:36.583 - INFO - opcua_client::session::session_state - security_mode = None 2022-02-28 13:58:36.583 - INFO - opcua_client::session::session_state - security_policy = None 2022-02-28 13:58:36.583 - DEBUG - 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 } } 2022-02-28 13:58:36.583 - DEBUG - opcua_client::message_queue - Request 1 was processed by the server 2022-02-28 13:58:36.584 - DEBUG - opcua_client::message_queue - Response to Request 1 has been stored 2022-02-28 13:58:36.584 - DEBUG - opcua_client::session::session_state - Setting transport's security token 2022-02-28 13:58:36.584 - INFO - opcua_client::session::session - Connect was successful 2022-02-28 13:58:36.584 - DEBUG - opcua_client::session::session - session:1 get_endpoints 2022-02-28 13:58:36.584 - DEBUG - opcua_client::message_queue - Request 2 was processed by the server 2022-02-28 13:58:36.585 - DEBUG - opcua_client::message_queue - Response to Request 2 has been stored 2022-02-28 13:58:36.585 - DEBUG - opcua_client::session::session - session:1 get_endpoints, success 2022-02-28 13:58:36.586 - DEBUG - opcua_client::message_queue - Request 3 was processed by the server 2022-02-28 13:58:36.586 - DEBUG - opcua_client::message_queue - Response to Request 3 has been stored 2022-02-28 13:58:36.586 - ERROR - opcua_client::session::session - session:1 close_session failed ServiceFault(ServiceFault { response_header: ResponseHeader { timestamp: DateTime { date_time: 2022-02-28T13:58:36.586462900Z }, request_handle: 3, service_result: IS_ERROR | BadUnexpectedError | BadResourceUnavailable | BadCommunicationError | BadIdentityTokenInvalid | BadIdentityTokenRejected | BadNonceInvalid | BadSessionIdInvalid, 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 { node_id: NodeId { namespace: 0, identifier: Numeric(0) }, body: None } } }) 2022-02-28 13:58:36.586 - ERROR - opcua_client - Received a service fault of BadSessionIdInvalid for the request 2022-02-28 13:58:36.586 - DEBUG - opcua_client::message_queue - Sending a quit to the message receiver 2022-02-28 13:58:36.586 - DEBUG - opcua_client::comms::tcp_transport - Writer is about to send a CloseSecureChannelRequest which means it should close in a moment 2022-02-28 13:58:36.586 - DEBUG - opcua_client::comms::tcp_transport - Waiting for a disconnect 2022-02-28 13:58:36.587 - DEBUG - opcua_client::message_queue - Request 4 was processed by the server 2022-02-28 13:58:36.587 - DEBUG - opcua_client::comms::tcp_transport - Writer is setting the connection state to finished(good) 2022-02-28 13:58:36.587 - DEBUG - opcua_client::comms::tcp_transport - Write bytes task received a close, so closing connection after this send 2022-02-28 13:58:36.587 - DEBUG - opcua_client::comms::tcp_transport - Writer write-task, 1 received a quit 2022-02-28 13:58:36.587 - DEBUG - opcua_client::comms::tcp_transport - Writer loop write-task, 1 is finished 2022-02-28 13:58:36.587 - DEBUG - opcua_core::runtime - deregistering component write-task, 1 2022-02-28 13:58:36.587 - INFO - opcua_client::comms::tcp_transport - WriteState has dropped 2022-02-28 13:58:36.595 - DEBUG - opcua_client::comms::tcp_transport - Connection state is finished so dropping out of connection task 2022-02-28 13:58:36.595 - DEBUG - opcua_client::session::session_state - Session was closed with status = Good 2022-02-28 13:58:36.595 - DEBUG - opcua_core::runtime - deregistering component connection-task, 1 2022-02-28 13:58:36.595 - DEBUG - opcua_client::comms::tcp_transport - Client tokio tasks have stopped for connection 2022-02-28 13:58:36.687 - DEBUG - opcua_client::comms::tcp_transport - Disconnected 2022-02-28 13:58:36.687 - INFO - opcua_client::session::session - Session has dropped 2022-02-28 13:58:36.687 - INFO - opcua_client::comms::tcp_transport - TcpTransport has dropped 2022-02-28 13:58:36.687 - INFO - opcua_client::session::session_state - SessionState has dropped 2022-02-28 13:58:36.687 - INFO - opcua_client::comms::tcp_transport - ReadState has dropped 2022-02-28 13:58:36.688 - INFO - opcua_client::session::session - Connect 2022-02-28 13:58:36.688 - INFO - opcua_client::session::session - Security policy = None 2022-02-28 13:58:36.688 - INFO - opcua_client::session::session - Security mode = None 2022-02-28 13:58:36.688 - DEBUG - opcua_client::comms::tcp_transport - Waiting for a connect (or failure to connect) 2022-02-28 13:58:36.688 - DEBUG - opcua_client::comms::tcp_transport - Client tokio tasks are starting for connection 2022-02-28 13:58:36.688 - DEBUG - opcua_core::runtime - registering component client-connection-thread-ThreadId(1) 2022-02-28 13:58:36.688 - DEBUG - opcua_client::comms::tcp_transport - Creating a connection task to connect to [::1]:50000 with url opc.tcp://localhost:50000/ 2022-02-28 13:58:36.688 - DEBUG - opcua_core::runtime - registering component connection-task, 2 2022-02-28 13:58:36.688 - DEBUG - opcua_client::comms::tcp_transport - Sending HELLO 2022-02-28 13:58:36.688 - DEBUG - opcua_core::runtime - deregistering component connection-task, 2 2022-02-28 13:58:36.688 - DEBUG - opcua_core::runtime - registering component finished-monitor-task, 2 2022-02-28 13:58:36.689 - DEBUG - opcua_core::runtime - registering component read-task, 2 2022-02-28 13:58:36.689 - DEBUG - opcua_core::runtime - registering component write-task, 2 2022-02-28 13:58:36.689 - DEBUG - opcua_client::comms::tcp_transport - Reader got ack AcknowledgeMessage { message_header: MessageHeader { message_type: Acknowledge, message_size: 28 }, protocol_version: 0, receive_buffer_size: 65535, send_buffer_size: 65535, max_message_size: 4194304, max_chunk_count: 0 } 2022-02-28 13:58:36.788 - DEBUG - opcua_client::comms::tcp_transport - Connected 2022-02-28 13:58:36.788 - DEBUG - opcua_client::session::session - session:2 open_secure_channel 2022-02-28 13:58:36.789 - INFO - opcua_client::session::session_state - Making secure channel request 2022-02-28 13:58:36.789 - INFO - opcua_client::session::session_state - security_mode = None 2022-02-28 13:58:36.789 - INFO - opcua_client::session::session_state - security_policy = None 2022-02-28 13:58:36.789 - DEBUG - 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 } } 2022-02-28 13:58:36.789 - DEBUG - opcua_client::message_queue - Request 1 was processed by the server 2022-02-28 13:58:36.789 - DEBUG - opcua_client::message_queue - Response to Request 1 has been stored 2022-02-28 13:58:36.790 - DEBUG - opcua_client::session::session_state - Setting transport's security token 2022-02-28 13:58:36.790 - INFO - opcua_client::session::session - Connect was successful 2022-02-28 13:58:36.790 - DEBUG - opcua_client::session::session - session:2 CreateSessionRequest = CreateSessionRequest { request_header: RequestHeader { authentication_token: NodeId { namespace: 0, identifier: Numeric(0) }, timestamp: DateTime { date_time: 2022-02-28T13:58:36.790274400Z }, request_handle: 2, return_diagnostics: (empty), audit_entry_id: UAString { value: None }, timeout_hint: 10000, additional_header: ExtensionObject { node_id: NodeId { namespace: 0, identifier: Numeric(0) }, body: None } }, client_description: ApplicationDescription { application_uri: UAString { value: Some("urn:SimpleClient") }, product_uri: UAString { value: Some("urn:SimpleClient") }, application_name: LocalizedText { locale: UAString { value: Some("") }, text: UAString { value: Some("Simple Client") } }, application_type: Client, gateway_server_uri: UAString { value: None }, discovery_profile_uri: UAString { value: None }, discovery_urls: None }, server_uri: UAString { value: None }, endpoint_url: UAString { value: Some("opc.tcp://localhost:50000/") }, session_name: UAString { value: Some("Rust OPC UA Client") }, client_nonce: ByteString { value: Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]) }, client_certificate: ByteString { value: Some([48, 130, 3, 171, 48, 130, 2, 147, 160, 3, 2, 1, 2, 2, 16, 93, 85, 247, 38, 30, 78, 196, 43, 190, 57, 250, 3, 76, 12, 212, 29, 48, 13, 6, 9, 42, 134, 72, 134, 247, 13, 1, 1, 11, 5, 0, 48, 102, 49, 22, 48, 20, 6, 3, 85, 4, 3, 12, 13, 83, 105, 109, 112, 108, 101, 32, 67, 108, 105, 101, 110, 116, 49, 22, 48, 20, 6, 3, 85, 4, 10, 12, 13, 83, 105, 109, 112, 108, 101, 32, 67, 108, 105, 101, 110, 116, 49, 22, 48, 20, 6, 3, 85, 4, 11, 12, 13, 83, 105, 109, 112, 108, 101, 32, 67, 108, 105, 101, 110, 116, 49, 11, 48, 9, 6, 3, 85, 4, 6, 19, 2, 73, 69, 49, 15, 48, 13, 6, 3, 85, 4, 8, 12, 6, 68, 117, 98, 108, 105, 110, 48, 30, 23, 13, 50, 49, 48, 54, 48, 56, 49, 51, 50, 56, 53, 57, 90, 23, 13, 50, 50, 48, 54, 48, 56, 49, 51, 50, 56, 53, 57, 90, 48, 102, 49, 22, 48, 20, 6, 3, 85, 4, 3, 12, 13, 83, 105, 109, 112, 108, 101, 32, 67, 108, 105, 101, 110, 116, 49, 22, 48, 20, 6, 3, 85, 4, 10, 12, 13, 83, 105, 109, 112, 108, 101, 32, 67, 108, 105, 101, 110, 116, 49, 22, 48, 20, 6, 3, 85, 4, 11, 12, 13, 83, 105, 109, 112, 108, 101, 32, 67, 108, 105, 101, 110, 116, 49, 11, 48, 9, 6, 3, 85, 4, 6, 19, 2, 73, 69, 49, 15, 48, 13, 6, 3, 85, 4, 8, 12, 6, 68, 117, 98, 108, 105, 110, 48, 130, 1, 34, 48, 13, 6, 9, 42, 134, 72, 134, 247, 13, 1, 1, 1, 5, 0, 3, 130, 1, 15, 0, 48, 130, 1, 10, 2, 130, 1, 1, 0, 210, 90, 66, 189, 102, 246, 193, 124, 107, 90, 185, 72, 158, 84, 63, 183, 218, 115, 87, 235, 9, 138, 178, 81, 188, 46, 178, 200, 128, 117, 112, 172, 54, 209, 137, 216, 122, 97, 204, 132, 238, 116, 203, 44, 54, 163, 250, 199, 15, 153, 121, 187, 138, 40, 140, 165, 134, 57, 120, 128, 34, 27, 207, 156, 5, 12, 231, 197, 234, 233, 44, 95, 58, 83, 5, 130, 21, 49, 146, 181, 141, 155, 71, 20, 17, 127, 5, 160, 102, 51, 246, 235, 123, 224, 16, 14, 217, 15, 51, 232, 251, 163, 215, 26, 239, 118, 202, 250, 62, 206, 63, 162, 5, 70, 35, 157, 57, 77, 176, 181, 136, 67, 16, 29, 49, 159, 91, 145, 215, 203, 87, 160, 159, 145, 50, 91, 44, 160, 190, 114, 0, 216, 70, 24, 15, 248, 233, 148, 74, 66, 48, 207, 105, 99, 101, 144, 115, 111, 197, 227, 201, 18, 169, 194, 235, 114, 74, 216, 75, 45, 212, 211, 192, 233, 139, 62, 151, 156, 136, 45, 18, 30, 197, 158, 118, 68, 178, 94, 169, 200, 70, 127, 87, 150, 176, 250, 36, 17, 225, 126, 75, 7, 132, 233, 255, 237, 124, 134, 201, 205, 236, 225, 88, 192, 53, 213, 227, 161, 121, 73, 122, 99, 180, 150, 22, 191, 84, 105, 189, 93, 13, 200, 133, 48, 251, 153, 79, 118, 18, 36, 193, 160, 234, 120, 76, 248, 153, 72, 44, 90, 136, 251, 148, 131, 41, 155, 2, 3, 1, 0, 1, 163, 85, 48, 83, 48, 11, 6, 3, 85, 29, 15, 4, 4, 3, 2, 2, 244, 48, 29, 6, 3, 85, 29, 37, 4, 22, 48, 20, 6, 8, 43, 6, 1, 5, 5, 7, 3, 1, 6, 8, 43, 6, 1, 5, 5, 7, 3, 2, 48, 37, 6, 3, 85, 29, 17, 4, 30, 48, 28, 134, 16, 117, 114, 110, 58, 83, 105, 109, 112, 108, 101, 67, 108, 105, 101, 110, 116, 130, 8, 115, 111, 102, 97, 107, 105, 110, 103, 48, 13, 6, 9, 42, 134, 72, 134, 247, 13, 1, 1, 11, 5, 0, 3, 130, 1, 1, 0, 21, 108, 215, 147, 135, 254, 230, 205, 128, 39, 20, 107, 174, 101, 87, 27, 186, 19, 80, 37, 19, 94, 189, 230, 232, 158, 86, 223, 191, 138, 219, 157, 33, 71, 246, 134, 205, 163, 242, 98, 185, 195, 5, 51, 255, 0, 98, 207, 253, 80, 231, 217, 126, 204, 230, 128, 67, 188, 106, 112, 19, 109, 47, 41, 21, 14, 205, 215, 66, 224, 68, 151, 75, 15, 217, 188, 222, 220, 93, 200, 75, 104, 159, 228, 54, 170, 202, 152, 74, 124, 49, 182, 119, 236, 82, 22, 208, 155, 137, 174, 159, 147, 133, 101, 187, 64, 220, 130, 6, 113, 133, 132, 137, 214, 194, 131, 79, 182, 24, 245, 124, 64, 220, 172, 52, 197, 58, 171, 103, 188, 159, 223, 76, 62, 147, 169, 45, 96, 130, 93, 62, 58, 166, 120, 26, 77, 251, 41, 126, 243, 175, 119, 188, 77, 88, 74, 48, 48, 171, 103, 194, 112, 145, 188, 153, 158, 245, 99, 170, 178, 80, 243, 92, 103, 254, 146, 72, 44, 181, 159, 206, 14, 227, 60, 253, 21, 5, 232, 43, 66, 52, 13, 81, 118, 213, 53, 1, 180, 77, 200, 72, 243, 37, 238, 139, 120, 206, 234, 107, 166, 191, 173, 238, 137, 91, 71, 136, 109, 209, 140, 51, 133, 54, 186, 78, 23, 240, 187, 231, 244, 220, 94, 170, 72, 251, 82, 200, 105, 37, 22, 141, 110, 64, 43, 94, 196, 153, 59, 150, 188, 195, 143, 96, 211, 97, 40]) }, requested_session_timeout: 179769313486231570000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000.0, max_response_message_size: 0 } 2022-02-28 13:58:36.790 - DEBUG - opcua_client::message_queue - Request 2 was processed by the server 2022-02-28 13:58:36.795 - DEBUG - opcua_client::message_queue - Response to Request 2 has been stored 2022-02-28 13:58:36.795 - DEBUG - opcua_client::session::session - session:2 Revised session timeout is 3600000 2022-02-28 13:58:36.795 - DEBUG - opcua_client::session::session - session:2 spawn_session_activity_task(3600000) 2022-02-28 13:58:36.795 - DEBUG - opcua_client::session::session - session:2 session timeout is 3600000, activity timer is 2700000 2022-02-28 13:58:36.796 - DEBUG - opcua_client::session::session - session:2 Endpoint policy = Some(UserTokenPolicy { policy_id: UAString { value: Some("1") }, token_type: Anonymous, issued_token_type: UAString { value: None }, issuer_endpoint_url: UAString { value: None }, security_policy_uri: UAString { value: Some("http://opcfoundation.org/UA/SecurityPolicy#Basic256") } }) 2022-02-28 13:58:36.796 - DEBUG - opcua_client::message_queue - Request 3 was processed by the server 2022-02-28 13:58:36.796 - DEBUG - opcua_client::message_queue - Response to Request 3 has been stored 2022-02-28 13:58:36.796 - DEBUG - opcua_client::session::session - session:2 read() requested to read nodes [ReadValueId { node_id: NodeId { namespace: 5, identifier: String(UAString { value: Some("DataAccess_AnalogType_Array_Variant") }) }, attribute_id: 13, index_range: UAString { value: None }, data_encoding: QualifiedName { namespace_index: 0, name: UAString { value: None } } }] 2022-02-28 13:58:36.797 - DEBUG - opcua_client::message_queue - Request 4 was processed by the server 2022-02-28 13:58:36.798 - ERROR - opcua_types::variant - Unrecognized encoding mask 2022-02-28 13:58:36.799 - DEBUG - opcua_core::comms::chunker - Cannot decode message ReadResponse_Encoding_DefaultBinary, err = IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError 2022-02-28 13:58:36.799 - ERROR - opcua_client::comms::tcp_transport - Reader has put connection into a finished state with status BadServiceUnsupported 2022-02-28 13:58:36.799 - DEBUG - opcua_client::comms::tcp_transport - Sending a quit to the writer 2022-02-28 13:58:36.799 - DEBUG - opcua_client::comms::tcp_transport - Read loop finished, connection state = Finished(IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadEncodingLimitsExceeded | BadUnknownResponse | BadTimeout | BadServiceUnsupported) 2022-02-28 13:58:36.799 - DEBUG - opcua_core::runtime - deregistering component read-task, 2 2022-02-28 13:58:36.799 - INFO - opcua_client::comms::tcp_transport - ReadState has dropped 2022-02-28 13:58:36.799 - DEBUG - opcua_client::comms::tcp_transport - Writer write-task, 2 received a quit 2022-02-28 13:58:36.799 - DEBUG - opcua_client::comms::tcp_transport - Writer loop write-task, 2 is finished 2022-02-28 13:58:36.799 - DEBUG - opcua_core::runtime - deregistering component write-task, 2 2022-02-28 13:58:36.799 - INFO - opcua_client::comms::tcp_transport - WriteState has dropped 2022-02-28 13:58:36.800 - DEBUG - opcua_client::comms::tcp_transport - Connection state is finished so dropping out of connection task ```Where I see the breakdown is the line "Unrecognized encoding mask"
For some reason, this shuts everything down and the read attempt eventually times out. But the session is broken in some way at this point, subsequent reads also time out.
In the code sample there are two nodes.
n1produces this problem, butn2does not (a value is returned). Swapping the order of the nodes, first gives a value, then it crashes.So far what I've figured is that
from_encoding_mask()does not handleVariant. I don't know why this is, and I don't know if this is the real problem. What I would like though, is that a read that fails to decode is just returned to me as an error like everything else, so I, as the client, can decide on how to act. As it stands, the only way I can see to recover is to re-initialize the client, but that seems like overkill.The signature of
from_encoding_mask()was changed recently (in 633b60a1252719c84c879cbb60884652e4d9a7b1) and the change from a panic to returning an error looks like the right direction, but it doesn't fully solve this issue.