MQTT for Tcl

I am running a simple subscriber client with this code, eg.

  set client [mqtt new]

  $client connect uwe-client $::addr

  $client subscribe {BCDS/#} message_callback

and while it works with a local broker, eg. mosquitto, it fails with an internet broker, eg. iot.eclipse.org.

The stack trace is

1507901608909 (::oo::Obj22_coro): can't read "msgid": no such variable
    while executing
"dict set rc msgid $msgid"
    (class "::mqtt" method "receive" line 35)
    invoked from within
"my receive"
    (class "::mqtt" method "listen" line 27)
    invoked from within
"my listen"

While debugging this problem, it seems that the API cannot handle concatenated messages into one packet. I cannot prove it without much effort. Can someone tell me yes or no whether concatenated messages are handled properly, eg. the packet to the receive method contains a MQTT request and a half?

The code was designed to correctly handle MQTT messages that are joined or split over TCP messages. Just to make sure it works as expected I wrote a small broker that sends 1½ PUBLISH message in one TCP message, and the remainder of the second PUBLISH message in another TCP message. I have confirmed this causes no problems.

The only way I can imagine you can get the error you reported is if the MQTT message is malformed. How quickly do you encounter the problem when connecting to iot.eclipse.org? I left your code running for over an hour and a half and did not see the error.

Nevertheless, a malformed MQTT message should not cause a stack dump. So I added some checks that will now report a malformed message via the logging mechanism of the library, and then continue processing subsequent messages.

If you still experience this problem, please activate logging and share what that reports.

Reproduced with originally reported code. Does not stack trace any more with latest, but now hangs intermittently. The message just before the hang is truncated. Can easily reproduce on iot.eclipse.org with wildcard topic #, eg.

lots of output, then a hang, last couple of lines:

topic Advantech/00D0C9FEDF69/Device_Status content {"status":"connect","name":"ADAM6250","macid":"00D0C9FEDF69","ipaddr":"192.168.1.50"} flag 1
topic Advantech/352753090098516/data content {"s":0,"t":"2019-01-17T16:47:30Z","q":192,"c":0,"di1":false,"di2":false,"di4":false,"di5":8.000,"di6":8} flag 1
topic Advantech/00D0C9FAC804/Device_Status content {"status":"connect","name":"WISE-4012","macid":"00D0C9FAC804","ipaddr":"192.168.0.106"} flag 1
topic Advantech/00D0C9FAC804/data content {"s":9,"t":"2019-01-05T06:04:35Z","q":192,"c":0,"ai1":423.132,"ai_st1":0,"ai2":24.109,"ai_st2":0} flag 1
topic Advantech/00D0C9F70C85/Device_Status content {"status":"connect","name":"WISE-4050_00D0C9F70C85","macid":"00D0C9F70C85","ipaddr":"192.168.0.108"}1CTCocina/feedback96:41
Licht3331:
          julinho/ flag 1

Notice there are binary characters before "CTCocina" that this form does not show. If you send non-random messages you can easily debug this as we do with our clients.

LOG Received PUBLISH (d0, q0, r1, 'Advantech/00D0C9FAC804/Device_Status', ... (87 bytes))
topic Advantech/00D0C9FAC804/Device_Status content {"status":"connect","name":"WISE-4012","macid":"00D0C9FAC804","ipaddr":"192.168.0.106"} flag 1
LOG Received PUBLISH (d0, q0, r1, 'Advantech/00D0C9FAC804/data', ... (97 bytes))
topic Advantech/00D0C9FAC804/data content {"s":9,"t":"2019-01-05T06:13:09Z","q":192,"c":0,"ai1":435.187,"ai_st1":0,"ai2":25.940,"ai_st2":0} flag 1
LOG Received PUBLISH (d0, q0, r1, 'Advantech/00D0C9F70C85/Device_Status', ... (149 bytes))
topic Advantech/00D0C9F70C85/Device_Status content {"status":"connect","name":"WISE-4050_00D0C9F70C85","macid":"00D0C9F70C85","ipaddr":"192.168.0.108"}1CTCocina/feedback96:41
Licht3331:
          julinho/ flag 1
LOG Received PUBCOMP (Mid: 29793)
LOG Received CONNACK (34, 118)
LOG Received PUBCOMP (Mid: 14882)
LOG Received CONNACK (34, 100)
LOG Received PUBREC (Mid: 2592)
LOG Sending PUBREL (Mid: 2592)
LOG Received CONNACK (58, 32)
LOG Received CONNACK (10, 32)
LOG wrong # args: should be "throw type message"
    while executing
"throw {MQTT PAYLOAD UNKNOWN}"
LOG Received PUBACK (Mid: 27753)
LOG Received PUBREC (Mid: 13634)
LOG Sending PUBREL (Mid: 13634)
LOG Received PUBREC (Mid: 18516)
LOG Sending PUBREL (Mid: 18516)
LOG wrong # args: should be "throw type message"
    while executing
"throw {MQTT PAYLOAD DEPLETED}"
    (class "::mqtt" method "payload" line 12)
    invoked from within
"my payload {}"
    invoked from within
"payload Su"
    (class "::mqtt" method "string" line 2)
    invoked from within
"my string protocol"
LOG (::oo::Obj22_coro): can't delete "payload": command doesn't exist
    while executing
"rename payload {}"
    (class "::mqtt" method "receive" line 122)
    invoked from within
"my receive $fd"
    (class "::mqtt" method "dialog" line 71)
    invoked from within
"my dialog $host $port"
LOG Connecting to iot.eclipse.org on port 1883
LOG Sending CONNECT (c1, k60)

The problem only happened when a message was both split and immediately followed by another message. In that case, the code could read too much data, as a result of which it got out of sync. This should be fixed by checkin [9e9c3c711f].