Open thosaa opened 1 year ago
Just a follow up.
It seems that there some session issues as the the MessageQueue.make_request_channel is called, but on the old session instead of the new session...
I have added a uuid to the MessageQueue, for debug purpose only, to be able to track the instances. I also added debug logs starting with ### .
2023-03-24 08:46:44.260Z DEBUG opcua::client::session::session_state - async_publish is acknowledging subscription acknowledgements with sequence nrs [3]
2023-03-24 08:46:44.260Z DEBUG opcua::client::message_queue - ### send_message self = MessageQueue {
inflight_requests: {
13: None,
},
responses: {},
sender: Some(
UnboundedSender {
chan: Tx {
inner: Chan {
tx: Tx {
block_tail: 0x00007f53240008e0,
tail_position: 12,
},
semaphore: 0,
rx_waker: AtomicWaker,
tx_count: 1,
rx_fields: "...",
},
},
},
),
mq_id: 8bbeb5b0-adfe-4c8a-ab82-9d268076334a,
}
2023-03-24 08:46:44.260Z DEBUG opcua::client::session::session_state - async_publish, request sent with handle 13
2023-03-24 08:46:44.260Z DEBUG opcua::client::message_queue - Request 13 was processed by the server
///////// Here the connection was interrupted (Ethernet disconnected from PLC) /////////
2023-03-24 08:46:56.469Z DEBUG opcua::client::message_queue - ### send_message self = MessageQueue {
inflight_requests: {
13: None,
14: None,
},
responses: {},
sender: Some(
UnboundedSender {
chan: Tx {
inner: Chan {
tx: Tx {
block_tail: 0x00007f53240008e0,
tail_position: 13,
},
semaphore: 0,
rx_waker: AtomicWaker,
tx_count: 1,
rx_fields: "...",
},
},
},
),
mq_id: 8bbeb5b0-adfe-4c8a-ab82-9d268076334a,
}
2023-03-24 08:46:56.469Z DEBUG opcua::client::session::session_state - async_publish, request sent with handle 14
2023-03-24 08:46:56.470Z DEBUG opcua::client::message_queue - Request 14 was processed by the server
///////// Here the connection was retablished (Ethernet inserted) /////////
2023-03-24 08:47:04.157Z ERROR opcua::client::comms::tcp_transport - Read loop error Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }
2023-03-24 08:47:04.157Z INFO opcua::client::comms::tcp_transport - ReadState has dropped
2023-03-24 08:47:04.157Z INFO opcua::client::comms::tcp_transport - WriteState has dropped
2023-03-24 08:47:04.157Z DEBUG opcua::client::comms::tcp_transport - Closing connection because the read loop terminated
2023-03-24 08:47:04.158Z DEBUG opcua::client::session::session_state - Session was closed with status = BadConnectionClosed
2023-03-24 08:47:04.159Z INFO opcua::client::session_retry_policy - Retry retriggered by policy
2023-03-24 08:47:04.159Z INFO opcua::client::session::session - Retrying to reconnect to server...
2023-03-24 08:47:04.159Z DEBUG opcua::client::message_queue - ### MessageQueue new
2023-03-24 08:47:04.159Z DEBUG opcua::client::session::session_state - ### SessionState new has id: 3, and messag_queue id: e3ee6e23-bb8c-433d-a8c5-cdf72f695f49
2023-03-24 08:47:04.159Z INFO opcua::client::session::session - Connect
2023-03-24 08:47:04.159Z INFO opcua::client::session::session - Security policy = Basic256Sha256
2023-03-24 08:47:04.159Z INFO opcua::client::session::session - Security mode = SignAndEncrypt
2023-03-24 08:47:04.160Z DEBUG opcua::client::comms::tcp_transport - Creating a connection task to connect to 192.168.1.77:4840 with url opc.tcp://CX-61AEAE:4840/
2023-03-24 08:47:04.161Z DEBUG opcua::client::comms::tcp_transport - ### WriteState new was hit, message_queue id: 8bbeb5b0-adfe-4c8a-ab82-9d268076334a
2023-03-24 08:47:04.161Z DEBUG opcua::client::message_queue - ### make_request_channel self = MessageQueue {
inflight_requests: {},
responses: {},
sender: Some(
UnboundedSender {
chan: Tx {
inner: Chan {
tx: Tx {
block_tail: 0x00007f5324019ad0,
tail_position: 0,
},
semaphore: 0,
rx_waker: AtomicWaker,
tx_count: 2,
rx_fields: "...",
},
},
},
),
mq_id: 8bbeb5b0-adfe-4c8a-ab82-9d268076334a,
}
2023-03-24 08:47:04.165Z DEBUG opcua::client::session::session - session:3 open_secure_channel
2023-03-24 08:47:04.165Z INFO opcua::client::session::session_state - Making secure channel request
2023-03-24 08:47:04.165Z INFO opcua::client::session::session_state - security_mode = SignAndEncrypt
2023-03-24 08:47:04.165Z INFO opcua::client::session::session_state - security_policy = Basic256Sha256
2023-03-24 08:47:04.165Z DEBUG opcua::client::message_queue - ### send_message self = MessageQueue {
inflight_requests: {
1: Some(
SyncSender { .. },
),
},
responses: {},
sender: None,
mq_id: e3ee6e23-bb8c-433d-a8c5-cdf72f695f49,
}
thread 'main' panicked at 'MessageQueue::send_message should never be called before make_request_channel', .../src/client/message_queue.rs:66:14
As the ### make_request_channel self =
shows the function is called and it holds a sender but the mq_id is the same as before the connection was interrupted.
I will try to get wiser on the sessions and get back.
I fixed the panic with https://github.com/locka99/opcua/compare/master...thosaa:opcua:dont-panic-on-reconnect But the code just stalls afterwards...
2023-03-24 10:48:46.679Z DEBUG opcua::client::session::session_state - ns=1;g=78589b75-5023-7741-b207-90801cb0ed85 Processing 1 async messages
2023-03-24 10:48:46.679Z DEBUG opcua::client::session::session_state - ns=1;g=78589b75-5023-7741-b207-90801cb0ed85 handle_async_response
2023-03-24 10:48:46.679Z DEBUG opcua::client::session::session_state - ns=1;g=78589b75-5023-7741-b207-90801cb0ed85 PublishResponse
2023-03-24 10:48:46.679Z DEBUG opcua::client::session::session_state - ns=1;g=78589b75-5023-7741-b207-90801cb0ed85 Received notifications, data changes = 1, events = 0
///////// Storing the data from the PLC to the database /////////
2023-03-24 10:48:46.679Z DEBUG opcua::client::session::session_state - async_publish is acknowledging subscription acknowledgements with sequence nrs [7]
2023-03-24 10:48:46.679Z DEBUG opcua::client::session::session_state - async_publish, request sent with handle 17
2023-03-24 10:48:46.680Z DEBUG opcua::client::message_queue - Request 17 was processed by the server
////////// Disconnecting the PLC /////////
2023-03-24 10:48:59.118Z DEBUG opcua::client::session::session_state - async_publish, request sent with handle 18
2023-03-24 10:48:59.119Z DEBUG opcua::client::message_queue - Request 18 was processed by the server
////////// Reconnecting the PLC /////////
2023-03-24 10:49:06.579Z ERROR opcua::client::comms::tcp_transport - Read loop error Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }
2023-03-24 10:49:06.579Z INFO opcua::client::comms::tcp_transport - ReadState has dropped
2023-03-24 10:49:06.579Z INFO opcua::client::comms::tcp_transport - WriteState has dropped
2023-03-24 10:49:06.579Z DEBUG opcua::client::comms::tcp_transport - Closing connection because the read loop terminated
2023-03-24 10:49:06.580Z DEBUG opcua::client::session::session_state - Session was closed with status = BadConnectionClosed
2023-03-24 10:49:06.589Z INFO opcua::client::session_retry_policy - Retry retriggered by policy
2023-03-24 10:49:06.589Z INFO opcua::client::session::session - Retrying to reconnect to server...
2023-03-24 10:49:06.589Z INFO opcua::client::session::session - Connect
2023-03-24 10:49:06.590Z INFO opcua::client::session::session - Security policy = Basic256Sha256
2023-03-24 10:49:06.590Z INFO opcua::client::session::session - Security mode = SignAndEncrypt
2023-03-24 10:49:06.590Z DEBUG opcua::client::comms::tcp_transport - Creating a connection task to connect to 192.168.1.77:4840 with url opc.tcp://CX-61AEAE:4840/
2023-03-24 10:49:06.595Z DEBUG opcua::client::session::session - session:3 open_secure_channel
2023-03-24 10:49:06.595Z INFO opcua::client::session::session_state - Making secure channel request
2023-03-24 10:49:06.595Z INFO opcua::client::session::session_state - security_mode = SignAndEncrypt
2023-03-24 10:49:06.595Z INFO opcua::client::session::session_state - security_policy = Basic256Sha256
2023-03-24 10:49:06.595Z DEBUG opcua::core::comms::secure_channel - AsymmetricSecurityHeader = AsymmetricSecurityHeader { security_policy_uri: UAString { value: Some("http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256") }, sender_certificate: ByteString { value: Some([48, 130, 3, 199, ...]) }, receiver_certificate_thumbprint: ByteString { value: Some([223, 223, 227, 199, 30, 19, 120, 214, 53, 251, 134, 113, 11, 116, 43, 32, 74, 164, 125, 96]) } }
2023-03-24 10:49:06.596Z DEBUG opcua::client::message_queue - Request 1 was processed by the server
2023-03-24 10:49:07.757Z DEBUG opcua::client::message_queue - Response to Request 1 has been stored
2023-03-24 10:49:07.757Z DEBUG opcua::client::session::session_state - Setting transport's security token
2023-03-24 10:49:07.758Z DEBUG opcua::client::session::session - session:3 Endpoint policy = Some(UserTokenPolicy { policy_id: UAString { value: Some("Anonymous-[0]-SignAndEncrypt-Basic256Sha256") }, token_type: Anonymous, issued_token_type: UAString { value: None }, issuer_endpoint_url: UAString { value: None }, security_policy_uri: UAString { value: None } })
2023-03-24 10:49:07.760Z DEBUG opcua::client::message_queue - Request 2 was processed by the server
2023-03-24 10:49:07.762Z DEBUG opcua::client::message_queue - Response to Request 2 has been stored
2023-03-24 10:49:07.762Z ERROR opcua::client - Received a service fault of BadSessionIdInvalid for the request
2023-03-24 10:49:07.762Z INFO opcua::client::session::session - Session activation failed on reconnect, error = BadSessionIdInvalid, so creating a new session
2023-03-24 10:49:07.762Z DEBUG opcua::client::session::session - session:3 create_session
2023-03-24 10:49:07.763Z DEBUG opcua::client::session::session - session:3 CreateSessionRequest = CreateSessionRequest { request_header: RequestHeader { authentication_token: NodeId { namespace: 0, identifier: Numeric(0) }, timestamp: DateTime { date_time: 2023-03-24T10:49:07.763119Z }, request_handle: 1, 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:Discovery") }, product_uri: UAString { value: Some("urn:CdgsOpcuaClient") }, application_name: LocalizedText { locale: UAString { value: Some("") }, text: UAString { value: Some("CDGs OPC UA 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://CX-61AEAE:4840/") }, session_name: UAString { value: Some("Rust OPC UA Client") }, client_nonce: ByteString { value: Some([46, 222, 26, ...) }, requested_session_timeout: 1.7976931348623157e308, max_response_message_size: 0 }
2023-03-24 10:49:07.763Z DEBUG opcua::client::message_queue - Request 1 was processed by the server
2023-03-24 10:49:08.336Z DEBUG opcua::client::message_queue - Response to Request 1 has been stored
2023-03-24 10:49:08.336Z DEBUG opcua::crypto::certificate_store - Validating cert with name on disk TcOpcUaServer@CX-61AEAE [dfdfe3c71e1378d635fb86710b742b204aa47d60].der
2023-03-24 10:49:08.336Z INFO opcua::crypto::x509 - Certificate is valid for this time
2023-03-24 10:49:08.336Z INFO opcua::crypto::x509 - Certificate host name CX-61AEAE is good
2023-03-24 10:49:08.336Z INFO opcua::crypto::x509 - Certificate application uri urn:BeckhoffAutomation:TcOpcUaServer is good
2023-03-24 10:49:08.336Z DEBUG opcua::client::session::session - session:3 Revised session timeout is 3600000
2023-03-24 10:49:08.337Z DEBUG opcua::client::session::session - session:3 spawn_session_activity_task(3600000)
2023-03-24 10:49:08.337Z DEBUG opcua::client::session::session - session:3 session timeout is 3600000, activity timer is 2700000
2023-03-24 10:55:21.231Z DEBUG opcua::client::comms::tcp_transport - Read loop finished, connection state = Processing
2023-03-24 10:55:21.231Z INFO opcua::client::comms::tcp_transport - ReadState has dropped
2023-03-24 10:55:21.231Z INFO opcua::client::comms::tcp_transport - WriteState has dropped
2023-03-24 10:55:21.231Z DEBUG opcua::client::comms::tcp_transport - Closing connection because the read loop terminated
2023-03-24 10:55:21.231Z DEBUG opcua::client::session::session_state - Session was closed with status = Good
I was expecting the code to take up the previous subscription, what am I missing?
FWIW: I am experiencing exactly the same problem after a reconnect (after restart of the server).
@thosaa it looks like the code stalls because of a mutex problem at spawn_session_activity_task
method (line 791). The lock cannot be acquired.
Below are my debug logs for your code with more verbose logging.
2023-07-13T13:06:50.164390100+01:00 INFO opcua::client::session::session - Session activation failed on reconnect, error = BadSessionIdInvalid, so creating a new session
Thread ThreadId(12), self.session_state write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 314
Thread ThreadId(12), self.session_state write lock completed
Thread ThreadId(12), self.message_queue write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session_state.rs, line 366
Thread ThreadId(12), self.message_queue write lock completed
2023-07-13T13:06:50.166402600+01:00 DEBUG opcua::client::session::session - session:3 create_session
Creating session
Thread ThreadId(12), self.secure_channel read locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1335
Thread ThreadId(12), self.secure_channel read lock completed
Thread ThreadId(12), self.certificate_store write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1343
Thread ThreadId(12), self.certificate_store write lock completed
Thread ThreadId(12), self.session_retry_policy locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1356
Thread ThreadId(12), self.session_retry_policy lock completed
Thread ThreadId(12), self.session_state write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1214
Thread ThreadId(12), self.session_state write lock completed
2023-07-13T13:06:50.228234200+01:00 DEBUG opcua::client::session::session - session:3 CreateSessionRequest = CreateSessionRequest { request_header: RequestHeader { authentication_token: NodeId { namespace: 0, identifier: Numeric(0) }, timestamp: DateTime { date_time: 2023-07-13T12:06:50.227976800Z }, request_handle: 1, 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:digicrop") }, product_uri: UAString { value: Some("urn:digicrop") }, application_name: LocalizedText { locale: UAString { value: Some("") }, text: UAString { value: Some("DigiCrop") } }, 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:48040/") }, session_name: UAString { value: Some("Rust OPC UA Client") }, client_nonce: ByteString { value: None }, client_certificate: ByteString { value: Some([48, 130, 3, 168, 48, 130, 2, 144, 160, 3, 2, 1, 2, 2, 16, 42, 127, 142, 9, 147, 150, 13, 182, 9, 117, 101, 99, 240, 51, 94, 227, 48, 13, 6, 9, 42, 134, 72, 134, 247, 13, 1, 1, 11, 5, 0, 48, 87, 49, 17, 48, 15, 6, 3, 85, 4, 3, 12, 8, 68, 105, 103, 105, 67, 114, 111, 112, 49, 17, 48, 15, 6, 3, 85, 4, 10, 12, 8, 68, 105, 103, 105, 67, 114, 111, 112, 49, 17, 48, 15, 6, 3, 85, 4, 11, 12, 8, 68, 105, 103, 105, 67, 114, 111, 112, 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, 51, 48, 55, 48, 56, 48, 56, 49, 54, 48, 56, 90, 23, 13, 50, 52, 48, 55, 48, 55, 48, 56, 49, 54, 48, 56, 90, 48, 87, 49, 17, 48, 15, 6, 3, 85, 4, 3, 12, 8, 68, 105, 103, 105, 67, 114, 111, 112, 49, 17, 48, 15, 6, 3, 85, 4, 10, 12, 8, 68, 105, 103, 105, 67, 114, 111, 112, 49, 17, 48, 15, 6, 3, 85, 4, 11, 12, 8, 68, 105, 103, 105, 67, 114, 111, 112, 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, 192, 44, 241, 95, 188, 77, 106, 146, 78, 218, 213, 178, 17, 161, 103, 221, 198, 180, 10, 224, 13, 37, 45, 208, 23, 108, 79, 207, 120, 170, 201, 142, 195, 63, 182, 189, 240, 51, 209, 12, 12, 107, 64, 67, 151, 10, 221, 125, 90, 247, 47, 33, 4, 7, 52, 13, 60, 145, 253, 184, 195, 125, 22, 228, 46, 96, 11, 209, 180, 50, 176, 137, 245, 179, 222,
178, 141, 104, 91, 187, 114, 255, 197, 42, 255, 169, 61, 123, 92, 228, 249, 126, 82, 130, 14, 8, 211, 39, 200, 126, 180, 9, 47, 238, 52, 11, 162, 32, 182, 29, 219, 249, 89, 162, 208, 17, 163, 21, 73, 238, 128, 200, 135, 105, 218, 121, 61, 184, 228, 137, 178, 93, 34, 98, 105, 182, 216, 20, 117, 255, 103, 233, 166, 132, 52, 65, 72, 30, 145, 172, 113, 197, 198, 97, 243, 37, 116, 154, 27, 192, 51, 253, 57, 207, 110, 112, 224, 154, 90, 129, 170, 161, 33, 183, 215, 101, 99, 45, 44, 89, 155, 0, 32, 2, 101, 169, 188, 85, 98, 154, 183, 252, 86, 54, 127, 195, 228, 22, 130, 239, 227, 174, 231, 230, 251, 132, 184, 247, 196, 193, 182, 173, 174, 97, 100, 175, 238, 74, 116, 164, 45, 194, 29, 120, 36, 153, 133, 217, 144, 68, 17, 203, 157, 124, 69, 53, 37, 189, 156, 147, 183, 79, 174, 155, 161, 118, 242, 72, 233, 152, 59, 141, 86, 214, 245, 245, 2, 3, 1, 0, 1, 163, 112, 48, 110, 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, 2, 6, 8, 43, 6, 1, 5, 5, 7, 3, 1, 48, 64, 6,
3, 85, 29, 17, 4, 57, 48, 55, 134, 12, 117, 114, 110, 58, 100, 105, 103, 105, 99, 114, 111, 112, 130, 15, 68, 69, 83, 75, 84, 79, 80, 45, 73, 78, 56, 73, 50, 78, 78, 135, 4, 192, 168, 31, 178, 135, 16, 254,
128, 0, 0, 0, 0, 0, 0, 154, 194, 188, 188, 202, 137, 33, 147, 48, 13, 6, 9, 42, 134, 72, 134, 247, 13, 1, 1, 11, 5, 0, 3, 130, 1, 1, 0, 189, 201, 50, 160, 127, 233, 187, 237, 178, 16, 183, 72, 21, 220, 214,
169, 231, 208, 9, 170, 140, 47, 199, 124, 24, 81, 235, 86, 41, 154, 199, 231, 135, 49, 185, 83, 249, 134, 148, 84, 24, 197, 103, 158, 39, 156, 122, 89, 4, 129, 224, 215, 32, 141, 198, 8, 85, 92, 138, 235, 70, 216, 247, 137, 53, 140, 57, 199, 204, 107, 125, 93, 217, 158, 133, 49, 118, 112, 44, 178, 82, 230, 243, 67, 182, 187, 205, 18, 252, 162, 38, 117, 79, 201, 171, 9, 230, 250, 178, 221, 98, 206, 135, 25, 91,
125, 217, 210, 218, 70, 218, 87, 24, 138, 78, 107, 89, 87, 85, 60, 87, 8, 122, 161, 224, 203, 59, 235, 224, 153, 154, 174, 124, 201, 183, 199, 177, 100, 172, 93, 80, 172, 99, 11, 84, 254, 154, 240, 218, 119, 203, 80, 217, 83, 121, 93, 19, 148, 54, 165, 38, 78, 41, 205, 209, 210, 135, 21, 50, 49, 129, 147, 95, 79, 5, 108, 143, 155, 50, 7, 29, 195, 175, 66, 78, 133, 114, 243, 26, 211, 184, 194, 251, 10, 251, 109, 103, 62, 188, 15, 112, 190, 94, 57, 148, 182, 65, 59, 248, 149, 54, 146, 166, 218, 241, 98, 26, 220, 225, 173, 106, 104, 253, 195, 180, 21, 53, 15, 93, 85, 54, 231, 127, 48, 70, 207, 208, 34, 202, 224, 244, 75, 161, 224, 138, 140, 181, 135, 155, 90, 180, 195, 91, 223, 138, 184]) }, requested_session_timeout: 1.7976931348623157e308, max_response_message_size: 0 }
Thread ThreadId(12), self.session_state write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1223
Thread ThreadId(12), self.session_state write lock completed
Thread ThreadId(12), self.secure_channel read locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session_state.rs, line 444
Thread ThreadId(12), self.secure_channel read lock completed
Thread ThreadId(12), self.message_queue write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session_state.rs, line 437
Thread ThreadId(12), self.message_queue write lock completed
Thread ThreadId(19), self.secure_channel read locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\comms\tcp_transport.rs, line 245
Thread ThreadId(19), self.secure_channel read lock completed
Thread ThreadId(19), write_state.message_queue write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\comms\tcp_transport.rs, line 558
Thread ThreadId(19), write_state.message_queue write lock completed
2023-07-13T13:06:50.250679+01:00 DEBUG opcua::client::message_queue - Request 1 was processed by the server
Thread ThreadId(19), self.secure_channel write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\comms\tcp_transport.rs, line 111
Thread ThreadId(19), self.secure_channel write lock completed
Thread ThreadId(19), self.secure_channel read locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\comms\tcp_transport.rs, line 115
Thread ThreadId(19), self.secure_channel read lock completed
Thread ThreadId(19), self.secure_channel read locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\comms\tcp_transport.rs, line 95
Thread ThreadId(19), self.secure_channel read lock completed
Thread ThreadId(19), depth_gauge locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\types\encoding.rs, line 48
Thread ThreadId(19), depth_gauge lock completed
Thread ThreadId(19), self.depth_gauge locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\types\encoding.rs, line 33
Thread ThreadId(19), self.depth_gauge lock completed
Thread ThreadId(19), read_state.message_queue write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\comms\tcp_transport.rs, line 496
Thread ThreadId(19), read_state.message_queue write lock completed
2023-07-13T13:06:50.262159600+01:00 DEBUG opcua::client::message_queue - Response to Request 1 has been stored
Thread ThreadId(12), self.session_state write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1379
Thread ThreadId(12), self.session_state write lock completed
Thread ThreadId(12), self.secure_channel write locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1383
Thread ThreadId(12), self.secure_channel write lock completed
Thread ThreadId(12), self.secure_channel read locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 1055
Thread ThreadId(12), self.secure_channel read lock completed
2023-07-13T13:06:50.269882700+01:00 DEBUG opcua::client::session::session - session:3 Revised session timeout is 3600000
Before spawn session activity task
2023-07-13T13:06:50.270979700+01:00 DEBUG opcua::client::session::session - session:3 spawn_session_activity_task(3600000)
Thread ThreadId(12), self.session_state read locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 771
Thread ThreadId(12), self.session_state read lock completed
2023-07-13T13:06:50.272491900+01:00 DEBUG opcua::client::session::session - session:3 session timeout is 3600000, activity timer is 2700000
After session timeout debug statement
session-activity-thread-ThreadId(12)
Thread ThreadId(12), self.runtime locking at C:\Users\FUJITSU-RMB\.cargo\git\checkouts\_empty-31ce7918aa1c8808\8425fbc\lib\src\client\session\session.rs, line 791
The run_loop
method didn't release the lock on the session runtime. I made a patch by running the session task on a fresh tokio runtime instead here. It works now, but still requires more testing.
@locka99 is this planned to be resolved in 0.13? There seems to be several issues related to this that are fairly well hashed out and even some PRs with potential fixes.
It's seems like a pretty big issue, since I imagine most people are trying to use opcua within some other application (a GUI, a web server, or whatever) and there's a pretty reasonable chance that existing application already has its own async runtime.
Just trying to gauge whether the presented fixes are acceptable and will be rolled in soon, or if I should look to run a patched fork, or look for alternatives, etc. Thanks!
I am using the current master branch and I have a problem which is very alike #243.
I get a: 'main' panicked at 'MessageQueue::send_message should never be called before make_request_channel' Which is due to hitting the expect at: https://github.com/locka99/opcua/blob/master/lib/src/client/message_queue.rs#L57
When I unplug our real PLC from the network, wait a bit and then reconnecting the PLC I get: