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 connection issues #5

Closed
brocaar opened this issue Apr 2, 2016 · 2 comments
Closed

MQTT connection issues #5

brocaar opened this issue Apr 2, 2016 · 2 comments

Comments

@brocaar
Copy link
Owner

brocaar commented Apr 2, 2016

After running loraserver for a long time (I'm using the latest https://github.com/eclipse/paho.mqtt.golang version: 4ab3e86, but the problem is not exclusive to this version), it runs into mqtt connection issues. Most of the time, it is able to recover by (automatically) reconnecting and re-subscribing, but sometimes it looses the connection with the mqtt server (Mosquitto 1.4.3 in my case) and stops handling packets. Server is a Digitalocean Ubuntu 15.10 server. I see the same behaviour for the semtech bridge.

One part where the mqtt connection happens is: https://github.com/brocaar/loraserver/blob/master/application/mqttpubsub/backend.go

This problem might be related to eclipse/paho.mqtt.golang#32

Please share your findings!

loraserver logs:

Apr 01 18:10:08 iot loraserver[18659]: time="2016-04-01T18:10:08-04:00" level=info msg="application/mqttpubsub: publishing message" topic="application/0101010101010101/node/0202020202020202/rx"
Apr 01 18:10:08 iot loraserver[18659]: time="2016-04-01T18:10:08-04:00" level=info msg="node-session saved" dev_addr=07e4ac98
Apr 01 18:10:58 iot loraserver[18659]: time="2016-04-01T18:10:58-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 18:10:58 iot loraserver[18659]: time="2016-04-01T18:10:58-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 18:10:58 iot loraserver[18659]: time="2016-04-01T18:10:58-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 18:11:08 iot loraserver[18659]: time="2016-04-01T18:11:08-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 18:11:08 iot loraserver[18659]: time="2016-04-01T18:11:08-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 18:11:08 iot loraserver[18659]: time="2016-04-01T18:11:08-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 18:11:10 iot loraserver[18659]: time="2016-04-01T18:11:10-04:00" level=info msg="packet(s) collected" gw_count=1 gw_macs=1dee08d0b691d149 mtype=UnconfirmedDataUp
Apr 01 18:11:10 iot loraserver[18659]: time="2016-04-01T18:11:10-04:00" level=info msg="application/mqttpubsub: publishing message" topic="application/0101010101010101/node/0202020202020202/rx"
Apr 01 18:11:10 iot loraserver[18659]: time="2016-04-01T18:11:10-04:00" level=info msg="node-session saved" dev_addr=07e4ac98
Apr 01 18:12:12 iot loraserver[18659]: time="2016-04-01T18:12:12-04:00" level=info msg="packet(s) collected" gw_count=1 gw_macs=1dee08d0b691d149 mtype=UnconfirmedDataUp
Apr 01 18:12:12 iot loraserver[18659]: time="2016-04-01T18:12:12-04:00" level=info msg="application/mqttpubsub: publishing message" topic="application/0101010101010101/node/0202020202020202/rx"
Apr 01 18:12:12 iot loraserver[18659]: time="2016-04-01T18:12:12-04:00" level=info msg="node-session saved" dev_addr=07e4ac98
Apr 01 18:13:15 iot loraserver[18659]: time="2016-04-01T18:13:15-04:00" level=info msg="packet(s) collected" gw_count=1 gw_macs=1dee08d0b691d149 mtype=UnconfirmedDataUp
Apr 01 18:13:15 iot loraserver[18659]: time="2016-04-01T18:13:15-04:00" level=info msg="application/mqttpubsub: publishing message" topic="application/0101010101010101/node/0202020202020202/rx"
Apr 01 18:13:15 iot loraserver[18659]: time="2016-04-01T18:13:15-04:00" level=info msg="node-session saved" dev_addr=07e4ac98
Apr 01 18:14:17 iot loraserver[18659]: time="2016-04-01T18:14:17-04:00" level=info msg="packet(s) collected" gw_count=1 gw_macs=1dee08d0b691d149 mtype=UnconfirmedDataUp
Apr 01 18:14:17 iot loraserver[18659]: time="2016-04-01T18:14:17-04:00" level=info msg="application/mqttpubsub: publishing message" topic="application/0101010101010101/node/0202020202020202/rx"
Apr 01 18:14:17 iot loraserver[18659]: time="2016-04-01T18:14:17-04:00" level=info msg="node-session saved" dev_addr=07e4ac98
Apr 01 18:21:27 iot loraserver[18659]: time="2016-04-01T18:21:27-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 18:21:27 iot loraserver[18659]: time="2016-04-01T18:21:27-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 18:21:27 iot loraserver[18659]: time="2016-04-01T18:21:27-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 18:21:37 iot loraserver[18659]: time="2016-04-01T18:21:37-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 18:21:37 iot loraserver[18659]: time="2016-04-01T18:21:37-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 18:21:37 iot loraserver[18659]: time="2016-04-01T18:21:37-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 18:50:04 iot loraserver[18659]: time="2016-04-01T18:50:04-04:00" level=error msg="gateway/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 18:50:04 iot loraserver[18659]: time="2016-04-01T18:50:04-04:00" level=info msg="gateway/mqttpubsub: connected to mqtt server"
Apr 01 18:50:04 iot loraserver[18659]: time="2016-04-01T18:50:04-04:00" level=info msg="gateway/mqttpubsub: subscribing to rx topic" topic="gateway/+/rx"
Apr 01 18:50:14 iot loraserver[18659]: time="2016-04-01T18:50:14-04:00" level=error msg="gateway/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 18:50:14 iot loraserver[18659]: time="2016-04-01T18:50:14-04:00" level=info msg="gateway/mqttpubsub: connected to mqtt server"
Apr 01 18:50:14 iot loraserver[18659]: time="2016-04-01T18:50:14-04:00" level=info msg="gateway/mqttpubsub: subscribing to rx topic" topic="gateway/+/rx"
Apr 01 19:16:44 iot loraserver[18659]: time="2016-04-01T19:16:44-04:00" level=error msg="gateway/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 19:16:44 iot loraserver[18659]: time="2016-04-01T19:16:44-04:00" level=info msg="gateway/mqttpubsub: connected to mqtt server"
Apr 01 19:16:44 iot loraserver[18659]: time="2016-04-01T19:16:44-04:00" level=info msg="gateway/mqttpubsub: subscribing to rx topic" topic="gateway/+/rx"
Apr 01 19:16:54 iot loraserver[18659]: time="2016-04-01T19:16:54-04:00" level=error msg="gateway/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 19:16:54 iot loraserver[18659]: time="2016-04-01T19:16:54-04:00" level=info msg="gateway/mqttpubsub: connected to mqtt server"
Apr 01 19:16:54 iot loraserver[18659]: time="2016-04-01T19:16:54-04:00" level=info msg="gateway/mqttpubsub: subscribing to rx topic" topic="gateway/+/rx"
Apr 01 20:04:24 iot loraserver[18659]: time="2016-04-01T20:04:24-04:00" level=error msg="gateway/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 20:04:24 iot loraserver[18659]: time="2016-04-01T20:04:24-04:00" level=info msg="gateway/mqttpubsub: connected to mqtt server"
Apr 01 20:04:24 iot loraserver[18659]: time="2016-04-01T20:04:24-04:00" level=info msg="gateway/mqttpubsub: subscribing to rx topic" topic="gateway/+/rx"
Apr 01 20:04:34 iot loraserver[18659]: time="2016-04-01T20:04:34-04:00" level=error msg="gateway/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 20:04:34 iot loraserver[18659]: time="2016-04-01T20:04:34-04:00" level=info msg="gateway/mqttpubsub: connected to mqtt server"
Apr 01 20:04:34 iot loraserver[18659]: time="2016-04-01T20:04:34-04:00" level=info msg="gateway/mqttpubsub: subscribing to rx topic" topic="gateway/+/rx"
Apr 01 20:34:48 iot loraserver[18659]: time="2016-04-01T20:34:48-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 20:34:48 iot loraserver[18659]: time="2016-04-01T20:34:48-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 20:34:48 iot loraserver[18659]: time="2016-04-01T20:34:48-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 20:34:58 iot loraserver[18659]: time="2016-04-01T20:34:58-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 20:34:58 iot loraserver[18659]: time="2016-04-01T20:34:58-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 20:34:58 iot loraserver[18659]: time="2016-04-01T20:34:58-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 20:59:08 iot loraserver[18659]: time="2016-04-01T20:59:08-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 20:59:08 iot loraserver[18659]: time="2016-04-01T20:59:08-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 20:59:08 iot loraserver[18659]: time="2016-04-01T20:59:08-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 20:59:18 iot loraserver[18659]: time="2016-04-01T20:59:18-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
Apr 01 20:59:18 iot loraserver[18659]: time="2016-04-01T20:59:18-04:00" level=info msg="application/mqttpubsub: connected to mqtt server"
Apr 01 20:59:18 iot loraserver[18659]: time="2016-04-01T20:59:18-04:00" level=info msg="application/mqttpubsub: subscribing to tx topic" topic="application/+/node/+/tx"
Apr 01 21:13:18 iot loraserver[18659]: time="2016-04-01T21:13:18-04:00" level=error msg="application/mqttpubsub: mqtt connection error: pingresp not received, disconnecting"
...

Mosquitto logs:

1459546993: Socket error on client 885a5fc6-12cb-4249-a7c4-9cb4aaf99d10, disconnecting.
1459546993: New client connected from 127.0.0.1 as c371d40c-876d-4cf1-a900-24539741f56b (c1, k30).
1459547003: Socket error on client c371d40c-876d-4cf1-a900-24539741f56b, disconnecting.
1459547003: New connection from 127.0.0.1 on port 1883.
1459547003: New client connected from 127.0.0.1 as 43e07938-154a-4571-9e14-bb4443cf5138 (c1, k30).
1459547103: New connection from 127.0.0.1 on port 1883.
1459547103: Socket error on client 43e07938-154a-4571-9e14-bb4443cf5138, disconnecting.
1459547103: New client connected from 127.0.0.1 as 518e58fe-f2e5-49ce-b621-cae192e184cc (c1, k30).
1459547113: Socket error on client 518e58fe-f2e5-49ce-b621-cae192e184cc, disconnecting.
1459547113: New connection from 127.0.0.1 on port 1883.
1459547113: New client connected from 127.0.0.1 as 2e11c696-b3c2-436e-82d0-4e20952f5acf (c1, k30).
1459547963: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1459548105: Socket error on client 534e8be8-8dbb-4c05-b29d-ae8d13b9a979, disconnecting.
1459548105: New connection from 127.0.0.1 on port 1883.
1459548105: New client connected from 127.0.0.1 as 8664a25e-22e5-4417-89ef-b862e33e2c90 (c1, k30).
1459548115: Socket error on client 8664a25e-22e5-4417-89ef-b862e33e2c90, disconnecting.
1459548115: New connection from 127.0.0.1 on port 1883.
1459548115: New client connected from 127.0.0.1 as 398a4f2e-4b18-4148-a322-176249184796 (c1, k30).
1459548479: New connection from 127.0.0.1 on port 1883.
1459548479: Socket error on client 12220090-cb15-4ba5-9636-b98dc04a1796, disconnecting.
1459548479: New client connected from 127.0.0.1 as 16c9079e-6ef7-4097-81d3-66f517c48ff6 (c1, k30).
1459548489: Socket error on client 16c9079e-6ef7-4097-81d3-66f517c48ff6, disconnecting.
1459548489: New connection from 127.0.0.1 on port 1883.
1459548489: New client connected from 127.0.0.1 as fcc78d39-2fd3-4a17-980a-73d8b290989f (c1, k30).
1459548658: Socket error on client 398a4f2e-4b18-4148-a322-176249184796, disconnecting.
1459548658: New connection from 127.0.0.1 on port 1883.
1459548658: New client connected from 127.0.0.1 as 1a30a813-adaa-4fb6-8581-3be188c482f5 (c1, k30).
1459548668: Socket error on client 1a30a813-adaa-4fb6-8581-3be188c482f5, disconnecting.
1459548668: New connection from 127.0.0.1 on port 1883.
1459548668: New client connected from 127.0.0.1 as 73f2fd18-c10d-4b09-a9e1-c99d293f8e34 (c1, k30).
1459549287: Socket error on client 73f2fd18-c10d-4b09-a9e1-c99d293f8e34, disconnecting.
1459549287: New connection from 127.0.0.1 on port 1883.
1459549287: New client connected from 127.0.0.1 as f7a011f3-a9a0-4e64-98ad-1850233ddbaf (c1, k30).
1459549297: Socket error on client f7a011f3-a9a0-4e64-98ad-1850233ddbaf, disconnecting.
1459549297: New connection from 127.0.0.1 on port 1883.
1459549297: New client connected from 127.0.0.1 as 314ef86a-9fdb-4ce1-92a6-6d2844a38567 (c1, k30).
...
This was referenced Apr 2, 2016
Closed
Merged
brocaar added a commit that referenced this issue Apr 4, 2016
@brocaar
Update github.com/eclipse/paho.mqtt.golang vendor.
152efb0 
This should fix various connection related issues (see also #5).
@brocaar
Copy link
Owner Author

brocaar commented Apr 4, 2016

This issue is hopefully fixed in the updated mqtt package.

@brocaar
Copy link
Owner Author

brocaar commented Apr 18, 2016

There are still connection problems in the paho package, but both the latest lora-semtech-bridge and loraserver are able to recover from connection issues. I'll close this issue for now and will keep an eye on the paho mqtt client updates.

@brocaar brocaar closed this as completed Apr 18, 2016
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
1 participant
@brocaar