search

sskaje / mqtt

MQTT Client class
https://sskaje.me/category/MQTT/
MIT License
86 stars 33 forks source link

PHP Fatal error: Uncaught exception 'SPMQTT_Exception' with message 'SUBSCRIBE/SUBACK message identifier mismatch #1

Closed Amblego closed 10 years ago

Amblego commented 10 years ago

Sometimes MQTT-client breaks down with exception "PHP Fatal error: Uncaught exception 'SPMQTT_Exception' with message 'SUBSCRIBE/SUBACK message identifier mismatch: ........ in z_MQTT_class.php:356"

Debug mode log:

[2014-04-09 19:54:12.882859] socket_connect() [2014-04-09 19:54:12.886875] socket_connect(): connect to=tcp://127.0.0.1:1883/ [2014-04-09 19:54:12.887093] connect() [2014-04-09 19:54:12.887205] connect(): clientid=clientid [2014-04-09 19:54:12.887257] connect(): keepalive=90 [2014-04-09 19:54:12.887304] connect(): username=gamble0 password=123123 [2014-04-09 19:54:12.887405] Message Build: remaining length=41 [2014-04-09 19:54:12.887463] Message write: message_type=1 [2014-04-09 19:54:12.887526] Message Build: remaining length=41 [2014-04-09 19:54:12.887658] Message write: message=10 29 00 06 4d 51 49 73 64 70 03 c0 00 5a 00 0a 63 6c 69 65 6e 74 5f 69 64 5f 00 07 67 61 6d 62 6c 65 30 00 06 31 32 33 31 32 33 [2014-04-09 19:54:12.887705] Message write: bytes written=43 [2014-04-09 19:54:12.887749] connect(): bytes written=43 [2014-04-09 19:54:12.887795] Message Read: message_type=2 [2014-04-09 19:54:12.887850] Message Read: bytes to read=4 [2014-04-09 19:54:12.887931] Message read: message=20 02 00 00 [2014-04-09 19:54:12.887976] Message Read: bytes to read=4 [2014-04-09 19:54:12.888029] Connected to Broker [2014-04-09 19:54:12.888264] connect(): connected=1 [2014-04-09 19:54:12.888371] ping() [2014-04-09 19:54:12.888483] Message write: message_type=12 [2014-04-09 19:54:12.888590] Message Build: remaining length=0 [2014-04-09 19:54:12.889038] Message write: message=c0 00 [2014-04-09 19:54:12.889178] Message write: bytes written=2 [2014-04-09 19:54:12.889270] Message Read: message_type=13 [2014-04-09 19:54:12.889372] Message Read: bytes to read=2 [2014-04-09 19:54:12.889505] Message read: message=d0 00 [2014-04-09 19:54:12.889595] Message Read: bytes to read=2 [2014-04-09 19:54:12.889801] Message PINGRESP: success [2014-04-09 19:54:12.889895] ping(): response 1 array(2) { ["#"]=> int(0) ["/$SYS/#"]=> int(0) } [2014-04-09 19:54:12.890398] Message write: message_type=8 [2014-04-09 19:54:12.890499] Message SUBSCRIBE: msgid=35486 [2014-04-09 19:54:12.890604] Message Build: remaining length=16 [2014-04-09 19:54:12.891123] Message write: message=82 10 8a 9e 00 01 23 00 00 07 2f 24 53 59 53 2f 23 00 [2014-04-09 19:54:12.891299] Message write: bytes written=18 [2014-04-09 19:54:12.891470] subscribe(): bytes written=18 [2014-04-09 19:54:12.891684] Message Read: message_type=9 [2014-04-09 19:54:12.891808] Message Read: bytes to read=4 [2014-04-09 19:54:12.891931] Message read: message=90 04 8a 9e [2014-04-09 19:54:12.892020] Message Read: bytes to read=4 [2014-04-09 19:54:12.892153] Message SUBACK: success [2014-04-09 19:54:12.892271] loop() [2014-04-09 19:54:12.928167] checkAndPing() [2014-04-09 19:54:12.928335] loop(): message_type=3, dup=0, QoS=0, RETAIN=1 [2014-04-09 19:54:12.928404] loop(): remaining length=44 to read=42 [2014-04-09 19:54:12.928506] loop(): read message=31 2c 00 29 67 6f 61 6d 62 6c 65 2f 73 65 6e 73 6f 72 73 2f 31 33 39 37 30 34 37 33 34 36 2f 30 31 39 33 39 38 2f 76 6f 6c 74 61 67 65 36 [2014-04-09 19:54:12.928561] loop(): PUBLISH [2014-04-09 19:54:12.928622] loop(): PUBLISH QoS=0 PASS

goamble/sensors/1397047346/019398/voltage 6

[2014-04-09 19:54:12.928726] checkAndPing() [2014-04-09 19:54:12.928792] loop(): message_type=3, dup=0, QoS=0, RETAIN=1 [2014-04-09 19:54:12.928848] loop(): remaining length=40 to read=38 [2014-04-09 19:54:12.928942] loop(): read message=31 28 00 25 67 6f 61 6d 62 6c 65 2f 73 65 6e 73 6f 72 73 2f 31 33 39 37 30 34 37 33 34 36 2f 30 31 39 33 39 38 2f 67 73 6d 34 [2014-04-09 19:54:12.928994] loop(): PUBLISH [2014-04-09 19:54:12.929048] loop(): PUBLISH QoS=0 PASS

goamble/sensors/1397047346/019398/gsm 4

[2014-04-09 19:54:12.929124] checkAndPing() [2014-04-09 19:54:12.929188] loop(): message_type=3, dup=0, QoS=0, RETAIN=1 [2014-04-09 19:54:12.929243] loop(): remaining length=41 to read=39 [2014-04-09 19:54:12.929338] loop(): read message=31 29 00 26 67 6f 61 6d 62 6c 65 2f 73 65 6e 73 6f 72 73 2f 31 33 39 37 30 34 37 33 34 36 2f 30 31 39 33 39 38 2f 73 61 74 73 30 [2014-04-09 19:54:12.929391] loop(): PUBLISH [2014-04-09 19:54:12.929444] loop(): PUBLISH QoS=0 PASS

goamble/sensors/1397047346/019398/sats 0

[2014-04-09 19:54:12.929518] checkAndPing() [2014-04-09 19:54:12.929581] loop(): message_type=3, dup=0, QoS=0, RETAIN=1 [2014-04-09 19:54:12.929636] loop(): remaining length=54 to read=52 [2014-04-09 19:54:12.929744] loop(): read message=31 36 00 2a 67 6f 61 6d 62 6c 65 2f 73 65 6e 73 6f 72 73 2f 31 33 39 37 30 34 37 33 34 36 2f 30 31 39 33 39 38 2f 6c 61 73 74 5f 75 70 64 31 33 39 37 30 34 37 33 34 36 [2014-04-09 19:54:12.929797] loop(): PUBLISH [2014-04-09 19:54:12.929851] loop(): PUBLISH QoS=0 PASS

goamble/sensors/1397047346/019398/last_upd 1397047346

[2014-04-09 19:55:02.733819] checkAndPing() [2014-04-09 19:55:02.733972] checkAndPing(): current_time=1397058902, time=1397058852, keepalive=90 [2014-04-09 19:55:02.734019] ping() [2014-04-09 19:55:02.734083] Message write: message_type=12 [2014-04-09 19:55:02.734138] Message Build: remaining length=0 [2014-04-09 19:55:02.734223] Message write: message=c0 00 [2014-04-09 19:55:02.734268] Message write: bytes written=2 [2014-04-09 19:55:02.734335] Message Read: message_type=13 [2014-04-09 19:55:02.734389] Message Read: bytes to read=2 [2014-04-09 19:55:02.734457] Message read: message=30 3e [2014-04-09 19:55:02.734502] Message Read: bytes to read=2 [2014-04-09 19:55:02.734560] Message PINGRESP: type mismatch [2014-04-09 19:55:02.734605] ping(): response 0 [2014-04-09 19:55:02.734650] loop(): EOF detected [2014-04-09 19:55:02.734692] reconnect() [2014-04-09 19:55:02.734733] reconnect(): close current [2014-04-09 19:55:02.734774] disconnect() [2014-04-09 19:55:02.734825] Message write: message_type=14 [2014-04-09 19:55:02.734874] Message Build: remaining length=0 [2014-04-09 19:55:02.734947] Message write: message=e0 00 [2014-04-09 19:55:02.734991] Message write: bytes written=2 [2014-04-09 19:55:02.735035] socket_close() [2014-04-09 19:55:02.735125] socket_connect() [2014-04-09 19:55:02.735171] socket_connect(): connect to=tcp://127.0.0.1:1883/ [2014-04-09 19:55:02.735318] connect() [2014-04-09 19:55:02.735379] connect(): clientid=clientid [2014-04-09 19:55:02.735425] connect(): keepalive=90 [2014-04-09 19:55:02.735470] connect(): username=gamble0 password=123123 [2014-04-09 19:55:02.735534] Message Build: remaining length=41 [2014-04-09 19:55:02.735582] Message write: message_type=1 [2014-04-09 19:55:02.735639] Message Build: remaining length=41 [2014-04-09 19:55:02.735747] Message write: message=10 29 00 06 4d 51 49 73 64 70 03 c0 00 5a 00 0a 63 6c 69 65 6e 74 5f 69 64 5f 00 07 67 61 6d 62 6c 65 30 00 06 31 32 33 31 32 33 [2014-04-09 19:55:02.735794] Message write: bytes written=43 [2014-04-09 19:55:02.735836] connect(): bytes written=43 [2014-04-09 19:55:02.735879] Message Read: message_type=2 [2014-04-09 19:55:02.735929] Message Read: bytes to read=4 [2014-04-09 19:55:02.736003] Message read: message=20 02 00 00 [2014-04-09 19:55:02.736047] Message Read: bytes to read=4 [2014-04-09 19:55:02.736109] Connected to Broker [2014-04-09 19:55:02.736152] connect(): connected=1 [2014-04-09 19:55:02.736225] Message write: message_type=8 [2014-04-09 19:55:02.736272] Message SUBSCRIBE: msgid=35673 [2014-04-09 19:55:02.736327] Message Build: remaining length=16 [2014-04-09 19:55:02.736407] Message write: message=82 10 8b 59 00 01 23 00 00 07 2f 24 53 59 53 2f 23 00 [2014-04-09 19:55:02.736451] Message write: bytes written=18 [2014-04-09 19:55:02.736495] subscribe(): bytes written=18 [2014-04-09 19:55:02.736537] Message Read: message_type=9 [2014-04-09 19:55:02.736585] Message Read: bytes to read=4 [2014-04-09 19:55:02.736658] Message read: message=30 3e 00 38 [2014-04-09 19:55:02.736702] Message Read: bytes to read=4 [2014-04-09 19:55:02.736759] Message SUBACK: type mismatch PHP Fatal error: Uncaught exception 'SPMQTT_Exception' with message 'SUBSCRIBE/SUBACK message identifier mismatch: 35673:' in /wwwroot/borey/htdocs/mqtt/z_MQTT_class.php:356 Stack trace:

0 /wwwroot/borey/htdocs/mqtt/z_MQTT_class.php(393): spMQTT->subscribe(Array)

1 -(33): spMQTT->loop('default_subscri...')

2 {main}

thrown in /wwwroot/borey/htdocs/mqtt/z_MQTT_class.php on line 356

I have mosquitto broker under Debian 7.2 (Linux debian 3.2.0-4-686-pae #1 SMP Debian 3.2.51-1 i686 GNU/Linux):

apt-cache show mosquitto Package: mosquitto Version: 1.2.3-0mosquitto2 Architecture: i386 Maintainer: Roger A. Light roger@atchoo.org Installed-Size: 326 Depends: libc6 (>= 2.4), libssl1.0.0 (>= 1.0.1), libwrap0 (>= 7.6-4~), adduser (>= 3.10), lsb-base (>= 4.1+Debian3) Filename: pool/main/m/mosquitto/mosquitto_1.2.3-0mosquitto2_i386.deb Size: 118206

Package: mosquitto Version: 0.15-2 Installed-Size: 188 Maintainer: Roger A. Light roger@atchoo.org Architecture: i386 Depends: libc6 (>= 2.1), libwrap0 (>= 7.6-4~), adduser (>= 3.10), lsb-base (>= 3.2-13) Filename: pool/main/m/mosquitto/mosquitto_0.15-2_i386.deb Size: 68278

sskaje commented 10 years ago

@Amblego I made some changes, subscribe() and unsubscribe() won't send packets immediately but stored in an internal array, then proceeded in loop(), and $mqtt is passed into the callback, would these changes seems fine to you? If so, I'll commit.

Amblego commented 10 years ago

Dear, sskaje I guess, it would be enough. Please, commit. Thanks!

sskaje commented 10 years ago

Please try the latest commit. @Amblego

Amblego commented 10 years ago

Sskaje, thank you for quick actions!

Problem with uncaught exception was fixed, but it seems QoS 1/2 doesn't work.

For example: I start the subscribe script, after subscribe (with QoS=1 or 2) action I kill the script. After that I run publish script - it send some messages with QoS=1 or 2 and I kill it.

After that I run the same subscribe script (with QoS=1 or 2 and the same client_id) and there are no messages...

Where is my mistake?

Amblego commented 10 years ago

Sskaje, thank you for quick actions!

Problem with uncaught exception was fixed, but it seems QoS 1/2 doesn't work.

For example: I start the subscribe script, after subscribe (with QoS=1 or 2) action I kill the script. After that I run publish script - it send some messages with QoS=1 or 2 and I kill it.

After that I run the same subscribe script (with QoS=1 or 2 and the same client_id) and there are no messages...

Where is my mistake?

2014-04-15 12:39 GMT+04:00 sskaje notifications@github.com:

Please try the latest commit. @Amblego https://github.com/Amblego

— Reply to this email directly or view it on GitHubhttps://github.com/sskaje/mqtt/issues/1#issuecomment-40457952 .