Mqtt_input script run as systemd instead of initd

[glyn.hudson]

The mqtt_input service runs the phpmqtt_input script which subscribes to MQTT topics and posts data to local Emoncms. It’s used on the emonSD which is running on emonPi / emonBase.

Following on from mqtt_input script debugging, see threads:

Adding a node with MQTT problem

I’m trying to build a custom node with an ESP8266. I don’t want to publish data with the URL+KEY method, so I’m trying to write (and read) data via MQTT. The message I am posting is “emon/EVSE/power1” with an int power value. I added this in the configuration file under [nodes] [[42]] nodename = EVSE [[[rx]]] names = power1 datacodes = h scales = 1 units = W I can see the new node in the Inputs tab, but when I try to add a “Log to feed” I get this erro…

Cannot create Feed from MQTT input

Continuing the discussion from Publish to MQTT Issue: I am experiencing the same ERROR: Could not save processlist. undefined disappear issue. I created a simple nodered flow that publishes gallons to emon/water/gallons. I can see the data on the Input View page: [image]   and I can do a MQTT subscribe and all the data appears as expected. But when I click on the Spanner/Wrench, create a feed and click Changed, press to save I then get this error: [image] A reboot seemed to fix this l…

Publish to MQTT Issue

I am trying to publish two items to MQTT and I think I am doing something wrong. This is an emonPi with the emonSD-03May16 image. And I am using Node-RED to publish the two items. When I look at the Input View via 192.168.40.230/emoncms/input/view I see one value for a split second and then it is replaced by the 2nd value. The first value is published to emon/RF1/power1: [image]   The second value is published to emon/RF1/energy_kWh and I also tried emon/RF2/energy_kWh: [image]   Bot…

and GitHub issue:

Issue logging input to feed: "Error could not save process list Undefined"

---

I have made a change to the mqtt_input script to move to running it as a systemd service rather than init.d. This will give us better debugging and adds the feature of auto-restarting the mqtt_input script after 60s if for some reason the script crashes. The systemd unit file also specifies that the mqtt_input script should start after mysql, redis and mosquitto have started. I am quite new to using systemd, any feedback / improvements to the unit file would be appreciated.

See systemd unit file:

emoncms/emoncms/blob/master/scripts/mqtt_input.service

Running emonpi update will automatically remove the initd service and replace with the systemd mqtt_service service.

See emonpi emoncms update entry:

change mqtt_input to use systemd instead of initd

---

The mqt_input script can still be stop / started in the old way:

sudo service mqtt_input status

However, to get full benefit of using systemd we should use the new

sudo systemctl status mqtt_input.

The mqtt_input script logfile (last 100 lines) can be viewed by running:

sudo systemctl status mqtt_input -n100

Example output:

emonpi$ sudo systemctl status mqtt_input.service 
● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: loaded (/etc/systemd/system/mqtt_input.service; enabled)
   Active: active (running) since Thu 2017-01-05 10:25:05 UTC; 2min 51s ago
 Main PID: 8727 (php)
   CGroup: /system.slice/mqtt_input.service
           └─8727 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/power4 0
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/vrms 240.77
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/temp1 300
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/temp2 300
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/temp3 300
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/temp4 300
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/temp5 300
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/temp6 300
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/pulse 0
Jan 05 10:27:55 rfm69pi php[8727]: emon/emontx3/rssi -27

[pb66 (Paul)]

@glyn.hudson can you explain the example output you gave?

I don’t understand where the “rfm69pi php[8727]” ref comes from. Have you got a PHP script running in place of emonHub for RF? As I already use the systemctl status with the existing set up I am keen to understand the gains.

Before updating the emonPi I ran systemctl status for the mqtt_input for comparison, the emonPi was previously bang up to date and currently has 4 nodes being published over MQTT.

This is before updating

pi@emonpi(ro):~$ sudo systemctl status mqtt_input.service -n100
● mqtt_input.service - LSB: Starts phpmqtt_input agent daemon at boot time
   Loaded: loaded (/etc/init.d/mqtt_input)
   Active: active (running) since Mon 2017-01-02 16:24:58 UTC; 2 days ago
  Process: 1856 ExecStop=/etc/init.d/mqtt_input stop (code=exited, status=0/SUCCESS)
  Process: 1863 ExecStart=/etc/init.d/mqtt_input start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/mqtt_input.service
           └─1866 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Jan 02 16:24:58 emonpi mqtt_input[1863]: Starting Daemon for the emoncms MQTT script: mqtt_input.
Jan 02 16:24:58 emonpi systemd[1]: Started LSB: Starts phpmqtt_input agent daemon at boot time.

This is after updating

pi@emonpi(rw):~$ sudo systemctl status mqtt_input.service -n100
● mqtt_input.service - LSB: Starts phpmqtt_input agent daemon at boot time
   Loaded: loaded (/etc/init.d/mqtt_input)
   Active: active (exited) since Mon 2017-01-02 16:24:58 UTC; 2 days ago
  Process: 1856 ExecStop=/etc/init.d/mqtt_input stop (code=exited, status=0/SUCCESS)
  Process: 1863 ExecStart=/etc/init.d/mqtt_input start (code=exited, status=0/SUCCESS)

Jan 02 16:24:58 emonpi mqtt_input[1863]: Starting Daemon for the emoncms MQTT script: mqtt_input.
Jan 02 16:24:58 emonpi systemd[1]: Started LSB: Starts phpmqtt_input agent daemon at boot time.

the only noticeable changes are “active (running)” changed to “active (exited)” and the “CGroup” lines are absent. I left this running for a bit and tried again with no change, despite the MQTT inputs still arriving in emoncms as before.

This is after rebooting

pi@emonpi(ro):~$ sudo systemctl status mqtt_input.service -n100
● mqtt_input.service - LSB: Starts phpmqtt_input agent daemon at boot time
   Loaded: loaded (/etc/init.d/mqtt_input)
   Active: active (running) since Thu 2017-01-05 11:31:43 UTC; 3min 18s ago
  Process: 1859 ExecStop=/etc/init.d/mqtt_input stop (code=exited, status=0/SUCCESS)
  Process: 1866 ExecStart=/etc/init.d/mqtt_input start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/mqtt_input.service
           └─1869 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Jan 05 11:31:43 emonpi mqtt_input[1866]: Starting Daemon for the emoncms MQTT script: mqtt_input.
Jan 05 11:31:43 emonpi systemd[1]: Started LSB: Starts phpmqtt_input agent daemon at boot time.

this is exactly the same as the original “before updating” except for times and PIDs, MQTT inputs still ok but not seen in the status.
Also tried it without the “-n100” with no change and also using the old method, again the output is exactly the same.

pi@emonpi(ro):~$ sudo service mqtt_input status
● mqtt_input.service - LSB: Starts phpmqtt_input agent daemon at boot time
   Loaded: loaded (/etc/init.d/mqtt_input)
   Active: active (running) since Thu 2017-01-05 11:31:43 UTC; 13min ago
  Process: 1859 ExecStop=/etc/init.d/mqtt_input stop (code=exited, status=0/SUCCESS)
  Process: 1866 ExecStart=/etc/init.d/mqtt_input start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/mqtt_input.service
           └─1869 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Jan 05 11:31:43 emonpi mqtt_input[1866]: Starting Daemon for the emoncms MQTT script: mqtt_input.
Jan 05 11:31:43 emonpi systemd[1]: Started LSB: Starts phpmqtt_input agent daemon at boot time. 

Am I missing something?

[glyn.hudson]

@pb66

Am I missing something?

Yes, it seems after the update your still running the initd service from

/etc/init.d/mqtt_input.

If you noticed the loaded section of my status output you can see the sysemd unit file is running from

/etc/systemd/system/mqtt_input.service

The question is why did my update fail on your system. I did test on a ‘stock’ emonSD

The update script should remove the /etc/init.d/mqtt_file:

openenergymonitor/emonpi/blob/master/emoncmsupdate#L165

[pb66 (Paul)]

@glyn.hudson

The question is why did my update fail on your system.

Indeed!

My emonPi was bang upto date and totally stock aside from some edits to the emonhub.conf, and a few input processes and a couple of feeds set up in emoncms, this is a test setup not a live install.

There does not appear to be a service at that path

pi@emonpi(ro):~$ ls -la /etc/systemd/system/mqtt_input.service
ls: cannot access /etc/systemd/system/mqtt_input.service: No such file or directory
pi@emonpi(ro):~$ ls -la /etc/systemd/system/
total 52
drwxr-xr-x 12 root root 4096 Nov  4 02:16 .
drwxr-xr-x  6 root root 4096 Oct 30 01:21 ..
-rw-r--r--  1 root root 1551 Sep 18  2015 [email protected]
lrwxrwxrwx  1 root root   40 Nov 21  2015 dbus-org.freedesktop.Avahi.service -> /lib/systemd/system/avahi-daemon.service
lrwxrwxrwx  1 root root   34 Nov 21  2015 dhcpcd5 -> /lib/systemd/system/dhcpcd.service
drwxr-xr-x  2 root root 4096 Nov 21  2015 dhcpcd.service.d
drwxr-xr-x  2 root root 4096 Nov 21  2015 getty.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 [email protected]
drwxr-xr-x  2 root root 4096 Nov 21  2015 halt.target.wants
drwxr-xr-x  2 root root 4096 Feb  6  2016 multi-user.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 poweroff.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 rc-local.service.d
drwxr-xr-x  2 root root 4096 Nov 21  2015 reboot.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 sockets.target.wants
lrwxrwxrwx  1 root root   31 Nov 21  2015 sshd.service -> /lib/systemd/system/ssh.service
drwxr-xr-x  2 root root 4096 Nov 21  2015 sysinit.target.wants
lrwxrwxrwx  1 root root   35 Nov 21  2015 syslog.service -> /lib/systemd/system/rsyslog.service

here is my latest update log

I2C LCD DETECTED Ox27
Starting emonPi Update >
EUID: 1000

Thu  5 Jan 11:24:13 UTC 2017

emonSD-07Nov16

git pull /home/pi/emonpi
Updating 8a83665..929f7bb
git pull /home/pi/RFM2Pi
git pull /home/pi/emonhub
Updating 7a3b2eb..9ab0f49
Fast-forward
 README.md                                          | 27 +++----
 conf/interfacer_examples/directserial/readme.md    | 37 ++++++++++
 .../graphite/graphite.readme.md                    | 63 ----------------
 .../interfacer_examples/modbus/modbusTCP.readme.md | 83 ----------------------
 .../interfacer_examples/smilices/smilics.readme.md | 36 ----------
 .../vedirect/vedirect.readme.md                    | 55 --------------
 configuration.md                                   | 16 ++---
 7 files changed, 59 insertions(+), 258 deletions(-)
 create mode 100644 conf/interfacer_examples/directserial/readme.md
 delete mode 100644 conf/interfacer_examples/graphite/graphite.readme.md
 delete mode 100644 conf/interfacer_examples/modbus/modbusTCP.readme.md
 delete mode 100644 conf/interfacer_examples/smilices/smilics.readme.md
 delete mode 100644 conf/interfacer_examples/vedirect/vedirect.readme.md
git pull /home/pi/oem_openHab
Already up-to-date.
git pull /home/pi/usefulscripts
Already up-to-date.
git pull /home/pi/huawei-hilink-status

Start emonPi Atmega328 firmware update:

=================================
EmonPi update started
=================================

EUID: 1000

Requirement already up-to-date: paho-mqtt in /usr/local/lib/python2.7/dist-packages
Stopping OpenEnergyMonitor emonHub: emonhub has been stopped ok.
Start ATmega328 serial upload using avrdude with latest.hex
Discrete Sampling
avrdude -c arduino -p ATMEGA328P -P /dev/ttyAMA0 -b 115200 -U flash:w:/home/pi/emonpi/firmware/compiled/latest.hex
avrdude-original: Using autoreset DTR on GPIO Pin 7
Starting OpenEnergyMonitor emonHub: emonhub has been started ok.


Start emonhub update script:

=================================
EmonPi update started
=================================
Running emonhub automatic node addition script
EUID: 1000
EUID: 1000
[[5]]
Node 5 already present
[[6]]
Node 6 already present
[[7]]
Node 7 already present
[[8]]
Node 8 already present
[[9]]
Node 9 already present
[[10]]
#[[10]]
Node 10 already present
[[11]]
Node 11 already present
[[19]]
Node 19 already present
[[20]]
Node 20 already present
[[21]]
Node 21 already present
[[22]]
Node 22 already present
[[23]]
Node 23 already present
[[24]]
Node 24 already present
[[25]]
Node 25 already present
[[26]]
Node 26 already present
[[30]]
Node 30 already present

Start emoncms update:

=================================
Emoncms update started

Thu  5 Jan 11:24:40 UTC 2017

EUID: 1000
Checking cron tab for service runner entry...
service runner crontab entry already installed

git pull /var/www/emoncms
  dev-mosquitto-php
  master
* stable
  symlinked_modules
Updating db0e857..a2ac5e3
Fast-forward
 Modules/feed/Views/feedlist_view.php |  2 +-
 Modules/user/profile/profile.php     |  2 +-
 Modules/user/user.js                 |  6 ++---
 Theme/basic/theme.php                |  2 +-
 docs/RaspberryPi/MQTT.md             | 24 +++++++++++++++-----
 index.php                            |  2 +-
 scripts/mqtt_input.service           | 43 ++++++++++++++++++++++++++++++++++++
 scripts/phpmqtt_input.php            |  2 ++
 8 files changed, 71 insertions(+), 12 deletions(-)
 create mode 100644 scripts/mqtt_input.service


git pull /var/www/emoncms/Modules/app
* 9.0
Already up-to-date.

git pull /var/www/emoncms/Modules/config
* 9.0
Already up-to-date.

git pull /var/www/emoncms/Modules/wifi
* 9.0
Updating 8598aec..c2fc12e
Fast-forward
 view.html | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)
git pull /var/www/emoncms/Modules/dashboard
  environ-master
* master
Already up-to-date.

git pull /var/www/emoncms/Modules/graph
* master
Already up-to-date.

git pull /home/pi/postprocess
Your branch is up-to-date with 'remotes/origin/emonpi'.
Already up-to-date.
git pull /home/pi/backup
* master
Already up-to-date.


Update Emoncms database
[]

Restarting Services...
Restarting OpenEnergyMonitor emonHub: emonhub has been restarted ok.
Log is turned off
Restarting feedwriter

Restarting openhab (via systemctl): openhab.service.

Starting Daemon for the emoncms MQTT script: Restarting Daemon for the emoncms MQTT script: mqtt_input.

set log rotate config owner to root
Restarting Services...


Starting emonPi LCD service..

Filesystem is locked - Read Only access
type ' rpi-rw ' to unlock
Thu  5 Jan 11:25:34 UTC 2017


...................
emonPi update done

it shows your latest commits to emoncms being pulled in and the MQTT being restarted but not a “replacing initd mqtt_input with systemd mqtt input” message.

/etc/init.d/mqtt_input is there

pi@emonpi(ro):~$ ls -la /etc/init.d/mqtt_input
lrwxrwxrwx 1 root root 35 Jan 27  2016 /etc/init.d/mqtt_input -> /var/www/emoncms/scripts/mqtt_input

and a quick test proves the test doesn’t trip up on the symlink

pi@emonpi(ro):~$ if [ -f /etc/init.d/mqtt_input ]; then echo "true"; fi
true

So off hand I have no idea why your script didn’t succeed, at first glance it appears it didn’t run?

edit - The service wasn’t copied over either

pi@emonpi(ro):~$ ls -la /var/www/emoncms/scripts/mqtt_input.service
-rw-r--r-- 1 pi pi 1063 Jan  5 11:24 /var/www/emoncms/scripts/mqtt_input.service
pi@emonpi(ro):~$ ls -la /etc/systemd/system/mqtt_input.service
ls: cannot access /etc/systemd/system/mqtt_input.service: No such file or directory

[glyn.hudson]

Interesting, thanks a lot for helping to debug this.

What happens if you run update again? The emoncmsupdate script should have updated before running so the change should have been pulled in. Let’s see if it runs the second time round.

[pb66 (Paul)]

Still no joy!

I2C LCD DETECTED Ox27
Starting emonPi Update >
EUID: 1000

Thu  5 Jan 12:44:54 UTC 2017

emonSD-07Nov16

git pull /home/pi/emonpi
Updating 8a83665..929f7bb
git pull /home/pi/RFM2Pi
git pull /home/pi/emonhub
Already up-to-date.
git pull /home/pi/oem_openHab
Already up-to-date.
git pull /home/pi/usefulscripts
Already up-to-date.
git pull /home/pi/huawei-hilink-status

Start emonPi Atmega328 firmware update:

=================================
EmonPi update started
=================================

EUID: 1000

Requirement already up-to-date: paho-mqtt in /usr/local/lib/python2.7/dist-packages
Stopping OpenEnergyMonitor emonHub: emonhub has been stopped ok.
Start ATmega328 serial upload using avrdude with latest.hex
Discrete Sampling
avrdude -c arduino -p ATMEGA328P -P /dev/ttyAMA0 -b 115200 -U flash:w:/home/pi/emonpi/firmware/compiled/latest.hex
avrdude-original: Using autoreset DTR on GPIO Pin 7
Starting OpenEnergyMonitor emonHub: emonhub has been started ok.


Start emonhub update script:

=================================
EmonPi update started
=================================
Running emonhub automatic node addition script
EUID: 1000
EUID: 1000
[[5]]
Node 5 already present
[[6]]
Node 6 already present
[[7]]
Node 7 already present
[[8]]
Node 8 already present
[[9]]
Node 9 already present
[[10]]
#[[10]]
Node 10 already present
[[11]]
Node 11 already present
[[19]]
Node 19 already present
[[20]]
Node 20 already present
[[21]]
Node 21 already present
[[22]]
Node 22 already present
[[23]]
Node 23 already present
[[24]]
Node 24 already present
[[25]]
Node 25 already present
[[26]]
Node 26 already present
[[30]]
Node 30 already present

Start emoncms update:

=================================
Emoncms update started

Thu  5 Jan 12:45:19 UTC 2017

EUID: 1000
Checking cron tab for service runner entry...
service runner crontab entry already installed

git pull /var/www/emoncms
  dev-mosquitto-php
  master
* stable
  symlinked_modules
Already up-to-date.


git pull /var/www/emoncms/Modules/app
* 9.0
Already up-to-date.

git pull /var/www/emoncms/Modules/config
* 9.0
Already up-to-date.

git pull /var/www/emoncms/Modules/wifi
* 9.0
Already up-to-date.
git pull /var/www/emoncms/Modules/dashboard
  environ-master
* master
Already up-to-date.

git pull /var/www/emoncms/Modules/graph
* master
Already up-to-date.

git pull /home/pi/postprocess
Your branch is up-to-date with 'remotes/origin/emonpi'.
Already up-to-date.
git pull /home/pi/backup
* master
Already up-to-date.


Update Emoncms database
[]

Restarting Services...
Restarting OpenEnergyMonitor emonHub: emonhub has been restarted ok.
Log is turned off
Restarting feedwriter

Restarting openhab (via systemctl): openhab.service.

Starting Daemon for the emoncms MQTT script: Restarting Daemon for the emoncms MQTT script: mqtt_input.

set log rotate config owner to root
Restarting Services...


Starting emonPi LCD service..

Filesystem is locked - Read Only access
type ' rpi-rw ' to unlock
Thu  5 Jan 12:46:10 UTC 2017


...................
emonPi update done

There is even the 2 additional lines “echoed” before and after but no “replacing initd mqtt_input with systemd mqtt input”, it does seem that whole section is being skipped.

Already up-to-date.


Update Emoncms database

[pb66 (Paul)]

Okay, sussed it! My fault!

There was another “edit” I had made and overlooked.

Lastest emonSD image updates on every reboot!

ring any bells?

My editing of the switch state was blocking the emonpi repo and therefore the emoncmsupdate script from being updated.

After forcing a pull and then re-running the update we are in business.

Already up-to-date.

replacing initd mqtt_input with systemd mqtt input
Stopping Daemon for the emoncms MQTT script: mqtt_input.

Update Emoncms database

and I can see the full log at last

pi@emonpi(rw):emonpi$ sudo systemctl status mqtt_input.service -n100
● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: loaded (/etc/systemd/system/mqtt_input.service; enabled)
   Active: active (running) since Thu 2017-01-05 12:58:53 UTC; 11s ago
 Main PID: 21104 (php)
   CGroup: /system.slice/mqtt_input.service
           └─21104 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Jan 05 12:58:53 emonpi systemd[1]: Started Emoncms MQTT Input Script.
Jan 05 12:58:55 emonpi php[21104]: Subscribing to: emon/#
Jan 05 12:58:55 emonpi php[21104]: Not connected, retrying connection
Jan 05 12:58:55 emonpi php[21104]: Connected to MQTT server with code 0 and message Connection Accepted.
Jan 05 12:58:55 emonpi php[21104]: Subscribed to topic: emon/#
Jan 05 12:58:57 emonpi php[21104]: emon/gasMon/pulsecount 18.39
Jan 05 12:58:57 emonpi php[21104]: emon/gasMon/uptime 249230000
Jan 05 12:58:57 emonpi php[21104]: emon/gasMon/rssi -68
Jan 05 12:58:58 emonpi php[21104]: emon/emontx/Vrms 240.5
Jan 05 12:58:59 emonpi php[21104]: emon/emontx/power1 -8
Jan 05 12:58:59 emonpi php[21104]: emon/emontx/power2 1696
Jan 05 12:58:59 emonpi php[21104]: emon/emontx/power3 6
Jan 05 12:58:59 emonpi php[21104]: emon/emontx/temp 5.81
Jan 05 12:58:59 emonpi php[21104]: emon/emontx/rssi -73
Jan 05 12:58:59 emonpi php[21104]: emon/emonpi/1 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/2 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/3 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/4 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/5 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/6 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/7 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/8 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/9 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/10 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/11 0
Jan 05 12:59:00 emonpi php[21104]: emon/emonpi/rssi 0
Jan 05 12:59:02 emonpi php[21104]: emon/gasMon/pulsecount 18.39
Jan 05 12:59:02 emonpi php[21104]: emon/gasMon/uptime 249235000
Jan 05 12:59:02 emonpi php[21104]: emon/gasMon/rssi -68
Jan 05 12:59:03 emonpi php[21104]: emon/emontx/Vrms 240.36
Jan 05 12:59:04 emonpi php[21104]: emon/emontx/power1 -1
Jan 05 12:59:04 emonpi php[21104]: emon/emontx/power2 1683
Jan 05 12:59:04 emonpi php[21104]: emon/emontx/power3 7
Jan 05 12:59:04 emonpi php[21104]: emon/emontx/temp 5.81
Jan 05 12:59:04 emonpi php[21104]: emon/emontx/rssi -72
Jan 05 12:59:04 emonpi php[21104]: emon/emonpi/1 0
Jan 05 12:59:04 emonpi php[21104]: emon/emonpi/2 0
Jan 05 12:59:04 emonpi php[21104]: emon/emonpi/3 0
Jan 05 12:59:04 emonpi php[21104]: emon/emonpi/4 0
Jan 05 12:59:05 emonpi php[21104]: emon/emonpi/5 0
Jan 05 12:59:05 emonpi php[21104]: emon/emonpi/6 0

edit - Although I am still intrigued by the “rfm69pi” reference in your logs, are you running a custom software or is that the hostname?

edit2 - okay, answered my own question, it is the hostname, I just temporarily edited my emonpi’s hostname to test (just added an extra “i”)

pi@emonpii(ro):~$ sudo systemctl status mqtt_input -n100
● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: loaded (/etc/systemd/system/mqtt_input.service; enabled)
   Active: active (running) since Thu 2017-01-05 13:29:45 UTC; 41s ago
 Main PID: 1825 (php)
   CGroup: /system.slice/mqtt_input.service
           └─1825 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Jan 05 13:30:12 emonpii php[1825]: emon/emonpi/11 0
Jan 05 13:30:12 emonpii php[1825]: emon/emonpi/rssi 0

[pb66 (Paul)]

So this has been running a while now on the new service and the log is shown when using systenctl status, however. the original log file is no longer being used

pi@emonpi(ro):~$ ls -la /var/log
total 6076
drwxr-xr-x 10 root      root          520 Jan  5 15:17 .
drwxr-xr-x 12 root      root         4096 Nov  7 16:52 ..
drwxr-xr-x  2 root      adm            60 Jan  5 13:34 apache2
-rw-r-----  1 root      adm         56187 Jan  5 17:06 auth.log
-rw-r--r--  1 root      root         7630 Jan  5 13:34 boot.log
-rw-------  1 root      utmp            0 Jan  5 13:34 btmp
-rw-r-----  1 root      adm       1532972 Jan  5 17:06 daemon.log
-rw-r-----  1 root      adm       1453907 Jan  5 15:17 daemon.log.1
-rw-r-----  1 root      adm          1014 Jan  5 13:34 debug
-rw-rw-rw-  1 root      root          810 Jan  5 13:35 emoncms.log
drwxr-xr-x  2 emonhub   root          100 Jan  5 16:17 emonhub
drwxr-xr-x  2 pi        root           60 Jan  5 13:34 emonpilcd
-rw-r-----  1 root      adm         37914 Jan  5 16:58 kern.log
drwxr-xr-x  2 pi        pi             80 Jan  5 16:17 logrotate
-rw-r-----  1 root      adm         36821 Jan  5 16:58 messages
drwxr-xr-x  2 mosquitto mosquitto      60 Jan  5 13:34 mosquitto
-rw-rw-rw-  1 root      root            0 Jan  5 13:34 mqtt_input.log
drwxr-xr-x  2 mysql     adm            60 Jan  5 13:34 mysql
-rw-rw-rw-  1 root      root            0 Jan  5 13:34 mysql.log
drwxr-xr-x  2 openhab   openhab        80 Jan  5 13:35 openhab
drwxr-xr-x  2 redis     redis          60 Jan  5 13:34 redis
-rw-rw-rw-  1 root      root            0 Jan  5 13:34 service-runner.log
-rw-r-----  1 root      adm       1554503 Jan  5 17:06 syslog
-rw-r-----  1 root      adm       1500681 Jan  5 15:17 syslog.1
-rw-r-----  1 root      adm         11542 Jan  5 16:58 ufw.log
-rw-rw-r--  1 root      utmp         1920 Jan  5 13:36 wtmp

and instead all the mqtt_input log messages are going to /var/log/daemon.log

pi@emonpi(ro):~$ tail -f  /var/log/daemon.log
Jan  5 17:08:00 emonpi php[1832]: emon/emonpi/6 0
Jan  5 17:08:00 emonpi php[1832]: emon/emonpi/7 0
Jan  5 17:08:00 emonpi php[1832]: emon/emonpi/8 0
Jan  5 17:08:00 emonpi php[1832]: emon/emonpi/9 0
Jan  5 17:08:00 emonpi php[1832]: emon/emonpi/10 0
Jan  5 17:08:00 emonpi php[1832]: emon/emonpi/11 0
Jan  5 17:08:00 emonpi php[1832]: emon/emonpi/rssi 0

which I cannot imagine can be correct, or is it?

Surely that means that all logs of all daemons are lumped together in one file that is rapidly growing and being rotated. All the actual daemon log messages are getting buried and any debugging of any one service can now only be done via systemctl status so the messages get sorted for us, otherwise we have to trawl through pages and pages (or even the rotated archives) to find anything.

Surely there’s an error here? otherwise this is a big step backwards for debugging!

[ian]

Hi Glyn

I have to to keep up to date using git as my mqtt setup is on a different server. When this change is finalised would you indicate the steps needed to implement the change on a system like mine.

Regards

Ian

[pb66 (Paul)]

So in around 7hrs I have 3 deamon.log files

pi@emonpi(ro):~$ ls -la /var/log/
total 8072
drwxr-xr-x 10 root      root          560 Jan  5 19:17 .
drwxr-xr-x 12 root      root         4096 Nov  7 16:52 ..
drwxr-xr-x  2 root      adm            60 Jan  5 13:34 apache2
-rw-r-----  1 root      adm        106570 Jan  5 20:06 auth.log
-rw-r--r--  1 root      root         7630 Jan  5 13:34 boot.log
-rw-------  1 root      utmp            0 Jan  5 13:34 btmp
-rw-r-----  1 root      adm        665078 Jan  5 20:06 daemon.log
-rw-r-----  1 root      adm       1625546 Jan  5 19:17 daemon.log.1
-rw-r-----  1 root      adm       1680601 Jan  5 17:17 daemon.log.2
-rw-r-----  1 root      adm          1014 Jan  5 13:34 debug
-rw-rw-rw-  1 root      root          810 Jan  5 13:35 emoncms.log
drwxr-xr-x  2 emonhub   root          100 Jan  5 19:17 emonhub
drwxr-xr-x  2 pi        root           60 Jan  5 13:34 emonpilcd
-rw-r-----  1 root      adm         47222 Jan  5 20:06 kern.log
drwxr-xr-x  2 pi        pi             80 Jan  5 19:17 logrotate
-rw-r-----  1 root      adm         46129 Jan  5 20:06 messages
drwxr-xr-x  2 mosquitto mosquitto      60 Jan  5 13:34 mosquitto
-rw-rw-rw-  1 root      root            0 Jan  5 13:34 mqtt_input.log
drwxr-xr-x  2 mysql     adm            60 Jan  5 13:34 mysql
-rw-rw-rw-  1 root      root            0 Jan  5 13:34 mysql.log
drwxr-xr-x  2 openhab   openhab        80 Jan  5 13:35 openhab
drwxr-xr-x  2 redis     redis          60 Jan  5 13:34 redis
-rw-rw-rw-  1 root      root            0 Jan  5 13:34 service-runner.log
-rw-r-----  1 root      adm        674501 Jan  5 20:06 syslog
-rw-r-----  1 root      adm       1649195 Jan  5 19:17 syslog.1
-rw-r-----  1 root      adm       1704016 Jan  5 17:17 syslog.2
-rw-r-----  1 root      adm         20298 Jan  5 20:06 ufw.log
-rw-rw-r--  1 root      utmp         3456 Jan  5 20:03 wtmp

and on inspecting the current file I can find only a handful of non-mqtt lines among the pages and pages of mqtt.

pi@emonpi(ro):~$ less /var/log/daemon.log
Jan  5 19:17:02 emonpi systemd[1]: Stopping LSB: Save the current clock & ntp drift on read-only filesystem...
Jan  5 19:17:02 emonpi ntp-backup[4426]: Running ntp-backup to save current clock data.
Jan  5 19:17:02 emonpi systemd[1]: Starting LSB: Save the current clock & ntp drift on read-only filesystem...
Jan  5 19:17:02 emonpi ntp-backup[4441]: Starting ntp-backup.
Jan  5 19:17:02 emonpi systemd[1]: Started LSB: Save the current clock & ntp drift on read-only filesystem.
Jan  5 19:17:02 emonpi php[1832]: emon/gasMon/pulsecount 18.77
Jan  5 19:17:02 emonpi php[1832]: emon/gasMon/uptime 271915000
Jan  5 19:17:02 emonpi php[1832]: emon/gasMon/rssi -63
Jan  5 19:17:03 emonpi php[1832]: emon/emontx/Vrms 238.74
Jan  5 19:17:03 emonpi php[1832]: emon/emontx/power1 635

Jan  5 19:34:42 emonpi php[1832]: emon/gasMon/rssi -63
Jan  5 19:34:43 emonpi ntpd[1014]: frequency file /var/lib/ntp/ntp.drift.TEMP: Read-only file system
Jan  5 19:34:47 emonpi php[1832]: emon/emonpi/1 0
Jan  5 19:34:47 emonpi php[1832]: emon/emonpi/2 0

Jan  5 19:35:13 emonpi php[1832]: emon/gasMon/uptime 273005000
Jan  5 19:35:13 emonpi php[1832]: emon/gasMon/rssi -63
Jan  5 19:35:13 emonpi Node-RED[473]: 5 Jan 19:35:13 - [error] [wunderground:e6315c7a.2f9cf] [object Object]
Jan  5 19:35:17 emonpi php[1832]: emon/emonpi/1 0
Jan  5 19:35:17 emonpi php[1832]: emon/emonpi/2 0

Jan  5 20:05:12 emonpi php[1832]: emon/gasMon/uptime 274805000
Jan  5 20:05:12 emonpi php[1832]: emon/gasMon/rssi -64
Jan  5 20:05:13 emonpi Node-RED[473]: 5 Jan 20:05:13 - [error] [wunderground:e6315c7a.2f9cf] [object Object]
Jan  5 20:05:14 emonpi php[1832]: emon/emonpi/1 0
Jan  5 20:05:14 emonpi php[1832]: emon/emonpi/2 0

I don’t think mixing low priority/high frequency messages in the same log file as low frequency warnings from multiple sources is a good idea, I think the issue is that the mqtt_input daemon should not be producing so many log entries, but to remove those log messages is counter-productive and not an improvement to the previous method as these are being rotated out so fast that any other service’s messages will be lost.

@glyn.hudson Is there a way to specify a service specific logfile rather than funneling all messages to the one daemon.log?

If not I’d be inclined to revert to the old system until the mqtt_input is stable enough to warrant reducing the logged messages.

There are by far, more services still in the old format than the new, even on the emonSD image the old out number the new by over 4:1

pi@emonpi(ro):~$ ls -la /etc/systemd/system
total 56
drwxr-xr-x 12 root root 4096 Jan  5 12:58 .
drwxr-xr-x  6 root root 4096 Oct 30 01:21 ..
-rw-r--r--  1 root root 1551 Sep 18  2015 [email protected]
lrwxrwxrwx  1 root root   40 Nov 21  2015 dbus-org.freedesktop.Avahi.service -> /lib/systemd/system/avahi-daemon.service
lrwxrwxrwx  1 root root   34 Nov 21  2015 dhcpcd5 -> /lib/systemd/system/dhcpcd.service
drwxr-xr-x  2 root root 4096 Nov 21  2015 dhcpcd.service.d
drwxr-xr-x  2 root root 4096 Nov 21  2015 getty.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 [email protected]
drwxr-xr-x  2 root root 4096 Nov 21  2015 halt.target.wants
-rw-r--r--  1 root root 1063 Jan  5 12:58 mqtt_input.service
drwxr-xr-x  2 root root 4096 Jan  5 12:58 multi-user.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 poweroff.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 rc-local.service.d
drwxr-xr-x  2 root root 4096 Nov 21  2015 reboot.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 sockets.target.wants
lrwxrwxrwx  1 root root   31 Nov 21  2015 sshd.service -> /lib/systemd/system/ssh.service
drwxr-xr-x  2 root root 4096 Nov 21  2015 sysinit.target.wants
lrwxrwxrwx  1 root root   35 Nov 21  2015 syslog.service -> /lib/systemd/system/rsyslog.service

pi@emonpi(ro):~$ ls -la /etc/systemd/system
total 56
drwxr-xr-x 12 root root 4096 Jan  5 12:58 .
drwxr-xr-x  6 root root 4096 Oct 30 01:21 ..
-rw-r--r--  1 root root 1551 Sep 18  2015 [email protected]
lrwxrwxrwx  1 root root   40 Nov 21  2015 dbus-org.freedesktop.Avahi.service -> /lib/systemd/system/avahi-daemon.service
lrwxrwxrwx  1 root root   34 Nov 21  2015 dhcpcd5 -> /lib/systemd/system/dhcpcd.service
drwxr-xr-x  2 root root 4096 Nov 21  2015 dhcpcd.service.d
drwxr-xr-x  2 root root 4096 Nov 21  2015 getty.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 [email protected]
drwxr-xr-x  2 root root 4096 Nov 21  2015 halt.target.wants
-rw-r--r--  1 root root 1063 Jan  5 12:58 mqtt_input.service
drwxr-xr-x  2 root root 4096 Jan  5 12:58 multi-user.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 poweroff.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 rc-local.service.d
drwxr-xr-x  2 root root 4096 Nov 21  2015 reboot.target.wants
drwxr-xr-x  2 root root 4096 Nov 21  2015 sockets.target.wants
lrwxrwxrwx  1 root root   31 Nov 21  2015 sshd.service -> /lib/systemd/system/ssh.service
drwxr-xr-x  2 root root 4096 Nov 21  2015 sysinit.target.wants
lrwxrwxrwx  1 root root   35 Nov 21  2015 syslog.service -> /lib/systemd/system/rsyslog.service

Who knows, there maybe good reason other softwares are not rushing to take the plunge just yet.

[glyn.hudson]

Awesome! Nice work.

@pb66

Although I am still intrigued by the “rfm69pi” reference in your logs, are you running a custom software or is that the hostname?

Ah yes, it’s the hostname. I have an emonPi and an emonBase with an rfm69pi on the network in the office for testing. I changed the emonSD hostname to rfm12pi to differentiate from emonpi. Sorry for the confusion.

@pb66

which I cannot imagine can be correct, or is it?

This is correct. Or at least what I intended. I like viewing the logs via the status command since there are fewer points of failure (i.e don’t need to create the log file in /var/log) and less to remember since no need to remember where the logfile is stored. If would be possible to pipe the output of the script to a logfile or our choice by adding a >> logfile_of_our_choice in the systemd unit file.

I believe the sysemd logs are also more efficient since they are stored as binary rather than text: Linux Logging with Systemd - The Ultimate Guide To Logging

Anyone else with experience with systemd like to give some input? @Andy_Taylor @Bill.Thomson

[Bill.Thomson]

Hi Glyn,

I’d be happy to help, but I don’t run any of the systemd based OSes.

[jimmy]

I’m not fully familiar with systemd, but I read through log files daily for work. Having the ability to grep, awk and other text manipulation commands is vital for us for debugging, I have found the same for emoncms stuff too so think we need to keep to being able to use those tools to find things.

If systemd logs allow this then personally I’m ok with change as I’m used to reading /var/log/messages on centos

[Andy_Taylor]

Argh Systemd - where to start with that…

It’s supposed to be the fix-all solution to everything, and to some extent it is, but we’re at the point where there are some stupid dependancies relating to desktop type services that now rely on systemd, crazy IMO.

As for logging - there are usually two way to specify the log, in the unit file or in the config for the application / process.
Looking at the old init.d init script - you were setting the log file there previously;

NAME=mqtt_input
DESC="Daemon for the emoncms MQTT script"
PIDFILE="/var/run/${NAME}.pid"
LOGFILE="/var/log/${NAME}.log"

DAEMON="/usr/bin/php"
DAEMON_OPTS="/var/www/emoncms/scripts/phpmqtt_input.php"

Since this is the case, we should be doing the same in the systemd unit file, and this is where you run into problems.

Using the init.d - you were actually redirecting the output from the application to STDOUT to a log file, you can replicate that in systemd - kinda…

I have modified my version of the unit file as follows;

# Systemd unit file for mqtt input script

# INSTALL:
# sudo cp /var/www/emoncms/scripts/mqtt_input.service /etc/systemd/system/mqtt_input.service

# RUN AT STARTUP
# sudo systemctl daemon-reload
# sudo systemctl enable mqtt_service

# START / STOP With:
# sudo systemctl start mqtt_input
# sudo systemctl stop mqtt_input    

# VIEW STATUS / LOG
# sudo systemctl status mqtt_input -n50
# where -nX is the number of log lines to view 

###
#
#  All Emoncms code is released under the GNU Affero General Public License.
#  See COPYRIGHT.txt and LICENSE.txt.
#
#  ---------------------------------------------------------------------
#  Emoncms - open source energy visualisation
#  Part of the OpenEnergyMonitor project:
#  http://openenergymonitor.org
###

[Unit]
Description=Emoncms MQTT Input Script
After=mosquitto.service mysql.service redis.service

[Service]
Type=forking
ExecStart=/bin/sh -c '/usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php 2>&1 > /var/log/mqtt_input.log &'

# Restart script if stopped
#Restart=always
Restart=on-failure
# Wait 60s before restart
RestartSec=60

[Install]
WantedBy=multi-user.target

One other note - running the update failed on my Pi - the init.d script was removed, but the systemd unit file was not added to /etc/systemd/system - check that you have the file system writable at that point in the script…

Also because you are modifying systemd - make sure you call “systemctl daemon-reload” after adding the file, and then make it active with “systemctl enable mqtt_input”.

I have not checked your update script yet to see where these errors come from yet…

[glyn.hudson]

@jimmy

Having the ability to grep, awk and other text manipulation commands is vital for us for debugging

Yup, totally agree. The systemd logs can be outputted as text using journalctl then the usual text manipulation tools can be applied.

sudo journalctl -f -u mqtt_input -o cat | grep emontx

I’ve just updated the unit file to tag the systemd log entries with mqtt_input, this makes them easier to search.

update mqtt_service systemd unit file to tag logs and give other logging options

[Andy_Taylor]

I should point out that all my changes do - is revert to using the /var/log/mqtt_input.log rather than using /var/log/daemon.log as systemd will do by default.

You / We still need to work out why when I updated the init.d script was removed but the systemd script was not added.

[pb66 (Paul)]

I tried sudo journalctl -f -u mqtt_input -o cat | grep emontx ( and some similar searches) before changing anything and found it worked ok prior to the tag being added, also there is no time and date printed can that be set in command line?

Since updating emonpi I am unable to restart the service and have an error message

pi@emonpi(rw):~$ sudo systemctl restart mqtt_input.service
Failed to restart mqtt_input.service: Unit mqtt_input.service failed to load: Bad message. See system logs and 'systemctl status mqtt_input.service' for details.

pi@emonpi(rw):~$ systemctl status mqtt_input.service
● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: error (Reason: Bad message)
   Active: active (running) since Thu 2017-01-05 13:34:59 UTC; 22h ago
     Docs: https://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
 Main PID: 1832 (php)
   CGroup: /system.slice/mqtt_input.service
           └─1832 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

I have had a look and see no obvious (to me) reason, the update was done after the typo corrections to the comment lines.

Since the above search worked prior to the update and yet the “Docs” url has been added to the status output I’m unclear if the new unit is in service or not, but the daemon.log has not changed, I expected to see the tag there or is the daemon.log an additional log to a seperate systemd internal log? if it is, then great we can redirect what is going to the daemon.log to the mqtt_input.log and the systemd/systemctl/journalctl internal log will remain intact perhaps?

I notice @glyn.hudson that you have also added a commented out option to log to mqtt_input.log, but won’t that get overwritten at every emonpi update?

[glyn.hudson]

@Andy_Taylor

I should point out that all my changes do - is revert to using the /var/log/mqtt_input.log rather than using /var/log/daemon.log as systemd will do by default.

What changes are these? Sorry if I missed something. As I’m typing this, your order has just been shipped

@pb66

Since updating emonpi I am unable to restart the service and have an error message

Woops, my fault. I noticed a typo in the unit file which a corrected a few seconds later on the master branch. I created a PR to merge into stable but forgot to merge it…until now. Please try and update again

comment typo

[Andy_Taylor]

The changes are the ones a few posts up where I pasted a copy of the systemd unit file I modified to make mutt_input log to the correct file again.

[pb66 (Paul)]

@glyn.hudson thanks the correction fixed the unit issue, unfortunately your alternative log option doesn’t seem to work, even after reloading and restarting the unit the logs still go to the daemon.log, although I can now see the “mqtt_inpu” tag in place of the “php” tag.

pi@emonpi(rw):~$ tail  /var/log/daemon.log
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/3 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/4 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/5 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/6 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/7 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/8 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/9 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/10 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/11 0
Jan  6 13:06:35 emonpi mqtt_input[22099]: emon/emonpi/rssi 0

I tried @Andy_Taylor’s code

Type=forking
ExecStart=/bin/sh -c '/usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php 2>&1 > /var/log/mqtt_input.log &'

and that does send the logs to mqtt_input,log or more importantly, does not send them to ‘daemon.log’, (thanks Andy) however there is no time and date, I have not yet checked to see if this is due to the actual script not attaching it or if it is getting removed en-route.

pi@emonpi(rw):~$ tail  /var/log/mqtt_input.log
emon/emonpi/9 0
emon/emonpi/10 0
emon/emonpi/11 0
emon/emonpi/rssi 0
emon/emontx/Vrms 238.13
emon/emontx/power1 121
emon/emontx/power2 166
emon/emontx/power3 3
emon/emontx/temp 5.25
emon/emontx/rssi -69

For now I have also blindly carried over the “Type=forking” without really knowing which type is required.