Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

client: Failure to decode server response leads to broken session #170

Closed
laumann opened this issue Feb 28, 2022 · 11 comments
Closed

client: Failure to decode server response leads to broken session #170

laumann opened this issue Feb 28, 2022 · 11 comments

Comments

@laumann
Copy link
Contributor

laumann commented Feb 28, 2022

This takes a little explaining, so I'll start with the steps to reproduce:

Steps to reproduce

  1. Run this docker string:
    $ 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 -ut
  2. Apply this patch: 0001-samples-Simple-client-to-read-nodes.patch.txt on master EDIT: Please grab the patch attached in a comment below.
  3. cd samples/read-client
  4. RUST_OPCUA_LOG=debug cargo run

I 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"

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

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. n1 produces this problem, but n2 does 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 handle Variant. 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 633b60a) and the change from a panic to returning an error looks like the right direction, but it doesn't fully solve this issue.

@laumann
Copy link
Contributor Author

laumann commented Feb 28, 2022

I was also wondering if this is related to #145 (the type of the n1 node is Variant)

@laumann
Copy link
Contributor Author

laumann commented Feb 28, 2022

Sorry, I just realised the patch attached won't work on master. I'll rework it and post an update.

@laumann
Copy link
Contributor Author

laumann commented Feb 28, 2022

0001-samples-Simple-client-to-read-nodes.patch.txt

This one should work.

@schroeder-
Copy link
Contributor

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
Copy link
Contributor Author

laumann commented Feb 28, 2022

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-
Copy link
Contributor

At this point the error is getting converted. For better diagnoses we should forward the error there.

match SupportedMessage::decode_by_object_id(&mut data, object_id, &decoding_options) {
Ok(decoded_message) => {
if let SupportedMessage::Invalid(_) = decoded_message {
debug!("Message {:?} is unsupported", object_id);
Err(StatusCode::BadServiceUnsupported)
} else {
// debug!("Returning decoded msg {:?}", decoded_message);
Ok(decoded_message)
}
}
Err(err) => {
debug!("Cannot decode message {:?}, err = {:?}", object_id, err);
Err(StatusCode::BadServiceUnsupported)
}
}

And here is the code where the connection is terminated, when decoding a message fails.

Message::Error(error) => {
// TODO client should go into an error recovery state, dropping the connection and reestablishing it.
session_status_code =
if let Some(status_code) = StatusCode::from_u32(error.error) {
status_code
} else {
StatusCode::BadUnexpectedError
};
error!(
"Expecting a chunk, got an error message {}",
session_status_code
);
}
_ => {
panic!("Expected a recognized message");
}

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
Copy link
Contributor Author

laumann commented Feb 28, 2022

So I'm with you this far:

  • In chunker.rs, we have SupportedMessage::decode_by_object_id() that fails (we see the message "Cannot decode message ..." in the logs)
  • For 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
Copy link
Owner

locka99 commented Feb 28, 2022

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-
Copy link
Contributor

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
Copy link
Contributor Author

laumann commented Mar 1, 2022

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
Copy link
Contributor Author

laumann commented Mar 1, 2022

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...

@laumann laumann closed this as completed Apr 6, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants