Local emonpi out of sync with MQTT?

borpin · 4 October 2022 20:48

I have previously noticed that you can flood the MQTT receiver on an EmonPi if you send too many messages - it isn’t very efficient. I’m sure I have posted on this before.

Send the data as a single JSON rather than individual values (I created this method for precisely this reason). If you use a timestamp, that makes it even more precise (if your EmonPi clock syncs correctly) and all the values have the same timestamp (otherwise by the time it has processed all the individual values from one device, the timeseries window might have moved on).

The data should appear in the same place in the Inputs.

    [[[runtimesettings]]]
        subchannels = ToEmonCMS,

        timestamped = True
        node_JSON_enable = 1
        node_JSON_basetopic = emon/

If I send data from Node-RED, I throttle the message rate to avoid this as well.

The HTTP interfacer is more efficient as it buffers the messages (by default).

a23452533 · 4 October 2022 21:07

Thanks Brian. Trying that setting now, and will report back!

I don’t have any particular reason to use the MQTT interfacer for the emontxes. I do have water counters and Openevse coming in via MQTT, so thought I might as well move everything to MQTT.

Should I go back to using the original httpinterfacer or stick with MQTT?

borpin · 5 October 2022 07:16

I use MQTT because I pick up the published data from more than one place (HA and Emoncms for instance). It really is your choice

a23452533 · 5 October 2022 07:39

Oh that’s interesting. I use the Emoncms integration in HA to bring in the feed values for_use and _kwh which drive the energy dashboard and other automation.

How are you using the mqtt data?

a23452533 · 30 October 2022 22:45

I am still having a lag problem with emontx. Although the msg count isn’t jumping around, the inputs are showing an 11 minute delay.

Interestingly I also have OpenEVSE inputs coming in which are not showing a delay.

Any suggestions on what to do next please?

borpin · 31 October 2022 06:49

Is the time on the Pi correct?

Is this still the same base image? If so there were issues with the NTP sync at one point so that might be the problem.

See Ensuring emonPi / emonBase time is synchronised with an NTP server

a23452533 · 31 October 2022 07:57

Thanks for the reply.
Time looks ok on the pi.

Here’s a couple of admin page screenshots.

borpin · 31 October 2022 15:47

AIUI, the time on the Inputs page is calculated as the difference between now() on that computer and the date stamp on the data.

Either the EmonPi’s time or the Computer’s time is wrong.

Your smartphone has the most accurate time. If you open a GPS app, that will be even better.

a23452533 · 31 October 2022 21:50

I just rechecked. The emonpi and computer time are correct.

the emontx inputs are showing 11 minutes behind. I also have openevse feeds which are coming through correctly, and green and only a few seconds behind.

borpin · 1 November 2022 07:21

Just to check, you have 2 emonTXs communicating to an EmonBase (i.e a Pi with the RFM Board)?

data is received by emonhub, then passed to emoncms via MQTT.

Are you using the timestamp JSON Format?

Can you post the relevant section of the emonhub log (on DEBUG), please? Is the timestamp correct?
From receipt of data from the first TX to the sending of the second TX data, please?

TrystanLea · 1 November 2022 11:57

That looks like what you might see if you had two emonTx units posting on the same nodeid… any chance that there is another emontx? or is there any chance one set of readings is coming via WiFi and another via the rfm radio? not sure how that would cause the 11 minute delay though…

The only time Im aware of seeing local time delays is when the time is incorrect after a power cut. I then run:

sudo service systemd-timesyncd restart

to correct it.

a23452533 · 10 November 2022 21:44

Hi, Here’s an emonhub log excerpt showing data going to mqtt with no delay. THis is not the internal emoncms MQTT, it is a separate Mosquito instance running as a docker.

2022-11-10 21:37:40,190 DEBUG    RFM2Pi     171677 NEW FRAME : OK 11 178 100 4 0 36 91 251 255 68 29 251 255 22 0 227 105 0 0 230 190 5 0 221 102 0 0 103 34 0 0 0 0 0 0 0 0 0 0 0 0
2022-11-10 21:37:40,194 DEBUG    RFM2Pi     171677 Timestamp : 1668116260.190044
2022-11-10 21:37:40,195 DEBUG    RFM2Pi     171677 From Node : 11
2022-11-10 21:37:40,196 DEBUG    RFM2Pi     171677    Values : [287922, 233.32, -5, 7492, -5, 22, 27107, 376550, 26333, 8807, 0, 0, 0, 0]
2022-11-10 21:37:40,197 DEBUG    RFM2Pi     171677 Sent to channel(start)' : ToEmonCMS
2022-11-10 21:37:40,197 DEBUG    RFM2Pi     171677 Sent to channel(end)' : ToEmonCMS
2022-11-10 21:37:40,309 DEBUG    MQTT       Publishing: emon/emontx1 {"MSG": 287922, "Vrms": 233.32, "P1": -5, "P2": 7492, "P3": -5, "P4": 22, "E1": 27107, "E2": 376550, "E3": 26333, "E4": 8807, "T1": 0, "T2": 0, "T3": 0, "pulse": 0, "time": 1668116260.1900437}
2022-11-10 21:37:45,239 DEBUG    RFM2Pi     171678 NEW FRAME : OK 12 178 100 4 0 120 90 211 47 4 0 146 10 2 0 160 174 12 0 184 166 3 0 131 227 2 0 73 115 2 0 0 0 0 0 0 0 0 0 0 0
2022-11-10 21:37:45,242 DEBUG    RFM2Pi     171678 Timestamp : 1668116265.239381
2022-11-10 21:37:45,243 DEBUG    RFM2Pi     171678 From Node : 12
2022-11-10 21:37:45,244 DEBUG    RFM2Pi     171678    Values : [287922, 231.6, 12243, 4, 2706, 2, 831136, 239288, 189315, 160585, 0, 0, 0, 0]
2022-11-10 21:37:45,244 DEBUG    RFM2Pi     171678 Sent to channel(start)' : ToEmonCMS
2022-11-10 21:37:45,245 DEBUG    RFM2Pi     171678 Sent to channel(end)' : ToEmonCMS
2022-11-10 21:37:45,445 DEBUG    MQTT       Publishing: emon/emontx2 {"MSG": 287922, "Vrms": 231.6, "P1": 12243, "P2": 4, "P3": 2706, "P4": 2, "E1": 831136, "E2": 239288, "E3": 189315, "E4": 160585, "T1": 0, "T2": 0, "T3": 0, "pulse": 0, "time": 1668116265.239381}
2022-11-10 21:37:50,189 DEBUG    RFM2Pi     171679 NEW FRAME : OK 11 179 100 4 0 249 90 251 255 44 29 251 255 21 0 227 105 0 0 251 190 5 0 221 102 0 0 103 34 0 0 0 0 0 0 0 0 0 0 0 0
2022-11-10 21:37:50,193 DEBUG    RFM2Pi     171679 Timestamp : 1668116270.188793
2022-11-10 21:37:50,195 DEBUG    RFM2Pi     171679 From Node : 11
2022-11-10 21:37:50,195 DEBUG    RFM2Pi     171679    Values : [287923, 232.89000000000001, -5, 7468, -5, 21, 27107, 376571, 26333, 8807, 0, 0, 0, 0]
2022-11-10 21:37:50,196 DEBUG    RFM2Pi     171679 Sent to channel(start)' : ToEmonCMS
2022-11-10 21:37:50,197 DEBUG    RFM2Pi     171679 Sent to channel(end)' : ToEmonCMS
2022-11-10 21:37:50,295 DEBUG    MQTT       Publishing: emon/emontx1 {"MSG": 287923, "Vrms": 232.89000000000001, "P1": -5, "P2": 7468, "P3": -5, "P4": 21, "E1": 27107, "E2": 376571, "E3": 26333, "E4": 8807, "T1": 0, "T2": 0, "T3": 0, "pulse": 0, "time": 1668116270.1887934}
2022-11-10 21:37:55,236 DEBUG    RFM2Pi     171680 NEW FRAME : OK 12 179 100 4 0 53 90 135 47 4 0 132 10 2 0 194 174 12 0 184 166 3 0 139 227 2 0 73 115 2 0 0 0 0 0 0 0 0 0 0 0
2022-11-10 21:37:55,239 DEBUG    RFM2Pi     171680 Timestamp : 1668116275.236220
2022-11-10 21:37:55,239 DEBUG    RFM2Pi     171680 From Node : 12
2022-11-10 21:37:55,240 DEBUG    RFM2Pi     171680    Values : [287923, 230.93, 12167, 4, 2692, 2, 831170, 239288, 189323, 160585, 0, 0, 0, 0]
2022-11-10 21:37:55,241 DEBUG    RFM2Pi     171680 Sent to channel(start)' : ToEmonCMS
2022-11-10 21:37:55,242 DEBUG    RFM2Pi     171680 Sent to channel(end)' : ToEmonCMS
2022-11-10 21:37:55,432 DEBUG    MQTT       Publishing: emon/emontx2 {"MSG": 287923, "Vrms": 230.93, "P1": 12167, "P2": 4, "P3": 2692, "P4": 2, "E1": 831170, "E2": 239288, "E3": 189323, "E4": 160585, "T1": 0, "T2": 0, "T3": 0, "pulse": 0, "time": 1668116275.23622}

Here’s the realtime visualisation showing 3 minutes behind on emonpi.

Here’s the feed screen showing the feeds delayed by 3 minutes

borpin · 11 November 2022 07:31

Can you screenshot the Inputs page.

[edit]
When looking at the emonhub log scrolling, the times shown there, matches the time on the PC?

a23452533 · 11 November 2022 10:53

Here’s the inputs page from this morning. Yes the emonhub
log matches the PC time.

In MQTT explorer, the messages also match emonhub-There is no delay.

If I reboot emonpi, the inputs start off coming through ok with no delay, but then deteriorate gradually over the day.

borpin · 11 November 2022 11:44

Can you adjust the emonhub config so it only sends one of the formats and then post emonhub log and emoncms log (preferably aligned), please?

It is very odd.

a23452533 · 11 November 2022 13:12

Will do. What should I comment out?
Thanks.

#######################################################################
#######################      emonhub.conf     #########################
#######################################################################
### emonHub configuration file, for info see documentation:
### http://github.com/openenergymonitor/emonhub/blob/emon-pi/configuration.md
#######################################################################
#######################    emonHub  settings    #######################
#######################################################################

[hub]
### loglevel must be one of DEBUG, DEBUG, DEBUG, ERROR, and CRITICAL
loglevel = DEBUG
### Uncomment this to also send to syslog
# use_syslog = yes
#######################################################################
#######################       Interfacers       #######################
#######################################################################

[interfacers]
### This interfacer manages the RFM12Pi/RFM69Pi/emonPi module
[[RFM2Pi]]
    Type = EmonHubJeeInterfacer
    [[[init_settings]]]
        com_port = /dev/ttyAMA0
        com_baud = 38400                       # 9600 for old RFM12Pi
    [[[runtimesettings]]]
        pubchannels = ToEmonCMS,
        subchannels = ToRFM12,

        group = 210
        frequency = 868
        baseid = 15                              # emonPi / emonBase nodeID
        quiet = true                            # Report incomplete RF packets (no implemented on emonPi)
        calibration = 230V                      # (UK/EU: 230V, US: 110V)
        # interval =  0                         # Interval to transmit time to emonGLCD (seconds)

[[MQTT]]

    Type = EmonHubMqttInterfacer
    [[[init_settings]]]
        mqtt_host = mqtt.lan
        mqtt_port = 1883
        mqtt_user = mqtt
        mqtt_passwd = xxxxxxx
#        mqtt_host = 127.0.0.1
#       mqtt_port = 1883
#      mqtt_user = emonpi
#        mqtt_passwd = emonpimqtt2016

    [[[runtimesettings]]]
        pubchannels = ToRFM12,
        subchannels = ToEmonCMS,

        # emonhub/rx/10/values format
        # Use with emoncms Nodes module
        node_format_enable = 0
        node_format_basetopic = emonhub/

        # emon/emontx/power1 format - use with Emoncms MQTT input
        # http://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
        nodevar_format_enable = 0
        nodevar_format_basetopic = emon/

        timestamped = True
        node_JSON_enable = 1
        node_JSON_basetopic = emon/

#[[emoncmsorg]]
#   Type = EmonHubEmoncmsHTTPInterfacer
#  [[[init_settings]]]
#   [[[runtimesettings]]]
#      pubchannels = ToRFM12,
#     subchannels = ToEmonCMS,
#        url = https://emoncms.org
#       apikey = xxxxxxx
#      senddata = 1                    # Enable sending data to Emoncms.org
#        sendstatus = 0                  # Enable sending WAN IP to Emoncms.org MyIP > https://emoncms.org/myip/list
#        sendinterval= 30                # Bulk send interval to Emoncms.org in seconds

#[[emoncmslocal]]
#   Type = EmonHubEmoncmsHTTPInterfacer
#    [[[init_settings]]]
#    [[[runtimesettings]]]
#        pubchannels = ToRFM12,
#        subchannels = ToEmonCMS,
#        url = http://localhost/emoncms
#        apikey = xxxxxxx
#        senddata = 0                    # Enable sending data to Emoncms.org
#        sendstatus = 0                  # Enable sending WAN IP to Emoncms.org MyIP > https://emoncms.org/myip/list
#        sendinterval= 10                # Bulk send interval to Emoncms.org in seconds

#[[emoncmsunraid]]
#    Type = EmonHubEmoncmsHTTPInterfacer
#    [[[init_settings]]]
#    [[[runtimesettings]]]
#        pubchannels = ToRFM12,
#        subchannels = ToEmonCMS,
#        url = http://192.168.27.3:8998
#        apikey = xxxxxxxxx
#        senddata = 1                    # Enable sending data to Emoncms.org
#        sendstatus = 0                  # Enable sending WAN IP to Emoncms.org MyIP > https://emoncms.org/myip/list
#        sendinterval= 5                # Bulk send interval to Emoncms.org in seconds

[Edit] removed API Keys and passwords - remember to do this when posting - Mod

borpin · 11 November 2022 14:10

According to this log, you already have removed the individual MQTT topics so you should only be publishing the JSON version (i.e. enable is 1).

Need to see the Emoncms log, preferably a snippet aligned with the emonhub log.

You could run these as a tail of the each log file in 2 separate SSH windows.(one log tail in each).

[edit]

tail -f /var/log/emonhub/emonhub.log | grep -e "Publishing"
tail -f /var/log/emoncms/emoncms.log | grep -e "emoncms_mqtt.php"

a23452533 · 11 November 2022 22:05

Thank you for persisting with me, Sorted now - user error, but not entirely sure of the cause.

Here’s what the 2 tails showed.

The MQTT connection error looked odd. Then I remembered that I’d started setting up a docker version of emoncms on my unRAID NAS. I had connected it to the same MQTT instance as emonpi because I wanted the docker to consume the same emonhub messages as emonpi. This was partially working because I could see all the inputs from MQTT in the docker instance. I didn’t finish setting it up because I couldn’t get the admin interface working properly.

I’d left that docker running. As soon as I shut it down, the inputs on emonpi started working properly again, with no delay, and the mqtt connection error on emonpi stopped appearing in the log.

Started the docker back up. Emonpi straight away showed 9 minutes delay.

I don’t know why the docker emoncms would conflict with the emonpi when consuming the same MQTT topics.

borpin · 12 November 2022 07:50

You need to post it as text, please.

[edit]
The info does need to make sense. Looks like the emoncms log level isn’t set to DEBUG.

You always get those warnings.

So is the time on the Docker MQTT, correct?

I’m unclear what settings you have on MQTT Brokers, emoncms & emonhub.

emonhub → Docker MQTT ← Emoncms - there is a delay
emonhub → EmonPi MQTT ← emoncms - no delay

If so looks like an issue with your Docker MQTT setup.

Did you change the settings for emonhub & emoncms to point to that Broker & restart both or did you just stop the Docker?

a23452533 · 18 November 2022 22:21

ah sorry I haven’t been clear.

Here’s what I had. The dotted lines show the 2nd instance (docker) of emoncms connected to my primary MQTT. When I shut the docker emoncms down then the problems disappeared.