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

MQTT client is disconnected and cannot reconnect after sending message #623

Closed
gavinheale opened this issue Dec 6, 2023 · 5 comments · Fixed by #627
Closed

MQTT client is disconnected and cannot reconnect after sending message #623

gavinheale opened this issue Dec 6, 2023 · 5 comments · Fixed by #627

Comments

@gavinheale
Copy link

I am testing the mqtt functionality using MQTTX (https://mqttx.app/) and the setup described in the intro (https://docs.aklivity.io/zilla/next/tutorials/mqtt/mqtt-intro.html).

I am connecting to the zilla broker using the address mqtt://localhost:7183

I can connect successfully and receive messages but when I send a message, I am automatically disconnected and the reconnects do not work.

I dont see anything in the zilla logs using the docker logs command.

I get the following log from MQTTX

[2023-12-06 17:28:16] [INFO] Message Arrived with topic: zilla
[2023-12-06 17:28:16] [INFO] Zilla message arrived: message added "message_a1f68ecf-3a0b-4fab-9856-264f001b3ded" and added to topic: "zilla", payload: "Hello World MQTTX 3" MQTT.js onMessageArrived trigger with Properties: undefined
[2023-12-06 17:28:16] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:20] [INFO] Zilla reconnect: 0 times retry
[2023-12-06 17:28:20] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:24] [INFO] Zilla reconnect: 1 times retry
[2023-12-06 17:28:25] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:29] [INFO] Zilla reconnect: 2 times retry
[2023-12-06 17:28:29] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:33] [INFO] Zilla reconnect: 3 times retry
[2023-12-06 17:28:33] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:37] [INFO] Zilla reconnect: 4 times retry
[2023-12-06 17:28:37] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:41] [INFO] Zilla reconnect: 5 times retry
[2023-12-06 17:28:41] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:45] [INFO] Zilla reconnect: 6 times retry
[2023-12-06 17:28:45] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:49] [INFO] Zilla reconnect: 7 times retry
[2023-12-06 17:28:50] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:54] [INFO] Zilla reconnect: 8 times retry
[2023-12-06 17:28:54] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:28:58] [INFO] Zilla reconnect: 9 times retry
[2023-12-06 17:28:58] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:29:02] [INFO] Zilla reconnect: 10 times retry
[2023-12-06 17:29:02] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-06 17:29:06] [WARN] Connection maxReconnectTimes limit, stop retry
[2023-12-06 17:29:06] [ERROR] Zilla connect fail, MQTT.js onError trigger, Error: client disconnecting
at MqttClient._checkDisconnecting (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:577:26)
at MqttClient.subscribe (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:723:12)
at MqttClient._resubscribe (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:1747:16)
at deliver (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:340:14)
at MqttClient. (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:369:5)
at MqttClient.emit (events.js:327:22)
at MqttClient._onConnect (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:1768:10)
at MqttClient._handleConnack (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:1386:10)
at MqttClient._handlePacket (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:549:12)
at work (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:438:12)
at Writable.writable._write (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:452:5)
at doWrite (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/node_modules/readable-stream/lib/_stream_writable.js:409:139)
at writeOrBuffer (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/node_modules/readable-stream/lib/_stream_writable.js:398:5)
at Writable.write (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/node_modules/readable-stream/lib/_stream_writable.js:307:11)
at Socket.ondata (internal/streams/readable.js:719:22)
at Socket.emit (events.js:315:20)
@bmaidics
Copy link
Contributor

bmaidics commented Dec 7, 2023 •
edited
Loading

Hi @gavinheale ,
Thanks for filing the issue.
If I understood correctly you

  1. opened a connection using MQTTX and subscribed to a topic filter.
  2. opened another connection, where you produced into this topic -> successfully received on connection 1
  3. produce message using client1, and you get disconnected.

I've tried it using these steps with the mqtt intro, and it was all working, so maybe I misunderstood your use case. Can you elaborate a little bit more?

  • What mqtt version are you using? (I used v5)
  • What is the max qos you're subscribing?
  • What's the qos you're producing?
  • Is it an intermittent issue or you're reproducing it constantly?

I can see in the payload "Hello World MQTTX 3". Based on this, maybe you're using V3 protocol? Note that we're only supporting v3.1.1 and v5 right now.

@gavinheale
Copy link
Author

Hi @bmaidics,

I just reproduced this using the following steps

  1. start a clean server using "docker compose up -d"
  2. subscribe to messages using mosquitto
  3. subscribe to messages using MQTTX
  4. send a test message from mosquitto - both clients receive it
  5. send a test message from MQTTX - both clients receive it but MQTTX is disconnected and cannot reconnect

To answer your questions

  • I am using mqtt version 5 (see screen shots and logs)
  • qos 2 I believe
  • qos 2
  • can be reproduced constantly

Here is the output from subscribing using mosquitto

(base) MacBook-Pro:logs gavin$ docker run -it --rm eclipse-mosquitto mosquitto_sub -V 'mqttv5' --topic 'zilla' --host 'host.docker.internal' --port 7183 --debug
Client null sending CONNECT
Client 5afed7bb-6886-4dad-900a-770918662e23 received CONNACK (0)
Client 5afed7bb-6886-4dad-900a-770918662e23 sending SUBSCRIBE (Mid: 1, Topic: zilla, QoS: 0, Options: 0x00)
Client 5afed7bb-6886-4dad-900a-770918662e23 received SUBACK
Subscribed (mid: 1): 0
Client 5afed7bb-6886-4dad-900a-770918662e23 sending PINGREQ
Client 5afed7bb-6886-4dad-900a-770918662e23 received PINGRESP
Client 5afed7bb-6886-4dad-900a-770918662e23 received PUBLISH (d0, q0, r0, m0, 'zilla', ... (21 bytes))
Test 1 from mosquitto
Client 5afed7bb-6886-4dad-900a-770918662e23 sending PINGREQ
Client 5afed7bb-6886-4dad-900a-770918662e23 received PINGRESP
Client 5afed7bb-6886-4dad-900a-770918662e23 received PUBLISH (d0, q0, r0, m0, 'zilla', ... (18 bytes))
Test 1 from MQTTX
Client 5afed7bb-6886-4dad-900a-770918662e23 sending PINGREQ
Client 5afed7bb-6886-4dad-900a-770918662e23 received PINGRESP
^CClient 5afed7bb-6886-4dad-900a-770918662e23 sending DISCONNECT
(base) MacBook-Pro:logs gavin$

Here is the log from MQTTX

bash-3.2$ tail -f log
[2023-12-07 11:15:31] [INFO] APP init
[2023-12-07 11:16:01] [INFO] MQTTX client with ID 087054be-06b2-467b-bc91-3c5f5e52dea6 assigned
[2023-12-07 11:16:01] [INFO] Connect client Zilla, MQTT/TCP connection: mqtt://localhost:7183 with Properties: {"sessionExpiryInterval":0,"receiveMaximum":null,"maximumPacketSize":null,"topicAliasMaximum":null,"requestResponseInformation":null,"requestProblemInformation":null,"authenticationMethod":null}
[2023-12-07 11:16:04] [INFO] Zilla connect success, MQTT.js onConnect trigger
[2023-12-07 11:16:04] [INFO] Topic: zilla is resubscribing
[2023-12-07 11:16:04] [INFO] Saved topic: zilla
[2023-12-07 11:16:04] [INFO] Topic: zilla successfully subscribed, Subscription Identifier: null, No Local flag: false, Retain as Published flag: false, Retain Handling: 0
[2023-12-07 11:16:59] [INFO] Message Arrived with topic: zilla
[2023-12-07 11:16:59] [INFO] Zilla message arrived: message added "message_efbf3db7-de15-4930-a2fd-d662bfcaebcd" and added to topic: "zilla", payload: "Test 1 from mosquitto" MQTT.js onMessageArrived trigger with Properties: undefined
[2023-12-07 11:17:56] [INFO] Message Arrived with topic: zilla
[2023-12-07 11:17:56] [INFO] Zilla message arrived: message added "message_7ed7cd4d-e7ad-40ec-a09a-4a91d16d93c4" and added to topic: "zilla", payload: "Test 1 from MQTTX " MQTT.js onMessageArrived trigger with Properties: undefined
[2023-12-07 11:17:56] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:00] [INFO] Zilla reconnect: 0 times retry
[2023-12-07 11:18:00] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:04] [INFO] Zilla reconnect: 1 times retry
[2023-12-07 11:18:04] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:08] [INFO] Zilla reconnect: 2 times retry
[2023-12-07 11:18:08] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:12] [INFO] Zilla reconnect: 3 times retry
[2023-12-07 11:18:13] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:17] [INFO] Zilla reconnect: 4 times retry
[2023-12-07 11:18:17] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:21] [INFO] Zilla reconnect: 5 times retry
[2023-12-07 11:18:21] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:25] [INFO] Zilla reconnect: 6 times retry
[2023-12-07 11:18:25] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:29] [INFO] Zilla reconnect: 7 times retry
[2023-12-07 11:18:29] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:33] [INFO] Zilla reconnect: 8 times retry
[2023-12-07 11:18:33] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:37] [INFO] Zilla reconnect: 9 times retry
[2023-12-07 11:18:37] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:41] [INFO] Zilla reconnect: 10 times retry
[2023-12-07 11:18:41] [INFO] Zilla connect close, MQTT.js onClose trigger
[2023-12-07 11:18:45] [WARN] Connection maxReconnectTimes limit, stop retry
[2023-12-07 11:18:45] [ERROR] Zilla connect fail, MQTT.js onError trigger, Error: client disconnecting
at MqttClient._checkDisconnecting (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:577:26)
at MqttClient.subscribe (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:723:12)
at MqttClient._resubscribe (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:1747:16)
at deliver (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:340:14)
at MqttClient. (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:369:5)
at MqttClient.emit (events.js:327:22)
at MqttClient._onConnect (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:1768:10)
at MqttClient._handleConnack (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:1386:10)
at MqttClient._handlePacket (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:549:12)
at work (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:438:12)
at Writable.writable._write (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/lib/client.js:452:5)
at doWrite (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/node_modules/readable-stream/lib/_stream_writable.js:409:139)
at writeOrBuffer (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/node_modules/readable-stream/lib/_stream_writable.js:398:5)
at Writable.write (/Applications/MQTTX.app/Contents/Resources/app.asar/node_modules/mqtt/node_modules/readable-stream/lib/_stream_writable.js:307:11)
at Socket.ondata (internal/streams/readable.js:719:22)
at Socket.emit (events.js:315:20)
[2023-12-07 11:18:45] [INFO] Zilla connect success, MQTT.js onConnect trigger
[2023-12-07 11:18:46] [INFO] Topic: zilla is resubscribing
[2023-12-07 11:18:46] [ERROR] Topic: subscribe error, Error: client disconnecting
^C
Screenshot 2023-12-07 at 11 19 14 AM
Screenshot 2023-12-07 at 11 19 22 AM

@bmaidics
Copy link
Contributor

bmaidics commented Dec 7, 2023

Thanks @gavinheale , now I could reproduce the issue. We're working on it and update you here once it's fixed

@jfallows jfallows mentioned this issue Dec 8, 2023
Merged
@jfallows jfallows closed this as completed Dec 8, 2023
@jfallows
Copy link
Contributor

@gavinheale fyi - fix released in 0.9.61

@gavinheale
Copy link
Author

Thanks for the quick response. I pulled the release and all looks good now.

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

Successfully merging a pull request may close this issue.

Fix encoding error when no properties defined by the client bmaidics/zilla
3 participants
@jfallows @gavinheale @bmaidics