Testing MQTT

[ckrey]

Note:

• default mqttProtocolVersion is 3, should be 4 nowadays
• seems to ignore keepAlive values < 900

Environment:

• Broker: mosquitto 1.6.8, TLS, authentication user/password
• Phone: HUAWEI Y6 2018
• Android-Verison 8.0.0

[binarybucks]

1. argreed
2. keepalive intervall is limited by the min scheduler intervall of 15m. Also you probably want higher intervals anyway to save on battery

[ckrey]

2. In iOS there is NO way to keep the MQTT running except in Move Mode. So, the connection is disconnected when the app goes into background and reestablished when foregrounded or when a new location is available.

[ckrey]

3. Phone ck00y6 locked, service is NOT active:

mosquitto assumes phone is connected and sends PUBLISH packets Qos2. ck00y6 does not respond (because service is not active?) ck00y6 wakes up after 900 secs and sends 3? PINGREQ Another 90 seconds later? ck00y6 responds to the PUBLISH packets

...
1586078334: Received PUBACK from ck00y6 (Mid: 335, RC:0)
...

1586079100: Sending PUBLISH to ck00y6 (d0, q2, r0, m336, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079118: Sending PUBLISH to ck00y6 (d0, q2, r0, m337, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079130: Sending PUBLISH to ck00y6 (d0, q2, r0, m338, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079132: Sending PUBLISH to ck00y6 (d0, q2, r0, m339, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079133: Sending PUBLISH to ck00y6 (d0, q2, r0, m340, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079135: Sending PUBLISH to ck00y6 (d0, q2, r0, m341, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079153: Sending PUBLISH to ck00y6 (d0, q2, r0, m342, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079155: Sending PUBLISH to ck00y6 (d0, q2, r0, m343, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079157: Sending PUBLISH to ck00y6 (d0, q2, r0, m344, 'owntracks/ck00/iPhoneSE', ... (216 bytes))
1586079160: Sending PUBLISH to ck00y6 (d0, q2, r0, m345, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079162: Sending PUBLISH to ck00y6 (d0, q2, r0, m346, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079164: Sending PUBLISH to ck00y6 (d0, q2, r0, m347, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079165: Sending PUBLISH to ck00y6 (d0, q2, r0, m348, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079167: Sending PUBLISH to ck00y6 (d0, q2, r0, m349, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079169: Sending PUBLISH to ck00y6 (d0, q2, r0, m350, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079171: Sending PUBLISH to ck00y6 (d0, q2, r0, m351, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079172: Sending PUBLISH to ck00y6 (d0, q2, r0, m352, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079174: Sending PUBLISH to ck00y6 (d0, q2, r0, m353, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079176: Sending PUBLISH to ck00y6 (d0, q2, r0, m354, 'owntracks/ck00/iPhoneSE', ... (217 bytes))
1586079203: Sending PUBLISH to ck00y6 (d0, q2, r0, m355, 'owntracks/ck00/iPhoneSE', ... (210 bytes))
1586079234: Received PINGREQ from ck00y6
1586079234: Sending PINGRESP to ck00y6
1586079234: Received PINGREQ from ck00y6
1586079234: Sending PINGRESP to ck00y6
1586079234: Received PINGREQ from ck00y6
1586079234: Sending PINGRESP to ck00y6

1586079340: Received PUBREC from ck00y6 (Mid: 336)
1586079340: Sending PUBREL to ck00y6 (m336)
1586079340: Received PUBREC from ck00y6 (Mid: 337)
1586079340: Sending PUBREL to ck00y6 (m337)
1586079340: Received PUBREC from ck00y6 (Mid: 338)

[ckrey]

Restarting Tests using version 21302:

• [x] still uses protocol MQTT v3.1, not MQTT v3.1.1

[ckrey]

• [ ] now each PUBLISH causes the MQTT connection to be re-initiated

...
1588090410: Received PUBCOMP from ck00y6 (Mid: 15, RC:0)
1588090434: Client ck00y6 already connected, closing old connection.
1588090434: New client connected from 79.195.76.56 as ck00y6 (p1, c0, k901, u'ck00').
1588090434: 	owntracks/ck00/Y6
1588090434: Sending CONNACK to ck00y6 (0, 0)
1588090434: Received SUBSCRIBE from ck00y6
1588090434: ck00y6 2 owntracks/+/+
1588090434: ck00y6 2 owntracks/+/+/info
1588090434: 	owntracks/ck00/Y6/cmd (QoS 2)
1588090434: ck00y6 2 owntracks/ck00/Y6/cmd
1588090434: ck00y6 2 owntracks/+/+/event
1588090434: ck00y6 2 owntracks/+/+/waypoints
1588090434: Sending SUBACK to ck00y6
1588090434: Sending PUBLISH to ck00y6 (d0, q2, r1, m1, 'owntracks/ck00/iPhoneSE', ... (223 bytes))
...

[ckrey]

• [ ] MQTT connection remains open while phone is locked (good)!
• [ ] PINGREQ works (after 15 min / 900 sec)

[growse]

* [ ]  still uses protocol MQTT v3.1, not MQTT v3.1.1

Just pushed a new version that changes this default. It won't change it for users with an existing config though.

* [ ]  now each `PUBLISH` causes the MQTT connection to be re-initiated

I'm not sure I fully understand, are you seeing an MQTT reconnection on every location notification, or is this from a command coming down to the device from MQTT?

* [ ]  MQTT connection remains open while phone is locked (good)!
* [ ]  `PINGREQ` works (after 15 min / 900 sec)

Just to clarify - a ping command produces a response from the device, but only after 15 mins?

[ckrey]

• [ ] now each PUBLISH causes the MQTT connection to be re-initiated

yes, I see a reconnection on every location notification. I did check the code. It seems to check if it is already connected, but it establishes a new connection...

• [x] PINGREQ works (after 15 min / 900 sec) just and observation. We already discussed the need for a long (15min) keepAlive value because the minimum service re-activation time is 15min

[ckrey]

Now testing version 22013:

• [x] now each PUBLISH causes the MQTT connection to be re-initiated

does not happen anymore

[growse]

Now testing version 22013:

• [x] now each PUBLISH causes the MQTT connection to be re-initiated

does not happen anymore

How weird. Worth keeping an eye on - I don't think anything changed in the MQTT code between 22011 and 22013.

[ckrey]

PINGREQs are not sent anymore after keepAlive seconds (900) in version 22123. Therefore broker detects timeout after 1350 seconds (900 * 1.5)

1604924390: Sending PUBLISH to cky6 (d0, q1, r0, m56439, 'owntracks/ck/Y6', ... (195 bytes))
1604924390: Received PUBACK from cky6 (Mid: 56439, RC:0)
1604925740: Client cky6 has exceeded timeout, disconnecting.

[growse]

Booo. Let me reproduce.