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