Community
OpenEnergyMonitor

Community

MQTT gone on EmonBase

Tags: #<Tag:0x00007f6e0e444d90> #<Tag:0x00007f6e0e444c00>

I’ve had problems with the inputs on my EmonBase, so I decided do a full restore of the system and reset the SD-card to a fresh Build. Well, said and done the reinstallation went fine but when everything is up I still have errors relating to MQTT

This comes from the log, when just having booted up

LAST ENTRIES ON THE LOG FILE
2018-04-29 14:57:52.412|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' in /var/www/emoncms/scripts/phpmqtt_input.php:125
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(125): Mosquitto\Client->connect('localhost', 1883, 5)
#1 {main}
2018-04-29 14:57:52.561|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 14:57:58.001|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 14:57:58.006|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-04-29 14:58:06.210|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 14:58:06.240|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-04-29 15:01:11.662|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 15:01:11.681|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0

Where do I start to try to nail this error down?

Added, It might also be that the Radio module, for communication with my EmonTHs, have failed. How do I check that?

Tried Minicom, but it said Disconnected

Can you confirm exactly what hardware you have please (sometimes names get conflated). Is this just the wireless module, plugged into your own Pi?

Have you run an emoncms update? I think the SD card image may be behind the current stable version so it is worth doing.

Next to ‘Server information’ on the admin page, you will see ‘Copy to clipboard’. Click this and paste the information into a reply please.

Please post a bit more of the main log and also the emonhub log (same timeframe if possible).

Try the following commands and paste the output as well please.

sudo systemctl status emonhub
sudo systemctl status feedwriter
sudo systemctl status mqtt_input
sudo systemctl status mosquitto

Do you just have inputs from EmonTHs? This looks like a problem with the MQTT service

It’s one EmonBase purchased from the shop around May last year.(https://shop.openenergymonitor.com/emonbase-web-connected-base-station/), I guess it’s a RPi 3, and also 4 EmonTHs.

I’ve done updates to the latest version. Where/How can I find the main log, that you asked for?

LAST ENTRIES ON THE LOG FILE
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(125): Mosquitto\Client->connect('localhost', 1883, 5)
#1 {main}
2018-04-29 17:19:29.003|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 17:19:35.002|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' in /var/www/emoncms/scripts/phpmqtt_input.php:125
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(125): Mosquitto\Client->connect('localhost', 1883, 5)
#1 {main}
2018-04-29 17:19:35.003|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 17:19:41.002|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' in /var/www/emoncms/scripts/phpmqtt_input.php:125
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(125): Mosquitto\Client->connect('localhost', 1883, 5)
#1 {main}
2018-04-29 17:19:41.002|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 17:19:47.001|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' in /var/www/emoncms/scripts/phpmqtt_input.php:125
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(125): Mosquitto\Client->connect('localhost', 1883, 5)
#1 {main}
2018-04-29 17:19:47.002|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 17:19:53.002|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 17:19:53.004|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-04-29 18:24:50.705|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 18:24:50.754|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-04-29 18:26:38.683|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-04-29 18:26:38.736|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0

Server Information
Emoncms Version low-write 9.8.28 : 2018.01.27
Modules Administration : App v1.1.0 : Backup v1.1.2 : EmonHub Config v1.0.0 : Dashboard v1.1.1 : EventProcesses : Feed : Graph v1.2.0 : Input : postprocess : CoreProcess : Schedule : setup : sync : Time : User : Visualisation : WiFi v1.0.0
Buffer loading…
Writer Daemon is running with sleep 60s
Server OS Linux 4.9.35-v7+
Host emonpi emonpi (127.0.1.1)
Date 2018-04-30 08:58:44 CEST
Uptime 08:58:44 up 14:57, 1 user, load average: 0.10, 0.13, 0.10
HTTP Server Apache/2.4.10 (Raspbian) HTTP/1.1 CGI/1.1 80
MySQL Version 5.5.57-0+deb8u1
Host localhost (127.0.0.1)
Date 2018-04-30 08:58:44 (UTC 02:00‌​)
Stats Uptime: 53848 Threads: 2 Questions: 9016 Slow queries: 0 Opens: 59 Flush tables: 1 Open tables: 52 Queries per second avg: 0.167
Redis Version 2.8.17
Host localhost:6379 (127.0.0.1)
Size 63 keys (485.48K)
Uptime 0 days
MQTT Version 1.4.14
Host localhost:1883 (127.0.0.1)
Pi CPU Temp 54.77°C
Release emonSD-26Oct17
File-system Set root file-system temporarily to read-write, (default read-only)
Memory RAM Used: 26.54% Total: 970.93 MB Used: 257.73 MB Free: 713.2 MB
Disk Mount Stats
/ Used: 60.82% Total: 3.33 GB Used: 2.03 GB Free: 1.14 GB
/boot Used: 36.36% Total: 59.95 MB Used: 21.8 MB Free: 38.15 MB
/home/pi/data Used: 8.90% Total: 968.33 MB Used: 86.21 MB Free: 832.13 MB
PHP Version 5.6.30-0+deb8u1 (Zend Version 2.6.0)
Modules apache2handler : bcmath : bz2 : calendar : Core v5.6.30-0+deb8u1 : ctype : curl : date v5.6.30-0+deb8u1 : dba : dio v0.0.4RC4 : dom v20031129 : ereg : exif v1.4 : fileinfo v1.0.5 : filter v0.11.0 : ftp : gettext : hash v1.0 : iconv : json v1.3.6 : libxml : mbstring : mcrypt : mhash : mosquitto v0.3.0 : mysql v1.0 : mysqli v0.1 : openssl : pcre : PDO v1.0.4dev : pdo_mysql v1.0.2 : Phar v2.0.2 : posix : readline v5.6.30-0+deb8u1 : redis v2.2.7 : Reflection : session : shmop : SimpleXML v0.1 : soap : sockets : SPL v0.2 : standard v5.6.30-0+deb8u1 : sysvmsg : sysvsem : sysvshm : tokenizer v0.1 : wddx : xml : xmlreader v0.1 : xmlwriter v0.1 : Zend OPcache v7.0.6-devFE : zip v1.12.5 : zlib v2.0 :
[email protected](ro):~$ sudo systemctl status emonhub
● emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (exited) since Mon 2018-04-30 09:02:33 CEST; 6min ago

Apr 30 09:02:37 emonpi emonhub[18195]: Traceback (most recent call last):
Apr 30 09:02:37 emonpi emonhub[18195]: File "/usr/share/emonhub/emonhub.py", line 328, in <module>
Apr 30 09:02:37 emonpi emonhub[18195]: hub = EmonHub(setup)
Apr 30 09:02:37 emonpi emonhub[18195]: File "/usr/share/emonhub/emonhub.py", line 75, in __init__
Apr 30 09:02:37 emonpi emonhub[18195]: self._update_settings(settings)
Apr 30 09:02:37 emonpi emonhub[18195]: File "/usr/share/emonhub/emonhub.py", line 213, in _update_settings
Apr 30 09:02:37 emonpi emonhub[18195]: interfacer.set(**I['runtimesettings'])
Apr 30 09:02:37 emonpi emonhub[18195]: File "/home/pi/emonhub/src/interfacers/EmonHubJeeInterfacer.py", line 192, in set
Apr 30 09:02:37 emonpi emonhub[18195]: time.sleep(1)
Apr 30 09:02:37 emonpi emonhub[18195]: KeyboardInterrupt
[email protected](ro):~$ sudo systemctl status feedwriter
● feedwriter.service - LSB: feedwriter script daemon
   Loaded: loaded (/etc/init.d/feedwriter)
   Active: active (exited) since Sun 2018-04-29 18:01:33 CEST; 15h ago

Apr 29 18:01:20 emonpi systemd[1]: Starting LSB: feedwriter script daemon...
Apr 29 18:01:20 emonpi feedwriter[1712]: Log is turned off
Apr 29 18:01:20 emonpi feedwriter[1712]: Starting RPI
Apr 29 18:01:33 emonpi systemd[1]: Started LSB: feedwriter script daemon.
[email protected](ro):~$ sudo systemctl status mqtt_input
● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: loaded (/etc/systemd/system/mqtt_input.service; enabled)
   Active: active (running) since Mon 2018-04-30 09:02:52 CEST; 6min ago
     Docs: https://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
 Main PID: 18801 (php)
   CGroup: /system.slice/mqtt_input.service
           └─18801 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Apr 30 09:02:52 emonpi systemd[1]: Started Emoncms MQTT Input Script.
[email protected](ro):~$ sudo systemctl status mosquitto
● mosquitto.service - Mosquitto MQTT Broker
   Loaded: loaded (/lib/systemd/system/mosquitto.service; enabled)
   Active: active (running) since Sun 2018-04-29 19:19:47 CEST; 13h ago
     Docs: man:mosquitto(8)
           https://mosquitto.org/
 Main PID: 9760 (mosquitto)
   CGroup: /system.slice/mosquitto.service
           └─9760 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf

Apr 29 19:19:47 emonpi systemd[1]: Started Mosquitto MQTT Broker.

image

It is the emonhub log. Actually I am not sure where it is on this setup @pb66 will be able to help on that.

From what you have sent, it can be seen that the emoncms mqtt_input and mosquitto services are running but not emonhub and feedwriter.

Could you check your settings.php and set the log level to INFO please.

I do not understand why the Mosquitto MQTT service apparently keeps on dropping the connection. However, this has been seen elsewhere recently.

[edit] please also confirm the mosquitto version

$mosquitto -v

Check emonhub.log either via the emoncms - emonhub config page or by checking the files at /var/log/emonhub/emonhub.log

Can you also uncollapse one of your inputs on the input page of emoncms and check for duplicated inputs, ie 2 complete sets of inputs under one heading, the first set not updating and the second set in green.

Luckily the emonhub.log is still found in the same place on all linux based installs at /var/log/emonhub/emonhub.log.

Although I’m not entirely sure the “Active: active (exited)” is indicative of a failed or stopped service, we see this quite frequently (eg emonPi hangs and stops logging). I’m tempted to say it’s more likely to be linked to the fact the emonhub and feedwriter services are systemV init scripts being run in “compatibility mode” by systemd, but I cannot be sure. Both Mosquitto and mqtt_input services are systemd units.

Looking at the “server information” that shows the feedwriter as running and I see no “errors” in the short log attached to the emonhub service status, only some valid start up lines and the last entry is a keyboard interrupt. @Daniel_Edvall have you manually stopped the emonhub service to try minicom?

What I do find interesting is that both the emonhub and mqtt_input services are only running 6mins were as the other 2 are running 15hours, @Daniel_Edvall did something significant ocurr 6mins before checking the statuses? eg running the emonpi update again.

It’s always been an issue since MQTT was first implemented, the apparent changes in frequency have been due to other issues coming and going so more or less logs are seen, and at some point the code was changed so the errors weren’t logged but the problem has always been there.

Presumably you mean since MQTT was implemented in emonhub. I use the HTTP API from emonhub without issue and MQTT for other inputs. I do not see these connections/disconnections so it implies it is an emonhub implementation of MQTT rather than the emoncms side (though the 2 could be interacting to cause the issues).

Need to see if the process is running ps something (not that much of a linux man).

Sorry, yes, I should have been clearer. It has always been a problem since MQTT was implemented on the emonPi, the mqtt implementation in emonhub and emoncms were rolled out together and both parts have been replaced/rewritten since their original release.

I do not know what part is at fault for this specific issue, I just know that both parts are “not right” for various reasons and together they have a problem on the emonSD image. I assume that the Mosquito broker or MQTT in general isn’t to blame but the emonPi image also has openHab and nodered and emonLCD etc that I’m not familiar with, but I have seen error logs showing they have issues too, but is that a cause or effect? chicken and egg situation!

That is how the emoncms admin page is updated with the feedwriter service status. The systend status check should be the correct way of checking, we just need to learn how to interpret the messages with some confidence and perhaps make some changes so they work correctly if necessary.

@Daniel_Edvall can you try this please…

sudo service emonhub status 
sudo service feedwriter status

It is likely they are running but just to check…

could you also run as well so we have them in the same timeframe.

sudo systemctl status mqtt_input
sudo systemctl status mosquitto

ps -ef or ps -aux should do what you want, Brian.

1 Like

I just did some very basic tests and I now suspect emonhub is NOT running. Despite the other occurances, I have not been able to recreate emonhub running and observe a “Active: active (exited)” service (although I wouldn’t class my tests as conclusive) but what I have noticed is the way the log entries seem to work and the service log seems to show a keyboard interrupt. I suspect that can only occur if emonhub is started from the command line using

/usr/share/emonhub/emonhub.py

and then stopping that instance with CTRL-C.

BUT that might then refer to the command line instance not the daemon. I think we need to know more about what @Daniel_Edvall has been trying.

What does

ps -ef | grep -E 'emonhub|feedwriter|mqtt_input|mosquitto'

reveal?

sudo service xyz status and sudo systemctl status xyz should return the same data as they are doing the same job, the 1st is just to offer backward compatibility. eg

[email protected](rw):~$ sudo service emonhub status
â emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (running) since Mon 2018-04-30 10:49:31 UTC; 18min ago
  Process: 9273 ExecStop=/etc/init.d/emonhub stop (code=exited, status=0/SUCCESS)
  Process: 9826 ExecStart=/etc/init.d/emonhub start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/emonhub.service
           ââ9876 python /usr/share/emonhub/emonhub.py --config-file /home/pi/data/emonhub.conf --logfile /var/log/emonhub/emonhub.log

Apr 30 10:49:30 emonpi sudo[9836]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 30 10:49:30 emonpi sudo[9836]: pam_unix(sudo:session): session closed for user root
Apr 30 10:49:30 emonpi sudo[9847]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown -R emonhub /var/log/emonhub
Apr 30 10:49:30 emonpi sudo[9847]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 30 10:49:30 emonpi sudo[9847]: pam_unix(sudo:session): session closed for user root
Apr 30 10:49:30 emonpi sudo[9856]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown -R emonhub /var/log/emonhub
Apr 30 10:49:31 emonpi sudo[9856]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 30 10:49:31 emonpi sudo[9856]: pam_unix(sudo:session): session closed for user root
Apr 30 10:49:31 emonpi emonhub[9826]: Starting OpenEnergyMonitor emonHub: emonhub has been started ok.
Apr 30 10:49:31 emonpi systemd[1]: Started LSB: Start/stop emonHub.
[email protected](rw):~$ sudo systemctl status emonhub
â emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (running) since Mon 2018-04-30 10:49:31 UTC; 18min ago
  Process: 9273 ExecStop=/etc/init.d/emonhub stop (code=exited, status=0/SUCCESS)
  Process: 9826 ExecStart=/etc/init.d/emonhub start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/emonhub.service
           ââ9876 python /usr/share/emonhub/emonhub.py --config-file /home/pi/data/emonhub.conf --logfile /var/log/emonhub/emonhub.log

Apr 30 10:49:30 emonpi sudo[9836]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 30 10:49:30 emonpi sudo[9836]: pam_unix(sudo:session): session closed for user root
Apr 30 10:49:30 emonpi sudo[9847]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown -R emonhub /var/log/emonhub
Apr 30 10:49:30 emonpi sudo[9847]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 30 10:49:30 emonpi sudo[9847]: pam_unix(sudo:session): session closed for user root
Apr 30 10:49:30 emonpi sudo[9856]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown -R emonhub /var/log/emonhub
Apr 30 10:49:31 emonpi sudo[9856]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 30 10:49:31 emonpi sudo[9856]: pam_unix(sudo:session): session closed for user root
Apr 30 10:49:31 emonpi emonhub[9826]: Starting OpenEnergyMonitor emonHub: emonhub has been started ok.
Apr 30 10:49:31 emonpi systemd[1]: Started LSB: Start/stop emonHub.
[email protected](rw):~$

Well, uhm, the inactive feeds now seems to be active again. My procedure:
Shut down the PI and with surgial precision made sure that the RFM69Pi module were inserted properly. This time I also made shure the LED on RFM69Pi lighted up on boot, and sometimes blinked. What was different this time other than this, compared to the other 10 times I’ve done this, I do not know, but upon boot the feeds kicked alive and started recieving data.

Out if interest, you still want me to give some logs and statuses? @pb66, @borpin

Fair enough although I am sure I have seen differences in the past as the method of query (I thought) was different (systemd v SysV).

In any case, I am wondering if part of the solution is to port emonhub and feedwriter to systemd.