Error when clearing MqttByteBuffer

[devaronius]

Hi, When I communicate with my broker and send a payload with my message, I sometimes get the following error. Do you happen to know how I could resolve this one?

Caught error: - Error details: Bad state: MqttByteBuffer::clear - attempt to clear a byte buffer where postion is not zero, it is 2 - Stacktrace: #0 MqttByteBuffer.clear (package:mqtt5_client/src/utility/mqtt_byte_buffer.dart:191) #1 MqttServerConnection._onData (package:mqtt5_client/src/connectionhandling/server/mqtt_server_connection.dart:78) #2 _rootRunUnary (dart:async/zone.dart:1399) #3 _CustomZone.runUnary (dart:async/zone.dart:1300) #4 _CustomZone.runUnaryGuarded (dart:async/zone.dart:1209) #5 _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:339) #6 _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271) #7 _SyncStreamControllerDispatch._sendData (dart:async/stream_controller.dart:774) #8 _StreamController._add (dart:async/stream_controller.dart:648) #9 _StreamController.add (dart:async/stream_controller.dart:596) #10 _Socket._onData (dart:io-patch/socket_patch.dart:2324) #11 _rootRunUnary (dart:async/zone.dart:1407) #12 _CustomZone.runUnary (dart:async/zone.dart:1300) #13 _CustomZone.runUnaryGuarded (dart:async/zone.dart:1209) #14 _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:339) #15 _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271) #16 _SyncStreamControllerDispatch._sendData (dart:async/stream_controller.dart:774) #17 _StreamController._add (dart:async/stream_controller.dart:648) #18 _StreamController.add (dart:async/stream_controller.dart:596) #19 new _RawSocket.<anonymous closure> (dart:io-patch/socket_patch.dart:1849) #20 _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:1322) #21 _microtaskLoop (dart:async/schedule_microtask.dart:40) #22 _startMicrotaskLoop (dart:async/schedule_microtask.dart:49)

[Extenda-TimRoberson]

I'm working on the same codebase as @devaronius, some more context on this: This is using mqtt5_client v3.3.5 It seems to be caused by the messageType being reserved1 which throws MqttInvalidHeaderException through the default case of getMessage in MqttMessageFactory which is then caught in createFrom and thrown as MqttInvalidMessageException after which its attempts to clear the byte buffer with position is not zero

I/flutter ( 6506): 2023-01-31 13:17:07.947117 -- MqttServerConnection::_onData - Message Received Started <<< I/flutter ( 6506): 2023-01-31 13:17:07.949513 -- MqttServerConnection::_ondata - adding incoming data, data length is 6, message stream length is 1, message stream position is 0 I/flutter ( 6506): 2023-01-31 13:17:07.952328 -- Available bytes(7) is less than the message size 64 I/flutter ( 6506): 2023-01-31 13:17:07.954914 -- MqttServerConnection::_onData - Message Received Ended <<< I/flutter ( 6506): 2023-01-31 13:17:17.696947 -- MqttServerConnection::_onData - Message Received Started <<< I/flutter ( 6506): 2023-01-31 13:17:17.698422 -- MqttServerConnection::_ondata - adding incoming data, data length is 87, message stream length is 7, message stream position is 0 I/flutter ( 6506): 2023-01-31 13:17:17.712214 -- MqttServerConnection::_ondata - message is not yet valid, waiting for more data ... I/flutter ( 6506): 2023-01-31 13:17:17.717159 -- MqttServerConnection::_ondata - exception raised is mqtt-client::InvalidMessageException: The data provided in the message stream was not a valid MQTT Message, exception is mqtt-client::InvalidHeaderException: The Message Type specified (MessageType = MqttMessageType.reserved1 Duplicate = false Retain = false Qos = atMostOnce Size = 64.messageType) is not a valid MQTT Message type or currently not supported., bytestream is [0, 64, 4, 0, 3, 0, 0, 50, 85, 0, 42, 77, 121, 83, 99, 97, 110, 53, 47, 57, 57, 50, 48, 47, 65, 116, 116, 101, 110, 100, 97, 110, 116, 47, 83, 116, 97, 116, 117, 115, 85, 112, 100, 97, 116, 101, 47, 49, 47, 52, 55, 50, 48, 0, 1, 0, 123, 34, 112, 105, 110, 103, 34, 58, 116, 114, 117, 101, 44, 34, 97, 99, 116, 105, 118, 97, 116, 101, 84, 101, 114, 109, 105, 110, 97, 108, 34, 58, 102, 97, 108, 115, 101, 125]

I/flutter ( 6506): 2023-01-31 13:17:18.140232 -- MqttConnectionHandlerBase::sendMessage - sending message started >>> -> MQTTMessage of type MqttMessageType.pingRequest I/flutter ( 6506): MessageType = MqttMessageType.pingRequest Duplicate = false Retain = false Qos = atMostOnce Size = 0 I/flutter ( 6506): 2023-01-31 13:17:18.148840 -- MqttConnectionHandlerBase::sendMessage - sending message ended >>> I/flutter ( 6506): 2023-01-31 13:17:18.466508 -- MqttServerConnection::_onData - Message Received Started <<< I/flutter ( 6506): 2023-01-31 13:17:18.467697 -- MqttServerConnection::_ondata - adding incoming data, data length is 2, message stream length is 94, message stream position is 2 I/flutter ( 6506): 2023-01-31 13:17:18.469236 -- MqttServerConnection::_ondata - message is not yet valid, waiting for more data ... I/flutter ( 6506): 2023-01-31 13:17:18.469734 -- MqttServerConnection::_ondata - exception raised is mqtt-client::InvalidMessageException: The data provided in the message stream was not a valid MQTT Message, exception is mqtt-client::InvalidHeaderException: The Message Type specified (MessageType = MqttMessageType.reserved1 Duplicate = false Retain = false Qos = exactlyOnce Size = 0.messageType) is not a valid MQTT Message type or currently not supported., bytestream is [0, 64, 4, 0, 3, 0, 0, 50, 85, 0, 42, 77, 121, 83, 99, 97, 110, 53, 47, 57, 57, 50, 48, 47, 65, 116, 116, 101, 110, 100, 97, 110, 116, 47, 83, 116, 97, 116, 117, 115, 85, 112, 100, 97, 116, 101, 47, 49, 47, 52, 55, 50, 48, 0, 1, 0, 123, 34, 112, 105, 110, 103, 34, 58, 116, 114, 117, 101, 44, 34, 97, 99, 116, 105, 118, 97, 116, 101, 84, 101, 114, 109, 105, 110, 97, 108, 34, 58, 102, 97, 108, 115, 101, 125, 208, 0]

[shamblett]

So is the message type really coming in as reserved1 or is the incoming message correct and the client is decoding it incorrectly/?

[Extenda-TimRoberson]

I did some more investigating and it seems like it's caused by a leading space in the received data, when decoding the bytes received myself it seems like the data coming through is formatted as such: " 2W ,[Topic] [payload]", the app sending data is also using the mqtt5_client package of 3.3.5, and the " 2W " does not seem to be coming from our end, does it ring any bells on your side?

[shamblett]

Can't say I've seen this before, then again I'm not sure I've had an issue where the sending and receiving client are both the mqtt5_client. I'll have a look at the message stream from your piccy above.

Is it always the same topic and payload? How are you constructing the payload?

An obvious test is to use a different sending mqtt client but I appreciate this may be difficult.

[Extenda-TimRoberson]

The topic includes an identifier but otherwise is always the same and the payload is formatted as json. I did some test in rolling back to mqtt 3.1 implementations in our apps. When I changed the receiver to mqtt 3.1 implementation (keeping the publisher on mqtt 5) it received the message just fine. When I changed the publisher to mqtt 3.1 implementation (keeping the receiver on mqtt 5) the error showed up again in the receiver So it seems like there are some leading characters being added to the message in the receiving app when using mqtt5. Side note that it seems to be random, on another occasion it was prefixed with " @ 2U *" [0, 64, 4, 0, 3, 0, 0, 50, 85, 0, 42, 77, 121, 83, 99, 97, 110, 53, 47, 57, 57, 50, 48, 47, 65, 116, 116, 101, 110, 100, 97, 110, 116, 47, 83, 116, 97, 116, 117, 115, 85, 112, 100, 97, 116, 101, 47, 49, 47, 52, 55, 50, 48, 0, 1, 0, 123, 34, 112, 105, 110, 103, 34, 58, 116, 114, 117, 101, 44, 34, 97, 99, 116, 105, 118, 97, 116, 101, 84, 101, 114, 109, 105, 110, 97, 108, 34, 58, 102, 97, 108, 115, 101, 125 ]

[shamblett]

Yep, its the leading zero in the incoming stream, if you remove this the message correctly decodes into a publish ack, so we are occasionally still corrupting the incoming byte stream. I'll find out why.

[shamblett]

Where exactly in the code did you dump the above list?

[Extenda-TimRoberson]

I got those from the same breakpoint as the previous one, so readFrom in MqttHeader; line 82

[shamblett]

OK, I've created an issue44 branch for this and added some updates and more logging, could you update your pubspec to point to my test branch, i.e. update the mqtt5_client dependency to - git: url: https://github.com/shamblett/mqtt5_client.git ref: issue44

Thanks

[Extenda-TimRoberson]

The message is now coming through however there seems to be quite a delay followed by some duplicated messages coming through. The log file is attached. Mqtt5_Issue44Log_Feb17.txt

Also encountered a different issue yesterday but haven't been able to reproduce today with the Mqqt5 package logging on 2023-02-16 14:25:37.531 - SEVERE - Caught error: - Error details: Null check operator used on a null value - Stacktrace: #0 MqttPublishingManager.handlePublishComplete (package:mqtt5_client/src/mqtt_publishing_manager.dart:227:75)

1 MqttConnectionHandlerBase.messageAvailable (package:mqtt5_client/src/connectionhandling/mqtt_connection_handler_base.dart:237:15)

2 _rootRunUnary (dart:async/zone.dart:1406:47)

3 _CustomZone.runUnary (dart:async/zone.dart:1307:19)

4 _CustomZone.runUnaryGuarded (dart:async/zone.dart:1216:7)

5 CastStreamSubscription._onData (dart:_internal/async_cast.dart:85:11)

6 _rootRunUnary (dart:async/zone.dart:1406:47)

7 _CustomZone.runUnary (dart:async/zone.dart:1307:19)

8 _CustomZone.runUnaryGuarded (dart:async/zone.dart:1216:7)

9 _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:339:11)

10 _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271:7)

11 _ForwardingStreamSubscription._add (dart:async/stream_pipe.dart:123:11)

12 _WhereStream._handleData (dart:async/stream_pipe.dart:195:12)

13 _ForwardingStreamSubscription._handleData (dart:async/stream_pipe.dart:153:13)

14 _rootRunUnary (dart:async/zone.dart:1406:47)

15 _CustomZone.runUnary (dart:async/zone.dart:1307:19)

16 _CustomZone.runUnaryGuarded (dart:async/zone.dart:1216:7)

17 _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:339:11)

18 _DelayedData.perform (dart:async/stream_impl.dart:515:14)

19 _PendingEvents.handleNext (dart:async/stream_impl.dart:620:11)

20 _PendingEvents.schedule. (dart:async/stream_impl.dart:591:7)

21 _rootRun (dart:async/zone.dart:1390:47)

22 _CustomZone.run (dart:async/zone.dart:1300:19)

23 _CustomZone.runGuarded (dart:async/zone.dart:1208:7)

24 _CustomZone.bindCallbackGuarded. (dart:async/zone.dart:1248:23)

25 _rootRun (dart:async/zone.dart:1398:13)

26 _CustomZone.run (dart:async/zone.dart:1300:19)

27 _CustomZone.runGuarded (dart:async/zone.dart:1208:7)

28 _CustomZone.bindCallbackGuarded. (dart:async/zone.dart:1248:23)

29 _microtaskLoop (dart:async/schedule_microtask.dart:40:21)

30 _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)

Please let me know if there's any more data needed

Thanks

[shamblett]

Your log shows a lot of exceptions at its start, then it seems to settle down, are you expecting this? The performance hit is almost certainly the extra logging, I'll remove this when we don't need it.

[shamblett]

OK, I've updated the branch with another potential fix if you could give it a try, thanks.

[Extenda-TimRoberson]

Works like a charm now on the issue44 branch, thanks so much

[shamblett]

OK thanks, I'll remove the excess logging, push this into master and re release the package.

[shamblett]

Version 3.3.6 released.