When decoding arrays is the "len" a promise or a hint?

[laumann]

I'm working with a somewhat special OPC-UA server, and having some problems decoding arrays returning.

I've messed around with debugging and have managed to produce this log snippet:

2022-06-02T09:54:01.905208721+00:00: DEBUG: /omnioiot/opcua/client/src/message_queue.rs:101: Response to Request 788 has been stored
2022-06-02T09:54:01.905377070+00:00: DEBUG: /omnioiot/opcua/client/src/session/session.rs:2197: session:5 browse, success
2022-06-02T09:54:01.905674093+00:00: DEBUG: /omnioiot/opcua/client/src/message_queue.rs:51: Request 789 was processed by the server
2022-06-02T09:54:01.920895280+00:00: DEBUG: /omnioiot/opcua/client/src/comms/tcp_transport.rs:106: receive chunk intermediate 1789:839
2022-06-02T09:54:01.921120572+00:00: DEBUG: /omnioiot/opcua/core/src/comms/chunker.rs:299: Decoded node id / object id of BrowseResponse_Encoding_DefaultBinary
2022-06-02T09:54:01.921182136+00:00: DEBUG: /omnioiot/opcua/core/src/supported_message.rs:281: decoding object_id BrowseResponse_Encoding_DefaultBinary
2022-06-02T09:54:01.921230660+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [0]opcua_types::string::UAString
2022-06-02T09:54:01.921274461+00:00: DEBUG: /omnioiot/opcua/types/src/service_types/browse_response.rs:55: response_header = ResponseHeader { timestamp: DateTime { date_time: 2022-06-02T09:55:19.381129200Z }, request_handle: 789, service_result: HISTORICAL_RAW | Good, 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-06-02T09:54:01.921679179+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1]opcua_types::service_types::browse_result::BrowseResult
2022-06-02T09:54:01.921726744+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T09:54:01.923009814+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T09:54:01.923120810+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 891 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
2022-06-02T09:54:02.396905716+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [759693312]opcua_types::diagnostic_info::DiagnosticInfo
memory allocation of 60775464960 bytes failed
Aborted (core dumped)

I'm suspecting that the decoded array length is more of a hint than the necessarily the length of the array for two reasons:

• The fact that 891 items are successfully decoded before EOF is encountered
• The length of 759693312 just seems outlandish (= 0x2d480000)

A few notes:

• The patched code is not based on master but the v0.9, but AFAICT the decoding logic for arrays hasn't changed
• I made a small change where, instead of wanting to decode exactly len array items, any errors caught would just break out of the decoding loop.
• We run with the max possible decoding limits (i32::MAX as usize)
• The OPC-UA server in question is Kepware 5

The patch in question:

diff --git a/core/src/comms/chunker.rs b/core/src/comms/chunker.rs
index 15241a6a..b6d088c2 100644
--- a/core/src/comms/chunker.rs
+++ b/core/src/comms/chunker.rs
@@ -296,7 +296,7 @@ impl Chunker {
                     StatusCode::BadUnexpectedError
                 })
                 .map(|object_id| {
-                    trace!("Decoded node id / object id of {:?}", object_id);
+                    debug!("Decoded node id / object id of {:?}", object_id);
                     object_id
                 })
         }
diff --git a/core/src/supported_message.rs b/core/src/supported_message.rs
index 33617e9c..78971fa3 100644
--- a/core/src/supported_message.rs
+++ b/core/src/supported_message.rs
@@ -278,7 +278,7 @@ impl SupportedMessage {
         object_id: ObjectId,
         decoding_options: &DecodingOptions,
     ) -> EncodingResult<Self> {
-        trace!("decoding object_id {:?}", object_id);
+        debug!("decoding object_id {:?}", object_id);
         let decoded_message = match object_id {
             ObjectId::ServiceFault_Encoding_DefaultBinary => {
                 ServiceFault::decode(stream, decoding_options)?.into()
diff --git a/types/src/encoding.rs b/types/src/encoding.rs
index 21d8f39e..a5eb1a1e 100644
--- a/types/src/encoding.rs
+++ b/types/src/encoding.rs
@@ -95,7 +95,7 @@ where
     T: Debug,
 {
     result.map_err(|err| {
-        trace!("Decoding error - {:?}", err);
+        debug!("Decoding error - {:?}", err);
         StatusCode::BadDecodingError
     })
 }
@@ -132,6 +132,7 @@ pub fn read_array<S: Read, T: BinaryEncoder<T>>(
     decoding_options: &DecodingOptions,
 ) -> EncodingResult<Option<Vec<T>>> {
     let len = read_i32(stream)?;
+    debug!("decoding array of [{}]{}", len, std::any::type_name::<T>());
     if len == -1 {
         Ok(None)
     } else if len < -1 {
@@ -145,8 +146,19 @@ pub fn read_array<S: Read, T: BinaryEncoder<T>>(
         Err(StatusCode::BadDecodingError)
     } else {
         let mut values: Vec<T> = Vec::with_capacity(len as usize);
+        let mut count = 0;
         for _ in 0..len {
-            values.push(T::decode(stream, decoding_options)?);
+            //values.push(T::decode(stream, decoding_options)?);
+            match T::decode(stream, decoding_options) {
+                Ok(val) => {
+                    count += 1;
+                    values.push(val);
+                }
+                Err(err) => {
+                    debug!("Decoded {} items (expected {}), before failure: {:?}", count, len, err);
+                    break;
+                }
+            }
         }
         Ok(Some(values))
     }
diff --git a/types/src/service_types/browse_response.rs b/types/src/service_types/browse_response.rs
index 11b24635..bdcc80d0 100644
--- a/types/src/service_types/browse_response.rs
+++ b/types/src/service_types/browse_response.rs
@@ -52,8 +52,11 @@ impl BinaryEncoder<BrowseResponse> for BrowseResponse {
     #[allow(unused_variables)]
     fn decode<S: Read>(stream: &mut S, decoding_options: &DecodingOptions) -> EncodingResult<Self> {
         let response_header = ResponseHeader::decode(stream, decoding_options)?;
+        debug!("response_header = {:?}", response_header);
         let results: Option<Vec<BrowseResult>> = read_array(stream, decoding_options)?;
+        debug!("results = {:?}", results);
         let diagnostic_infos: Option<Vec<DiagnosticInfo>> = read_array(stream, decoding_options)?;
+        debug!("diagnostic_infos = {:?}", diagnostic_infos);
         Ok(BrowseResponse {
             response_header,
             results,
-- 
2.35.1

[schroeder-]

Len is a promis. So something is not decoded correctly. DiagnosticsInfo are strange beast, do you realy want DiagnosticsInfo? Because if not you can tell the server not to send them, in the request.

[locka99]

For reference, arrays are encoded like so:

https://reference.opcfoundation.org/v104/Core/docs/Part6/5.2.5/

Inside variants, arrays may be single or multi-dimensional and the encoding dictates what the variant holds:

https://reference.opcfoundation.org/v104/Core/docs/Part6/5.2.2/#Table15

As far as I am aware the array length is implicit to encoding an array otherwise how many elements are there? The decoder therefore needs the length. The encoding allows a length of -1 to denote a null array, or 0 for an empty array which are distinct. There is slight weirdness that if an array is empty / null, that the type of the array has to be guessed in the impl but otherwise yes you need length.

There are probably some edge cases especially with multi-dimensional arrays that might need further unit tests to ensure they are working properly.

[laumann]

@schroeder-

Len is a promis.

Oof, that's not what I wanted to hear :-) but thanks!

DiagnosticsInfo are strange beast, do you realy want DiagnosticsInfo?

Not necessarily, we could probably omit them, thanks for pointing that out.

@locka99 It does make that the decoded length should correspond to the number of items that should be decoded. (That just means that my problem lies elsewhere for now.)

It's a BrowseResponse we're decoding here btw, the contents of which shouldn't contain multi-dimensional (I think?)

For now, I'll try dropping the DiagnosticsInfo and report back here.

[laumann]

As another bit of info, the full log I have has lots of instances of "decoded less than expected". They can roughly be divided into two categories:

• Expecting 1000 (in two cases, 400) ReferenceDescription, ended up decoding fewer than that
• Expecting some large (variable) number of DiagnosticsInfo, ended up decoding between 0 and 10

2022-06-02T12:11:00.839626959+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:00.841073416+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:00.841245203+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 891 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:01.315442345+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [759693312]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:01.315739612+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:01.315844898+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 0 items (expected 759693312), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:03.875153132+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:03.876443693+00:00: ERROR: /omnioiot/opcua/types/src/service_types/enums.rs:602: Invalid value 107898112 for enum NodeClass
2022-06-02T12:11:03.876492726+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 944 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError
--
2022-06-02T12:11:04.292922228+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1409286144]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:04.293061036+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:04.293164982+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 1 items (expected 1409286144), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:06.686835778+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:06.688031200+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:06.688119172+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 934 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:07.104571854+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [978714624]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:07.104824596+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:07.104903735+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 0 items (expected 978714624), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:10.376303636+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:10.377437061+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:10.377546781+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 904 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:10.781662568+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [36712748]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:10.781820542+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:10.781934944+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 2 items (expected 36712748), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:31.043296864+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [400]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:31.043836063+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:31.043912003+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 389 items (expected 400), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:31.215638095+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1936018688]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:31.215773367+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:31.215907446+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 0 items (expected 1936018688), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:32.020156010+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [400]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:32.020643784+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:32.020720119+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 387 items (expected 400), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:32.196513163+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1936018688]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:32.196649602+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:32.196765138+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 0 items (expected 1936018688), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:34.453235681+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:34.454274129+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:34.454390067+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 559 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:34.699411075+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [825767216]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:34.699546883+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:34.699645052+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 2 items (expected 825767216), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:36.764710392+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:36.765548914+00:00: ERROR: /omnioiot/opcua/types/src/service_types/enums.rs:602: Invalid value 515 for enum NodeClass
2022-06-02T12:11:36.765597904+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 540 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError
--
2022-06-02T12:11:37.008394700+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [191784192]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:37.008533664+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:37.008644625+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 5 items (expected 191784192), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:43.685943949+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:43.687328523+00:00: ERROR: /omnioiot/opcua/types/src/service_types/enums.rs:602: Invalid value 512 for enum NodeClass
2022-06-02T12:11:43.687385058+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 885 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError
--
2022-06-02T12:11:44.102316027+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [4063232]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:44.102454617+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:44.102559138+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 10 items (expected 4063232), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:51.398853007+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:51.400663389+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:51.400847397+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 907 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:51.855705371+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [134218288]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:51.855870983+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:51.855981298+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 4 items (expected 134218288), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:54.407681833+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:54.408932636+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:54.409046538+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 880 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:54.814152830+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [759912018]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:54.814292813+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:54.814417229+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 0 items (expected 759912018), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:57.984085929+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:57.986640624+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:57.986750288+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 930 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:58.415301863+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [2048]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:58.415448500+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:58.415562677+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 2 items (expected 2048), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:59.741434012+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:59.742568680+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:59.742647002+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 946 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:12:00.172555048+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1701401344]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:12:00.172847262+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:12:00.172926302+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 0 items (expected 1701401344), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:12:02.010978105+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:12:02.012136121+00:00: ERROR: /omnioiot/opcua/types/src/node_id.rs:239: Unrecognized node id type 62
2022-06-02T12:12:02.012183427+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 892 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:12:02.425943415+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [50409216]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:12:02.426097122+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:12:02.426212581+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 2 items (expected 50409216), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError

ReferenceDescription:

2022-06-02T12:11:00.839626959+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:00.841073416+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:00.841245203+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 891 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:03.875153132+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:03.876443693+00:00: ERROR: /omnioiot/opcua/types/src/service_types/enums.rs:602: Invalid value 107898112 for enum NodeClass
2022-06-02T12:11:03.876492726+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 944 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError
--
2022-06-02T12:11:06.686835778+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:06.688031200+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:06.688119172+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 934 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:10.376303636+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:10.377437061+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:10.377546781+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 904 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:31.043296864+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [400]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:31.043836063+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:31.043912003+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 389 items (expected 400), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:32.020156010+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [400]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:32.020643784+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:32.020720119+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 387 items (expected 400), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:34.453235681+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:34.454274129+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:34.454390067+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 559 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:36.764710392+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:36.765548914+00:00: ERROR: /omnioiot/opcua/types/src/service_types/enums.rs:602: Invalid value 515 for enum NodeClass
2022-06-02T12:11:36.765597904+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 540 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError
--
2022-06-02T12:11:43.685943949+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:43.687328523+00:00: ERROR: /omnioiot/opcua/types/src/service_types/enums.rs:602: Invalid value 512 for enum NodeClass
2022-06-02T12:11:43.687385058+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 885 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError
--
2022-06-02T12:11:51.398853007+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:51.400663389+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:51.400847397+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 907 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:54.407681833+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:54.408932636+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:54.409046538+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 880 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:57.984085929+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:57.986640624+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:57.986750288+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 930 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:11:59.741434012+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:11:59.742568680+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:98: Decoding error - Error { kind: UnexpectedEof, message: "failed to fill whole buffer" }
2022-06-02T12:11:59.742647002+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 946 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError
--
2022-06-02T12:12:02.010978105+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1000]opcua_types::service_types::reference_description::ReferenceDescription
2022-06-02T12:12:02.012136121+00:00: ERROR: /omnioiot/opcua/types/src/node_id.rs:239: Unrecognized node id type 62
2022-06-02T12:12:02.012183427+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:158: Decoded 892 items (expected 1000), before failure: IS_ERROR | BadUnexpectedError | BadInternalError | BadOutOfMemory | BadResourceUnavailable | BadCommunicationError | BadEncodingError | BadDecodingError

DiagnosticInfo:

2022-06-02T12:11:01.315442345+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [759693312]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:04.292922228+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1409286144]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:07.104571854+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [978714624]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:10.781662568+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [36712748]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:31.215638095+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1936018688]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:32.196513163+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1936018688]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:34.699411075+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [825767216]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:37.008394700+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [191784192]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:44.102316027+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [4063232]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:51.855705371+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [134218288]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:54.814152830+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [759912018]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:11:58.415301863+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [2048]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:12:00.172555048+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [1701401344]opcua_types::diagnostic_info::DiagnosticInfo
2022-06-02T12:12:02.425943415+00:00: DEBUG: /omnioiot/opcua/types/src/encoding.rs:135: decoding array of [50409216]opcua_types::diagnostic_info::DiagnosticInfo

[laumann]

I went looking for how to disable the DiagnosticInfo, and is it correct that it's set in the request header, like this?

https://github.com/locka99/opcua/blob/974174152407a73f32d49286723bed36e14f4b7b/lib/src/client/session/session_state.rs#L267-L277

If so, I would assume the default is off (and then the question would be why would Kepware return DiagnosticInfo anyway...).

[svanharmelen]

Just FYI regarding the length... I encountered at least one server that crashed because we send -1. I assume they maybe used a uint or something like that which caused it to crash and restart (was an embedded server). So I needed to patch this locally to not send the -1 as the only way to "fix" the connection 😞

[schroeder-]

If so, I would assume the default is off (and then the question would be why would Kepware return DiagnosticInfo anyway...).

Ok diagnostics are turned off already but Kepware... they are know not to care about specs.

The reason you don't get the expected values is, that a server will return max results per request, for example 400 values and return a continuation point. Then the client have to call browse_next to get the next results until no continuation point is returned. Currently this value from the clientside is hardcoded to 1000, but it is more a hint, so servers can return less.

From my experience, if the array length is off, then a field before is decoded incorrect and the position in the buffer is not correct, that is why you read a to large value for array length.

[laumann]

Ok diagnostics are turned off already but Kepware... they are know not to care about specs.

Yeah, dealing with Kepware is a bit of a bummer... But I can't really go fix that :-)

The reason you don't get the expected values is, that a server will return max results per request, for example 400 values and return a continuation point. Then the client have to call browse_next to get the next results until no continuation point is returned. Currently this value from the clientside is hardcoded to 1000, but it is more a hint, so servers can return less.

I didn't look for returned continuation points in the server responses, but I assume you're correct that there are some. Our client implementation does handle continuation points (and from our testing, we are confident that it does so correctly).

But just to make sure, you're saying that the client indicates an upper limit of a 1000 items that it'll handle? Could maybe be interesting to tweak that if possible. If I were to set this to 1, would the server be allowed to return larger arrays? Or would the client then have to deal with a bunch of continuation points?

From my experience, if the array length is off, then a field before is decoded incorrect and the position in the buffer is not correct, that is why you read a to large value for array length.

That's interesting. Could it be something like the server only sends i16 for the length (2 bytes), but the decoder grabs 4? Or something like that?

[laumann]

Just FYI regarding the length... I encountered at least one server that crashed because we send -1. I assume they maybe used a uint or something like that which caused it to crash and restart (was an embedded server). So I needed to patch this locally to not send the -1 as the only way to "fix" the connection :disappointed:

:facepalm:

[schroeder-]

But just to make sure, you're saying that the client indicates an upper limit of a 1000 items that it'll handle? Could maybe be interesting to tweak that if possible. If I were to set this to 1, would the server be allowed to return larger arrays? Or would the client then have to deal with a bunch of continuation points?

An conforming server would return 1 and would return 1 per browse next. Zero is unlimited.

From Specs:

Indicates the maximum number of references to return for each starting Node specified in the request. The value 0 indicates that the Client is imposing no limitation.

-

From my experience, if the array length is off, then a field before is decoded incorrect and the position in the buffer is not correct, that is why you read a to large value for array length.

That's interesting. Could it be something like the server only sends i16 for the length (2 bytes), but the decoder grabs 4? Or something like that?

yes. So if you have an error most likely the element before is wrong.

[schroeder-]

Found some wrong ordering in DiagnosticInfos, but should not be the root of the problem. #213

[laumann]

I may have a theory that I'll just put out here, then try to go figure out how I could implement/test it.

The observations are/have been:

• An array of 1000 items are in the process of being decoded
• an "failed to fill buffer" error arises
• I skipped over the error, and continued decoding
• Got lots of DiagnosticInfo (with odd lengths)

I think the root of the problem is the "failed to fill buffer" error. As our client is not requesting any DiagnosticInfo, could it be that my attempt at "recovering" basically ends up treating the remaining buffer as an array of DiagnosticInfo to decode?

[locka99]

Ignore last commit comment, I referenced the wrong bug

[laumann]

Just to check back in on this - I haven't had much time to work on it, but my current working theory is that there's something going on in chunker.rs and/or the underlying stream. I ended up looking at the decoding for ReferenceDescription:

https://github.com/locka99/opcua/blob/fca6cdeed5382fc437a6dea23fc5e427f67f4a39/lib/src/types/service_types/reference_description.rs#L67-L75

and fields like browse_name and display_name end up decoding a UAString and calling read_exact() on the stream, which seems likely to be the source of the "failed to fill buffer" error.

https://github.com/locka99/opcua/blob/fca6cdeed5382fc437a6dea23fc5e427f67f4a39/lib/src/types/string.rs#L83

In my "workaround" (just swallowing the decoding error, and accepting fewer things decoded), the DiagnosticInfos are decoded (but there shouldn't be any) which leads me to believe that a subsequent call to the stream actually returns more bytes.

So maybe the problem is that the stream returns an error for read_exact(), but a subsequent call to some read() would actually return more bytes? I think one way to test this theory could be to replace read_exact() with a way to retry a read until the desired number of bytes (or some unrecoverable error) are obtained. I'll try it out when I have time again...

Any thoughts on this?

[locka99]

I looked at ReferenceDescription and the generated decoder and it looks correct to the schema - there is nothing to say strings are optional or whatever. If a string is null or empty, the UAString decoder would know that from the length prior to the data.

If you have wireshark, can you capture what is being sent to the lib to see if we can work out if it is chunks, or something else? There is some info about wireshark & a link here - https://github.com/locka99/opcua/blob/a67327e927760dd21c485424bf023679c8fff8a5/docs/developer.md

Ideally if we could get the chunks as sent, unencrypted, then it should be possible to assemble them into a message and decode them to see where the issue lies.