Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Error when clearing MqttByteBuffer #44

Closed
devaronius opened this issue Jan 31, 2023 · 15 comments
Closed

Error when clearing MqttByteBuffer #44

devaronius opened this issue Jan 31, 2023 · 15 comments

Comments

@devaronius
Copy link

devaronius commented Jan 31, 2023 •
edited
Loading

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

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

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

image

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

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

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

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

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

@Extenda-TimRoberson
Copy link

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

@shamblett
Copy link
Owner

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

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

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

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

@shamblett shamblett mentioned this issue Feb 19, 2023
Closed
@Extenda-TimRoberson
Copy link

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

@shamblett
Copy link
Owner

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

@shamblett
Copy link
Owner

Version 3.3.6 released.

@devaronius devaronius reopened this Feb 22, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@shamblett @devaronius @Extenda-TimRoberson