Mqtt_input script run as systemd instead of initd

pb66 · 2017-01-05T12:05:30.992Z

@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 · 2017-01-05T12:15:57.926Z

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:

github.com

openenergymonitor/emonpi/blob/master/emoncmsupdate#L165


      
          #!/bin/bash
          # REDIRECT FOR UPDATE TO NEW UPDATE PATH LOCATIONS
          # KEEP THIS FILE HERE FOR ALL UPDATED FROM OCT17 and OCT18 IMAGES
          DIR="$( cd "$( dirname "${BASH_SOURCE[0]}" )" >/dev/null 2>&1 && pwd )"
          usrdir=${DIR/\/emonpi/}
          $usrdir/emonpi/service-runner-update.sh all custom

pb66 · 2017-01-05T12:37:21.900Z

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 autologin@.service
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 getty@tty1.service.d
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 · 2017-01-05T12:43:14.036Z

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 · 2017-01-05T12:53:13.971Z

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 · 2017-01-05T13:08:25.582Z

Okay, sussed it! My fault!

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

github.com/openenergymonitor/emonpi

Lastest emonSD image updates on every reboot!

opened 01:05PM - 26 Dec 16 UTC

closed 07:35PM - 27 Dec 16 UTC

pb66

Latest build and fully updated. My emonPi updates on every reboot, it seems t…he "firstbootupdate" script is initializing an update even when it is not required. When I looked into it and tested the separate "or" parts of the if statement in this line https://github.com/openenergymonitor/emonpi/blob/master/firstbootupdate#L13 I found the log file is non-zero size as expected since it is not the first boot, but the $button value is 0 at rest and 1 when pressed, so the button action actually works as a "update bypass" if held while rebooting not a "forced update". By editing this line to if [ ! -s /home/pi/data/emonpiupdate.log ] || [ $button == 1 ]; then it works as expected. I can see there was a [recent change](https://github.com/openenergymonitor/emonpi/commit/44f5aa70f050cdb41e36110ab4e361653e9284af) to this code that inverted the action based on the $button value, was this intended? has the switch been physically changed in production?

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 · 2017-01-05T17:17:47.549Z

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 · 2017-01-05T19:43:14.595Z

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 · 2017-01-05T20:52:22.415Z

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 autologin@.service
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 getty@tty1.service.d
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 autologin@.service
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 getty@tty1.service.d
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 · 2017-01-05T20:57:08.138Z

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 · 2017-01-05T21:01:27.418Z

Hi Glyn,

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

jimmy · 2017-01-06T08:12:47.332Z

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 · 2017-01-06T11:03:18.964Z

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 · 2017-01-06T11:33:25.515Z

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.

github.com/emoncms/emoncms

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

Commit by

glynhudson in update mqtt_service systemd unit file to tag logs and give other logg…

emoncms:stable ← emoncms:master

Andy_Taylor · 2017-01-06T11:52:25.679Z

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 · 2017-01-06T12:39:03.403Z

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 · 2017-01-06T12:58:57.660Z

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

github.com/emoncms/emoncms

comment typo

emoncms:stable ← emoncms:master

opened 11:40AM - 06 Jan 17 UTC

glynhudson

+1 -1

Andy_Taylor · 2017-01-06T13:10:29.382Z

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 · 2017-01-06T13:28:40.318Z

@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.

glyn.hudson · 2017-01-06T13:38:47.254Z

Apologies, I missed your post above. Got it now, thanks.

Is possible I would like to move to using the systemd journal log, this seems to be the preferred way to go ‘all-in’ with systemd. This is how nodeRED runs. I have been looking at the nodeRED unit file as an example.

However, it would be good to give the option for users to log to mqtt_input.log if they prefer as a commented out option in the unit file which can easily be enabled.

pb66:

unfortunately your alternative log option doesn’t seem to work,

I have updated the unit file to use @Andy_Taylor logging code as an alternative commented out option. I don’t quite understand what is meant by forking. I will leaf type=forking commented out.

from: [Solved] systemd - To fork or not to fork when writing services / Applications & Desktop Environments / Arch Linux Forums

If you have a choice then use Type=simple for your systemd services. It is simpler and systemd will take care or proper process deamonizing, restarts and shutdowns.

Type=forking is for historical services that cannot be run in foreground. In this case process itself will take care of its deamonizing, but systemd should know the child pid somehow so you need to provide PIDFile= option as well.

I choose type=idle to ensure the script starts after all other services have started. Here is a full explanation of the different service types:

https://wiki.archlinux.org/index.php/Systemd#Service_types

I will keep these changes in the master branch until they have been more tested:

github.com

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


      
          
          [Unit]
          Description=Emoncms MQTT Input Script
          After=mosquitto.service mysql.service redis-server.service
          Documentation=https://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
          
          [Service]
          Type=idle
          ExecStart=/usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php
          
          # Uncomment instead of above to use standard log file, else use systemd log
          # 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
          # Wait 60s before restart
          RestartSec=60
          
          # Tag things in the log
          # View with: sudo journalctl -f -u mqtt_input -o cat