EmonPi2 Inputs Not Updating

dodger421 · 2024-05-06T11:13:17.734Z

On Friday I noticed the EmonPi2 inputs hadn’t updated for a few hours. Since then I’ve tried rebooting, updating, changing firmware versions and anything else I could think of that would retain the data logged from 29th March until now.

As that wasn’t getting anywhere I opted to follow the “factory reset” steps in the documentation. This successfully wiped the config and all data but needed a manual insert of the emonPi2 emonhub.conf.

After this the inputs updated once after rebooting the emonPi but then freeze again.

The emonhub log and serial monitor show the values coming in every 10 seconds and the only warning in the log was for being unable to open a USB serial port (which makes sense because I don’t have anything plugged into the USB ports).

No changes were made to the EmonHub/EmonCMS config before it stopped working, I just logged in to view my ASHP data and noticed the power/energy inputs hadn’t updated.

My next step is to try re-flashing the SD card but I really doubt that’s going to achieve anything at this stage. The only odd thing I’ve noticed is that the Pi status doesn’t seem recognise the RPi4 anymore, but I’m not sure if this is relevant?

Screenshot 2024-05-06 at 11.48.391856×1008 106 KB

Screenshot 2024-05-06 at 11.49.432726×1524 266 KB

Screenshot 2024-05-06 at 12.07.512274×462 48.8 KB

dodger421 · 2024-05-06T14:23:23.394Z

Re-flashing the SD card and updating all modules has now gotten the inputs logging again.

borpin · 2024-05-09T15:13:36.346Z

If it happens again SSH into the Pi and do a df -h to check the log partition isn’t full. Most common reason.

Robert.Wall · 2024-05-09T16:51:56.996Z

Might this be related to

Emonsd Feb24 - ttyAMA0 used by kernel causing interference with RFM / emonhub emonSD

Hi All Sorry I’ve been so quiet for such a long time, health problems, I’ve been debugging an issue after a fresh upgrade to emonSD Feb2024 on emonpi1. Symtom: emonhub would stop receiving data from serial / RF seemingly randomly, daily. I would also see random inputs appear and in some cases nodeid 5 data would appear as another nodeid altogether. Many days of debugging emonhub and atmega firmware, finally culminating in logging every character sent and received on serial and I discovered t…

dodger421 · 2024-05-09T20:28:05.361Z

Oddly enough the serial inputs have, once again, stopped logging. The system is now at 106 minutes without a serial input update.

df -h shows 10% use for /var/log (4.7M used, 46M free of 50M allocated). This is also represented in the “Admin” GUI and is similar to the values seen on Monday.

The linked post looked promising, I’ve since tried both the Full Update method suggested by @TrystanLea and the SSH raspi-config method to fix the updates. Neither has worked.

The EmonHub log still shows New Frames and MQTT messages every 10 seconds as expected, the feedwriter shows 200+ feed points pending write.

Edited to add I’ve also checked the cmdline.txt via nano and confirmed the serial0 lines have been removed.

Screenshot 2024-05-09 at 21.35.381540×1134 128 KB

alandpearson · 2024-05-09T23:39:28.473Z

I’m by no means an expert…

from what I see radio hardware is working and data making it to emonhub (you said when the system has inputs not updating you still see MQTT messages in emonhub.log and presumably serial frames like your screenshot in the same log file).
This tells me emonhub is doing its thing and the problem likely emoncms.

emonhub is a python application that gets the data from radio using an “interfacer” (which talks to either serial or SPI if this is a emonpi2) and then publishes it to MQTT. It does not populate emoncms (what you see as the User interface with inputs).

emoncms is a PHP web application that gets data via emoncms_mqtt.php which subscribes to the MQTT topic that emonhub is publishing to (normally emon/ ) and puts the data into emoncms inputs.
To me this looks like the broken part…

Can you ssh in to the box and do:

ps -ef | grep mqtt

which should yield something like :

root      1128     1 26 May09 ?        02:24:59 /usr/bin/php /var/www/emoncms/scripts/services/emoncms_mqtt/emoncms_mqtt.php
pi    22730 16947  0 00:33 pts/1    00:00:00 grep --color=auto mqtt

also run

systemctl status emoncms_mqtt

which should yield something like:

 emoncms_mqtt.service - Emoncms emoncms_mqtt script
     Loaded: loaded (/etc/systemd/system/emoncms_mqtt.service; enabled; preset: enabled)
     Active: active (running) since Thu 2024-05-09 14:59:17 BST; 9h ago
       Docs: https://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
    Process: 950 ExecStartPre=/bin/mkdir -p ${LOG_PATH} (code=exited, status=0/SUCCESS)
    Process: 1120 ExecStartPre=/bin/chown ${USER} ${LOG_PATH} (code=exited, status=0/SUCCESS)
    Process: 1123 ExecStartPre=/bin/touch ${LOG_PATH}/emoncms.log (code=exited, status=0/SUCCESS)
    Process: 1125 ExecStartPre=/bin/chmod 666 ${LOG_PATH}/emoncms.log (code=exited, status=0/SUCCESS)
   Main PID: 1128 (php)
      Tasks: 1 (limit: 1571)
        CPU: 2h 25min 51.658s
     CGroup: /system.slice/emoncms_mqtt.service
             └─1128 /usr/bin/php /var/www/emoncms/scripts/services/emoncms_mqtt/emoncms_mqtt.php

Look too at /var/log/emoncms/emoncms.log
You may want to enable more logging for emoncms - edit /var/www/emoncms/settings.ini and under the [log] section set level to 1, then restart with

systemctl stop emoncms_mqtt
systemctl start emoncms_mqtt

[EDIT]
Check feedwriter too please :

pi@emonpi: systemctl status feedwriter.service 

feedwriter.service - Emoncms feedwriter script
     Loaded: loaded (/etc/systemd/system/feedwriter.service; enabled; preset: enabled)
     Active: active (running) since Thu 2024-05-09 14:59:17 BST; 9h ago
       Docs: https://github.com/emoncms/emoncms/blob/master/scripts/services/install-service-feedwriter.md
    Process: 951 ExecStartPre=/bin/mkdir -p ${LOG_PATH} (code=exited, status=0/SUCCESS)
    Process: 1121 ExecStartPre=/bin/chown ${USER} ${LOG_PATH} (code=exited, status=0/SUCCESS)
    Process: 1124 ExecStartPre=/bin/touch ${LOG_PATH}/emoncms.log (code=exited, status=0/SUCCESS)
    Process: 1127 ExecStartPre=/bin/chmod 666 ${LOG_PATH}/emoncms.log (code=exited, status=0/SUCCESS)
   Main PID: 1131 (php)
      Tasks: 1 (limit: 1571)
        CPU: 18.206s
     CGroup: /system.slice/feedwriter.service
             └─1131 /usr/bin/php /var/www/emoncms/scripts/feedwriter.php

Let’s see what that shows…

[EDIT2]
You could also try downloading MQTT-Explorer http://mqtt-explorer.com and point it to your emonpi , you are looking at the emon/ topic to see that it is being published to correctly (this will eliminate the whole emonhub part from the equation if it is)… Here’s a screenshot (note your emonpi entry is likely called emonpi not emonpiCM like mine):

Screenshot 2024-05-10 at 01.06.281640×1398 263 KB

Please post an emonhub.log snippet with debug enabled when the system isn’t working… I’d like to verify the frames being sent & received look correct (correct nodeID etc).

dodger421 · 2024-05-10T11:41:48.430Z

I very much appreciate the help because this is baffling me. Last serial input update now 17 hours ago.

Emonhub log snippet, debug with system not working.

Screenshot 2024-05-10 at 12.35.302720×1040 484 KB

grep mqtt and emoncms_mqtt commands

Screenshot 2024-05-10 at 12.28.501556×600 90.4 KB

feedwriter

Screenshot 2024-05-10 at 12.32.021556×490 218 KB

MQTT explorer. Mosquitto on Home Assistant is configured as a bridge re-transmitting MQTT information from a couple of sensors for the Panasonic ASHP and GivEnergy inverter/battery.

Screenshot 2024-05-10 at 12.32.572272×1664 230 KB

dodger421 · 2024-05-10T12:03:34.104Z

alandpearson:

Look too at /var/log/emoncms/emoncms.log
You may want to enable more logging for emoncms - edit /var/www/emoncms/settings.ini and under the [log] section set level to 1, then restart with
systemctl stop emoncms_mqtt
systemctl start emoncms_mqtt

I also changed the emoncms log level to 1 (info) as suggested. Interestingly this shows no MQTT data for the emonpi2 or GivEnergy topics. This tallies with the “inputs” page showing the last update 17 and 15 hours ago respectively for these two topics. MQTT Explorer continues to show refreshes and new data for these topics.

alandpearson · 2024-05-10T12:31:11.888Z

OK, we’re onto something.
emonhub is working just fine and doing as it should.
The values in the log look good, and it’s publishing the emon topic as it should too.
The question is why is emoncms_mqtt.php not doing anything…

With debug to 1 on my system, the log is going crazy … it logs a line for every MQTT topic/value it gets.

alandpearson · 2024-05-10T12:32:18.050Z

Can you post the emoncms_mqtt log with debug at 1 ?
[EDIT] from the start after a restart… I’d like to see if it successfully connects to mosquito.

Also, try restarting it with

systemctl stop emoncms_mqtt
systemctl start emoncms_mqtt

This one is a mystery…

[EDIT] To be clear, again, the emonpi installation (both settings.ini and emonhub.conf) are pointed at the emonpi mosquito instance right ? You mentioned mosquitto on HA …

dodger421 · 2024-05-10T12:55:00.973Z

A brief snippet after restart (via command line).

2024-05-10 12:47:37.-451|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 12:47:37.-451|WARN|emoncms_mqtt.php|Not connected, retrying connection
2024-05-10 12:47:37.-440|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2024-05-10 12:47:37.-440|INFO|emoncms_mqtt.php|Subscribed to: emon/# ID - 2
2024-05-10 12:47:37.-430|INFO|emoncms_mqtt.php|Callback subscribed to topic: 
2024-05-10 12:47:37.-419|INFO|emoncms_mqtt.php|MQTT Valid JSON found 
2024-05-10 12:47:37.-419|INFO|emoncms_mqtt.php|No time element found in JSON - System time used
2024-05-10 12:47:37.-419|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/stats {"uptime":8352320,"voltage":3.38,"free memory":73,"free heap":28632,"wifi":40,"mqtt reconnects":4,"total reads":2871,"good reads":2871,"bad crc reads":0,"bad header reads":0,"too short reads":0,"too long reads":0,"timeout reads":0,"version":"3.2.3"}
2024-05-10 12:47:37.-386|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Pump_Flow 30.92
2024-05-10 12:47:37.-365|INFO|feed_model.php|post() feedid=43 updatetime=1715345257 feedtime=1715345257 value=30.92 padding_mode=
2024-05-10 12:47:37.-353|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Heatpump_State 1
2024-05-10 12:47:37.-322|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Force_DHW_State 0
2024-05-10 12:47:37.-292|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Quiet_Mode_Schedule 0
2024-05-10 12:47:37.-263|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Operating_Mode_State 4
2024-05-10 12:47:37.-233|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Main_Inlet_Temp 53.50
2024-05-10 12:47:37.-214|INFO|feed_model.php|post() feedid=28 updatetime=1715345257 feedtime=1715345257 value=53.50 padding_mode=join
2024-05-10 12:47:37.-202|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Main_Outlet_Temp 58.50
2024-05-10 12:47:37.-183|INFO|feed_model.php|post() feedid=29 updatetime=1715345257 feedtime=1715345257 value=58.50 padding_mode=join
2024-05-10 12:47:37.-172|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Main_Target_Temp 59
2024-05-10 12:47:37.-153|INFO|feed_model.php|post() feedid=30 updatetime=1715345257 feedtime=1715345257 value=59 padding_mode=join
2024-05-10 12:47:37.-141|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Compressor_Freq 35
2024-05-10 12:47:37.-111|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/DHW_Target_Temp 50
2024-05-10 12:47:37.-81|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/DHW_Temp 48
2024-05-10 12:47:37.-52|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Operations_Hours 947
2024-05-10 12:47:37.-22|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Operations_Counter 6425
2024-05-10 12:47:38.007|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Main_Schedule_State 0
2024-05-10 12:47:38.036|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Outside_Temp 20
2024-05-10 12:47:38.055|INFO|feed_model.php|post() feedid=31 updatetime=1715345258 feedtime=1715345258 value=20 padding_mode=join
2024-05-10 12:47:38.068|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/main/Heat_Power_Production 0
2024-05-10 12:47:38.084|INFO|feed_model.php|post() feedid=35 updatetime=1715345258 feedtime=1715345258 value=0 padding_mode=
2024-05-10 12:47:38.085|INFO|feed_model.php|post() feedid=44 updatetime=1715345258 feedtime=1715345258 value=0 padding_mode=join
2024-05-10 12:47:38.086|INFO|feed_model.php|post() feedid=45 updatetime=1715345258 feedtime=1715345258 value=75.901277777762 padding_mode=join
2024-05-10 12:47:38.087|INFO|feed_model.php|post() feedid=36 updatetime=1715345258 feedtime=1715345258 value=60.356888888876 padding_mode=join
2024-05-10 12:47:38.088|INFO|feed_model.php|post() feedid=37 updatetime=1715345258 feedtime=1715345258 value=0 padding_mode=join

Emonhub.conf

 [[MQTT]]
        Type = EmonHubMqttInterfacer
        [[[init_settings]]]
            mqtt_host = 127.0.0.1
            mqtt_port = 1883
            mqtt_user = emonpi
            mqtt_passwd = emonpimqtt2016

and Settings.ini both point at the emonpi MQTT interfacer

[mqtt]
enabled = true
user = 'emonpi'
password = 'emonpimqtt2016'

Mosquitto on Home Assistant uses the following as a bridge configuration to the emonpi MQTT broker. I’m no MQTT expert but I believe this is the correct configuration and MQTT explorer seems to confirm this.

connection emonCMS_emonPi2
remote_username emonpi
remote_password emonpimqtt2016
address 192.168.50.43:1883
topic # both 0 "" emon/

alandpearson · 2024-05-10T13:09:37.608Z

the log shows entries from the heat pump… JSON format
Do you see these as inputs being updated ?
I’m guessing yes

Are there no entries at all for other topics… e.g. emonpi2 ?
(FYI the emonhub entries are not published as JSON, but this is more fyi than anything)

alandpearson · 2024-05-10T13:15:13.584Z

Is there any way you can stop everything publishing to mqtt except the emonpi ? You shouldn’t have to restart anything on the emonpi.

[edit] try first without restarting anything, then try restarting emoncms_mqtt.php

(I’m wondering does the JSON decoding interfere with normal operation, but this could be a red herring.)

dodger421 · 2024-05-10T13:29:08.571Z

Yes, the heat pump, aquarea and home assistant inputs all update as expected. The Emonpi2 doesn’t appear at all and GivEnergy only posts a status message (which is also updating).

This is a txt of the complete log download.

emoncms-6.txt (4.3 MB)

I’m just trying to comment out the bridge configuration to stop the rebroadcast from Home Assistant.

alandpearson · 2024-05-10T13:38:20.700Z

Ok, my next steps which you may not be comfortable with involve hacking on the emoncms_mqtt.php code to see what is going on.

You do this at your own risk !
Backup the file first and the first thing I’d want to do is add an additional log message at line 268, in the message function to check it is actually receiving non-json data from mqtt.
Add this line:
$log->info("Received topic: " + $topic + " Value: " + $value);

restart emoncms_mqtt and I’d imagine your log will be filled with the other inputs…
We’ll then have to add other logging statements to see why they aren’t being processed if so.

I’m not a dev for this project and maybe others can come in with other ways without hacking the code…

dodger421 · 2024-05-10T13:56:17.353Z

Ok, this is slightly promising. Removing the bridge configuration and deleting the previously subscribed topics using MQTT explorer has gotten the emonPi2 inputs updating again.

Just stopping removing the bridge configuration did not work, even though the other topics were not updating.

I have not added any code to the emoncms_mqtt.php file yet.

alandpearson · 2024-05-10T15:12:32.226Z

Ok, my guess is it looks like emoncms_mqtt.php is receiving something that it doesn’t like and blocking non-JSON reception…or maybe another way to put it is blocking node/topic=value format.

I see two suspicious things in your log…
Every 10 seconds mqtt disconnects :

2024-05-10 13:21:57.-478|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:22:07.-477|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:22:17.-476|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:22:27.-442|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:22:37.-479|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:22:47.-458|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:22:57.-476|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:23:07.-469|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:23:17.-455|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:23:27.-460|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:23:37.-474|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:23:47.-438|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:23:57.-472|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:24:07.-438|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:24:17.-469|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:24:27.-464|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:24:37.-444|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:24:47.-473|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:24:57.-475|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:25:07.-457|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:25:17.-451|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:25:27.-438|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:25:37.-441|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly
2024-05-10 13:25:47.-466|WARN|emoncms_mqtt.php|MQTT has disconnected - cleanly

and I see this:

2024-05-10 13:17:02.-64|INFO|emoncms_mqtt.php|emon/panasonic_heat_pump/stat0 ^_^@^Wpanasonic_heat_pump/LWTOnlineÀ^@0g^@^Wpanasonic_heat_pump/logTue Feb 20 01:21:31 2024 (119171633): Received bad header. Ignoring this data!0«^B^@^Wpanasonic_heat_pump/logTue Feb 20 01:21:31 2024 (119171636): Heishamon stats: Uptime: 1 day 9 hours 6 minutes 11 second

Note the silly characters which are non-ascii control characters… Some sort of dodgy data is being sent into MQTT topic… I’m not sure if this is causing all the disconnections but it is worth looking at.

I’m not sure it will tell us anything but a look at /var/log/mosquitto/mosquitto.log may be worth it

Also try stopping emoncms_mqtt.php (systemctl stop emoncms_mqtt) and run it manually to see if php is spitting out any errors when HA is pushing data into emon/:

/usr/bin/php /var/www/emoncms/scripts/services/emoncms_mqtt/emoncms_mqtt.php

[EDIT] Look at lines 62 to lines 133 in the emoncms_mqtt.log file you sent…it looks like another issue (likely THE issue) is your GivEnergy node. It is sending a many, many messages in about 3 seconds after which emoncms_mqtt disconnects from mosquitto. Something smells wrong there. That pattern continues ad-infinitum in the log, which is likely the reason we don’t see other MQTT inputs.

I’d look to sort out both those issues and see if that solves it.

dodger421 · 2024-05-10T21:02:52.004Z

Thanks for your help with this. I’d noted the MQTT disconnects but thought they were fairly normal.

Rather than bridging everything from the HA broker to the EmonPi broker I’ve selectively re-enabled topics and messages to try and get to the root cause. It does look like an invalid result was received from the heat pump translator, hopefully that’s been resolved.

Since I removed the “homeassistant” topic (and duplicate GivEnergy sensor entities) from the broadcast and all the “raw” topics from GivEnergy and the panasonic_heat_pump topic everything seems to have been stable and updating as it should.