MQTT Input Process Issues (suspected)

Continuing the discussion from Ghost pulse meter reading:

I’m still investigating this but thought I’d post what I’m seeing and what I have found so far. It looks like my main MQTT Broker is playing up. The emoncms MQTT Input process is playing up.

I noticed a while back (mid Jan) my Pulse interface was jumping. I then had a complete failure so there was a gap in the data collection. The Pulse interface is an RPi with just emonhub installed.

What you see as a graph is this;

which is odd as the pulse count does not increase. The reason for that is simple, I use feedwriter and, as discussed elsewhere, it will not overwrite old data.

Looking at the logs for one jump, you can see the incoming data is the issue. At 04:27:52.706 both the value and the timestamp are wrong. [edit] This is a ghost receipt by the MQTT process - it was never sent by emonhub nor published by the Broker.

2021-02-12 04:27:27.665|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341859, "Pulse Inc": 1, "time": 1613104047.2622879}
2021-02-12 04:27:34.375|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341860, "Pulse Inc": 1, "time": 1613104054.0438154}
2021-02-12 04:27:41.075|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341861, "Pulse Inc": 1, "time": 1613104060.8232083}
2021-02-12 04:27:48.052|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341862, "Pulse Inc": 1, "time": 1613104067.6183624}
2021-02-12 04:27:52.706|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 298559, "Pulse Inc": 2, "time": 1613010009.1705785}
2021-02-12 04:27:54.647|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341863, "Pulse Inc": 1, "time": 1613104074.3221786}
2021-02-12 04:28:01.539|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341864, "Pulse Inc": 1, "time": 1613104081.213712}
2021-02-12 04:28:21.872|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341867, "Pulse Inc": 1, "time": 1613104101.5359166}

In checking the emonhub log on the Pulse Pi, I remembered I actually send the data to multiple MQTT Brokers. Looking at one of those;

2021-02-12 04:27:27.662|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341859, "Pulse Inc": 1, "time": 1613104047.2622879}
2021-02-12 04:27:34.469|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341860, "Pulse Inc": 1, "time": 1613104054.0438154}
2021-02-12 04:27:41.081|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341861, "Pulse Inc": 1, "time": 1613104060.8232083}
2021-02-12 04:27:48.058|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341862, "Pulse Inc": 1, "time": 1613104067.6183624}
2021-02-12 04:27:54.632|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341863, "Pulse Inc": 1, "time": 1613104074.3221786}
2021-02-12 04:28:01.580|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341864, "Pulse Inc": 1, "time": 1613104081.213712}
2021-02-12 04:28:08.254|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341865, "Pulse Inc": 1, "time": 1613104087.9125524}
2021-02-12 04:28:14.953|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341866, "Pulse Inc": 1, "time": 1613104094.7083879}
2021-02-12 04:28:21.868|INFO|emoncms_mqtt.php|emon/3 {"Pulse": 341867, "Pulse Inc": 1, "time": 1613104101.5359166}

I am clearly missing data on the other Broker. That is an issue as it is the main Broker on my ProxmoxVE setup. :angry:

[edit]
The Mosquitto logs on the Broker show the receipt and sending seems to be OK

1613104047: Sending PUBLISH to emoncmsprox (d0, q2, r0, m73, 'emon/3', ... (61 bytes))
1613104054: Received PUBLISH from 01144d27-ea2d-493e-9174-45fd63e6ed47 (d0, q2, r0, m26562, 'emon/3', ... (61 bytes))
1613104054: Sending PUBLISH to emoncmsprox (d0, q2, r0, m75, 'emon/3', ... (61 bytes))
1613104060: Received PUBLISH from 01144d27-ea2d-493e-9174-45fd63e6ed47 (d0, q2, r0, m26563, 'emon/3', ... (61 bytes))
1613104061: Sending PUBLISH to emoncmsprox (d0, q2, r0, m76, 'emon/3', ... (61 bytes))
1613104067: Received PUBLISH from 01144d27-ea2d-493e-9174-45fd63e6ed47 (d0, q2, r0, m26564, 'emon/3', ... (61 bytes))
1613104068: Sending PUBLISH to emoncmsprox (d0, q2, r0, m78, 'emon/3', ... (61 bytes))
1613104074: Received PUBLISH from 01144d27-ea2d-493e-9174-45fd63e6ed47 (d0, q2, r0, m26565, 'emon/3', ... (61 bytes))
1613104074: Sending PUBLISH to emoncmsprox (d0, q2, r0, m82, 'emon/3', ... (61 bytes))
1613104081: Received PUBLISH from 01144d27-ea2d-493e-9174-45fd63e6ed47 (d0, q2, r0, m26566, 'emon/3', ... (60 bytes))
1613104081: Sending PUBLISH to emoncmsprox (d0, q2, r0, m93, 'emon/3', ... (60 bytes))
1613104088: Received PUBLISH from 01144d27-ea2d-493e-9174-45fd63e6ed47 (d0, q2, r0, m26567, 'emon/3', ... (61 bytes))
1613104088: Sending PUBLISH to emoncmsprox (d0, q2, r0, m95, 'emon/3', ... (61 bytes))
1613104094: Received PUBLISH from 01144d27-ea2d-493e-9174-45fd63e6ed47 (d0, q2, r0, m26568, 'emon/3', ... (61 bytes))

This leads me to think it is the receiving emoncms_mqtt process that is at fault. I have previously noted that I can swamp it if the data is sent too quickly. I do send a fair bit via MQTT so I wonder if it is getting swamped.

I wonder if this should be moved from a PHP process to a Python script.

[edit2]
Found the sending log

2021-02-12 04:27:27,526 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341859, "Pulse Inc": 1, "time": 1613104047.2622879}
2021-02-12 04:27:34,244 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341860, "Pulse Inc": 1, "time": 1613104054.0438154}
2021-02-12 04:27:40,949 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341861, "Pulse Inc": 1, "time": 1613104060.8232083}
2021-02-12 04:27:47,920 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341862, "Pulse Inc": 1, "time": 1613104067.6183624}
2021-02-12 04:27:54,523 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341863, "Pulse Inc": 1, "time": 1613104074.3221786}
2021-02-12 04:28:01,419 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341864, "Pulse Inc": 1, "time": 1613104081.213712}
2021-02-12 04:28:08,117 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341865, "Pulse Inc": 1, "time": 1613104087.9125524}
2021-02-12 04:28:14,808 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341866, "Pulse Inc": 1, "time": 1613104094.7083879}
2021-02-12 04:28:21,736 DEBUG    MQTT       Publishing: emon/3 {"Pulse": 341867, "Pulse Inc": 1, "time": 1613104101.5359166}

Sent from emonhub → MQTT Broker → Emoncms MQTT process

But there was a ghost received value at 2021-02-12 04:27:52.706.