eclipse / paho.mqtt.javascript

paho.mqtt.javascript
Other
1.15k stars 467 forks source link

onMessageArrived called once for multiple messages, accessing payloadString causes UTF8 errors #47

Closed jpwsutton closed 8 years ago

jpwsutton commented 8 years ago

migrated from Bugzilla #407909 status CLOSED severity major in component MQTT-JS for --- Reported in version v0.5 on platform PC Assigned to: Andrew Banks

On 2013-05-13 11:34:06 -0400, Alexander Rust wrote:

Hi,

I just started playing with the Paho-Js client and tried to plug it into the existing code for a home-automation webinterface that is yet based on the mosquitto.js client. The client is set to subscribe to a some topics, for which it receives ~50 retained messages from a Mosquitto broker (v. 1.1.3) after the subscription.

Sometimes the onMessageArrived method is called with one message for which the destination name and payload string are correct.

In this case my code correctly reports topic:/devices/158212-Socket-11011-00001/controls/Power/meta/type payload:switch

However, mostly the method ends up being called once for ~30 message with the destination name and payload string messed up totally.

topic:/devices/158212-Socket-11011-00001/meta/name payload:Aquarium18,/devices/158212-Socket-11011-00001/meta/roomWohnzimmer1&/devices/294028-solar/meta/roomBucks1//devices/294028-solar/meta/nameSolar Position13,/devices/158212-Socket-11011-00010/meta/roomBucks11,/devices/158212-Socket-11011-00010/meta/nameAmp13,/devices/158212-Socket-11011-01000/meta/roomBucks12,/devices/158212-Socket-11011-01000/meta/nameDesk12,/devices/158212-Socket-11011-00100/meta/roomFlur19,/devices/158212-Socket-11011-00100/meta/nameCampusboard1.#/devices/465632-Ambilight/meta/nameAmbilight1*#/devices

I'm not sure whether I'm just wrongly assuming that the onMessageArrived method is called once for each received message or if message.payloadString has some weirdness going on.

In either case, accessing the payloadString often results in parseUTF8 errors:

Uncaught Error: AMQJS0009E Malformed UTF data:90 -7d . paho.js:598 parseUTF8 paho.js:598 _getPayloadString paho.js:1794 payloadString paho.js:1842 mqttSocketonmessage app.js:681 ClientImpl._receiveMessage paho.js:1281 ClientImpl._receivePublish paho.js:1256 ClientImpl._on_socket_message paho.js:1143 (anonymous function) paho.js:150

Additionally, or related to the above isse the string "cleanSession" seems to end up as the payloadString.

Please let me know if there is additional information that I should provide for this issue.

On 2013-05-13 11:54:57 -0400, Andy Piper wrote:

Thanks, hopefully Andrew can respond on expected behaviour of the JS client.

On 2013-05-15 00:55:19 -0400, Simon Racliffe wrote:

Alexander,

I had similar problems, using Mosquitto server, mod_websocket_mosquitto and mod_websocket. I suspect you are using a similar config. If so upgrade your Mosquitto server to the latest at https://bitbucket.org/oojah/mosquitto/downloads. Also mod_websocket_mosquitto is very simplistic and if the group of published messages is greater than 1024 bytes it WILL break.

I have written a patch for mod_websocket_mosquitto whcih properly parse the stream and passes it on correctly. I have post this on the mod_websocket_mosquitto issues pages, but have not yet had feedback from its author. Have a look at https://github.com/willem4ever/mod_websocket_mosquitto/issues/4

Cheers Simon

On 2013-05-15 06:01:09 -0400, Alexander Rust wrote:

Thanks Simon,

using a freshly compiled version of Mosquitto showed the same issues. Note, that I'm not using mod_websocket but https://github.com/stylpen/WSS that is written by a good friend of mine.

It's quite simple and solid, but as it was written and tested with the Mosquitto.js library I'll see whether there are some conditions that just worked with the mosquitto library.

On 2013-05-15 08:36:45 -0400, Simon Racliffe wrote:

Alexander,

It still sounds like a similar problem to what I was having where the software that wrapped the MQTT data into the websocket packets wasn't smart enough to deal with the mosquitto server sending a bunch of publish messages in a group.

I was only able to debug the problems I was having using wireshark, and almost blamed the wrong piece of software for the problem. The latest development version of wireshark also does a much better job of decoding the websocket protocol.

Hope something here helps.

Cheers Simon

On 2013-05-16 11:50:07 -0400, Alexander Rust wrote:

The Websocket server component looks solid, Simon. I also tried it with a patched version of mod_websocket, which showed the same issues.

Additionally, when I think about it, it was able to deal with the same bunch of published messages before, with the other library.

On 2013-05-18 06:33:51 -0400, Andrew Banks wrote:

Alexander, onMessagearrived should get driven once per message.

Could you capture some client side trace, as illustrated below, so that I can see what is being sent to the client to cause it to do what you are seeing?

// Start the client tracing, the trace records capture the method calls and network flows from now on. client.startTrace();

... generate the problem

window.location="mailto:helpdesk@"+location.hostname+"?Subject=Web%20Messaging%20Utility%20Trace&body="+client.getTraceLog().join("%0A"); client.stopTrace();

On 2013-05-18 07:05:54 -0400, Alexander Rust wrote:

Hi,

I gathered the following traces by starting them in the connect-onSuccess method, right before I subscribe to my topics that contain retained messages.

Trace a) was stopped in try-catch block around console.log(message.payloadString); in the onMessageArrived method where the Error: AMQJS0009E Malformed UTF data:90 -7d was thrown.

Trace b) was stopped two seconds after the subscribe when all retained messages were received from the broker.

Trace a) Client.startTrace%0A "2013-05-18T11:02:04.279Z"%0A "0.0.0.0"%0AClient.subscribe%0A "/devices/+/controls/+/meta/+"%0A {}%0AClient._socket_send%0A {"type":8,"topics":["/devices/+/controls/+/meta/+"],"requestedQos":[0],"messageIdentifier":1}%0AClient.subscribe%0A "/devices/+/controls/+"%0A {}%0AClient._socket_send%0A {"type":8,"topics":["/devices/+/controls/+"],"requestedQos":[0],"messageIdentifier":2}%0AClient.subscribe%0A "/devices/+/meta/#"%0A {}%0AClient._socket_send%0A {"type":8,"topics":["/devices/+/meta/#"],"requestedQos":[0],"messageIdentifier":3}%0AClient._on_socket_message%0A {"byteLength":5}%0AClient._on_socket_message%0A {"type":9,"messageIdentifier":1,"grantedQos":{"0":0,"length":1,"byteLength":1,"byteOffset":4,"buffer":{"byteLength":5}}}%0AClient._on_socket_message%0A {"byteLength":803}%0AClient._on_socket_message%0A {"type":3,"payloadMessage":{}}%0AClient._on_socket_message%0A {"byteLength":5}%0AClient._on_socket_message%0A {"type":9,"messageIdentifier":2,"grantedQos":{"0":0,"length":1,"byteLength":1,"byteOffset":4,"buffer":{"byteLength":5}}}%0AClient._on_socket_message%0A {"byteLength":1170}%0AClient._on_socket_message%0A {"type":3,"payloadMessage":{}}%0AClient.getTraceLog%0A "2013-05-18T11:02:04.347Z"%0AClient.getTraceLog in flight messages%0A%0A_sentMessages %0A "3"%0A {"type":8,"topics":["/devices/+/meta/#"],"requestedQos":[0],"messageIdentifier":3}

Trace b) Client.startTrace%0A "2013-05-18T10:44:48.540Z"%0A "0.0.0.0"%0AClient.subscribe%0A "/devices/+/controls/+/meta/+"%0A {}%0AClient._socket_send%0A {"type":8,"topics":["/devices/+/controls/+/meta/+"],"requestedQos":[0],"messageIdentifier":1}%0AClient.subscribe%0A "/devices/+/controls/+"%0A {}%0AClient._socket_send%0A {"type":8,"topics":["/devices/+/controls/+"],"requestedQos":[0],"messageIdentifier":2}%0AClient.subscribe%0A "/devices/+/meta/#"%0A {}%0AClient._socket_send%0A {"type":8,"topics":["/devices/+/meta/#"],"requestedQos":[0],"messageIdentifier":3}%0AClient._on_socket_message%0A {"byteLength":5}%0AClient._on_socket_message%0A {"type":9,"messageIdentifier":1,"grantedQos":{"0":0,"length":1,"byteLength":1,"byteOffset":4,"buffer":{"byteLength":5}}}%0AClient._on_socket_message%0A {"byteLength":803}%0AClient._on_socket_message%0A {"type":3,"payloadMessage":{}}%0AClient._on_socket_message%0A {"byteLength":555}%0AClient._on_socket_message%0A {"type":9,"messageIdentifier":2,"grantedQos":{"0":0,"1":49,"2":52,"3":0,"4":49,"5":47,"6":100,"7":101,"8":118,"9":105,"10":99,"11":101,"12":115,"13":47,"14":49,"15":53,"16":56,"17":50,"18":49,"19":50,"20":45,"21":83,"22":111,"23":99,"24":107,"25":101,"26":116,"27":45,"28":49,"29":49,"30":48,"31":49,"32":49,"33":45,"34":48,"35":48,"36":48,"37":48,"38":49,"39":47,"40":99,"41":111,"42":110,"43":116,"44":114,"45":111,"46":108,"47":115,"48":47,"49":80,"50":111,"51":119,"52":101,"53":114,"54":48,"55":49,"56":44,"57":0,"58":37,"59"...101,"476":115,"477":47,"478":49,"479":53,"480":56,"481":50,"482":49,"483":50,"484":45,"485":83,"486":111,"487":99,"488":107,"489":101,"490":116,"491":45,"492":49,"493":49,"494":48,"495":49,"496":49,"497":45,"498":48,"499":48,"500":49,"501":48,"502":48,"503":47,"504":109,"505":101,"506":116,"507":97,"508":47,"509":110,"510":97,"511":109,"512":101,"513":67,"514":97,"515":109,"516":112,"517":117,"518":115,"519":98,"520":111,"521":97,"522":114,"523":100,"524":49,"525":46,"526":0,"527":35,"528":47,"529":100,"530":101,"531":118,"532":105,"533":99,"534":101,"535":115,"536":47,"537":52,"538":54,"539":53,"540":54,"541":51,"542":50,"543":45,"544":65,"545":109,"546":98,"547":105,"548":108,"549":105,"550":103,"551":104,"552":116,"553":47,"554":109,"555":101,"556":116,"557":97,"558":47,"559":110,"560":97,"561":109,"562":101,"563":65,"564":109,"565":98,"566":105,"567":108,"568":105,"569":103,"570":104,"571":116,"572":49,"573":42,"574":0,"575":35,"576":47,"577":100,"578":101,"579":118,"580":105,"581":99,"582":101,"583":115,"584":47,"585":52,"586":54,"587":53,"588":54,"589":51,"590":50,"591":45,"592":65,"593":109,"594":98,"595":105,"596":108,"597":105,"598":103,"599":104,"600":116,"601":47,"602":109,"603":101,"604":116,"605":97,"606":47,"607":114,"608":111,"609":111,"610":109,"611":66,"612":117,"613":99,"614":107,"615":115,"length":616,"byteLength":616,"byteOffset":4,"buffer":{"byteLength":620}}}%0AClient.getTraceLog%0A "2013-05-18T10:44:50.542Z"%0AClient.getTraceLog in flight messages%0A

On 2013-05-20 06:02:45 -0400, Andrew Banks wrote:

Alexander, trace b) shows that the server is packing multiple MQTT command messages into a Websocket frame, the client assumes the server is sending it one MQTT message per frame. Your UTF-8 conversion error has probably come about because the following message has been joined on to the publication message. There is an Oasis is discussing whether WebSockets should carry multiple or partial MQTT messages in each frame.

https://tools.oasis-open.org/issues/browse/MQTT-1

On 2013-05-25 06:38:19 -0400, Alexander Rust wrote:

Thanks Andrew,

the Mosquitto library was perfectly happy with that kind of behavior. We modified our Websocket bridge accordingly to just send one MQTT message per Websocket frame which did fix all errors reported previously.

I think this can be closed now, thanks for your help.