Extra service-runner commands in crontab - Part II

Jon · 2016-05-09T22:39:54.227Z

Continuing the discussion from Extra service-runner commands in crontab:

@glyn.hudson - sorry - I found more weirdness. This is in sudo crontab -l:

Screen Shot 2016-05-09 at 5.30.27 PM_thumb.png557×584 207 KB

A few of my logs are filling up fast and I was digging around. One of the logs is auth.log:

Screen Shot 2016-05-09 at 5.35.10 PM_thumb.png680×524 325 KB

So is the line:
* * * * * /home/pi/emonpi/service-runner >> /var/log/service-runner.log 2>&1 suppose to be in the root crontab sudo crontab -l or in the user pi crontab crontab -l ?

glyn.hudson · 2016-05-10T00:18:42.560Z

Ah well spotted, I had forgotten that the update script runs as root, therefore crontab -l in the the update script is actually listing the root crontab > sudo crontab -l. This explains a lot…

I will get onto this tomorrow.

I’ve also noticed the log file issue this evening, this is a top priority to sort out. I thought we had nailed it with @Andy_Taylor 's help. Obviously not quite there yet

Andy_Taylor · 2016-05-10T09:03:57.387Z

What log is filling up now? auth.log? (I’m not getting affected by this because my Pi is currently running on batteries - so its rebooted every 12h when I change the battery pack…

Assuming it is auth.log filling up, I’ll do some digging on that in a moment, but it appears it could be due to the bizarre duplication in both the “pi” user’s crontab and the “root” user’s crontab; both of these have the same “* * * * * /home/pi/emonpi/service-runner >> /var/log/service-runner.log 2>&1” entry more than once.

@glyn.hudson point me at the update script and I’ll take a look if that helps…

glyn.hudson · 2016-05-10T12:22:28.832Z

It was /var/log/apache2/error.log that contained 27Mb of ‘divide by zero’ errors.

Since applying your PR the errors have stopped, however it would be good to figure out why the log was not rotated.

I’ve also noticed that even the log files that seem to be properly rotated /var/log/emonhub/emonhub.log are greater than 1Mb in size which should be the limit set by logrotate.conf. e.g.

pi@emonpi:~/emonpi $ du -ha /var/log/emonhub/
340K    /var/log/emonhub/emonhub.log
4.9M    /var/log/emonhub/emonhub.log.1
5.3M    /var/log/emonhub/

ah, it seems my /etc/logrotate.conf was not owned by root which was causing logrotate to exit. I’ve added a check to the update script to set this file ownership to root.

However /var/log/apache2/error.log is still not being considered, I can’t work out why /var/log/*/*.log should include it :

Handling 1 logs

rotating pattern: /var/log/*.log /var/log/*/*.log /var/log/syslog /var/log/messages  1048576 bytes (2 rotations)
empty log files are not rotated, old logs are removed
considering log /var/log/auth.log
  log needs rotating
considering log /var/log/daemon.log
  log does not need rotating
considering log /var/log/emoncms.log
  log does not need rotating
considering log /var/log/kern.log
  log does not need rotating
considering log /var/log/mqtt_input.log
  log does not need rotating
considering log /var/log/mysql.log
  log does not need rotating
considering log /var/log/service-runner.log
  log does not need rotating
considering log /var/log/ufw.log
  log does not need rotating
considering log /var/log/apache2/error.log
  log does not need rotating
considering log /var/log/emonhub/emonhub.log
  log does not need rotating
considering log /var/log/emonpilcd/emonpilcd.log
  log does not need rotating
considering log /var/log/logrotate/logrotate.log
  log does not need rotating
considering log /var/log/mysql/error.log
  log does not need rotating
considering log /var/log/openhab/2016_05_10.request.log
  log does not need rotating
considering log /var/log/openhab/events.log
  log does not need rotating
considering log /var/log/openhab/openhab.log
  log does not need rotating
considering log /var/log/redis/redis-server.log
  log does not need rotating
considering log /var/log/syslog
  log needs rotating
considering log /var/log/messages
  log does not need rotating
rotating log /var/log/auth.log, log->rotateCount is 2
dateext suffix '-20160510'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /var/log/auth.log.2 to /var/log/auth.log.3 (rotatecount 2, logstart 1, i 2), 
old log /var/log/auth.log.2 does not exist
renaming /var/log/auth.log.1 to /var/log/auth.log.2 (rotatecount 2, logstart 1, i 1), 
old log /var/log/auth.log.1 does not exist
renaming /var/log/auth.log.0 to /var/log/auth.log.1 (rotatecount 2, logstart 1, i 0), 
old log /var/log/auth.log.0 does not exist
log /var/log/auth.log.3 doesn't exist -- won't try to dispose of it
copying /var/log/auth.log to /var/log/auth.log.1
truncating /var/log/auth.log
rotating log /var/log/syslog, log->rotateCount is 2
dateext suffix '-20160510'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /var/log/syslog.2 to /var/log/syslog.3 (rotatecount 2, logstart 1, i 2), 
old log /var/log/syslog.2 does not exist
renaming /var/log/syslog.1 to /var/log/syslog.2 (rotatecount 2, logstart 1, i 1), 
old log /var/log/syslog.1 does not exist
renaming /var/log/syslog.0 to /var/log/syslog.1 (rotatecount 2, logstart 1, i 0), 
old log /var/log/syslog.0 does not exist
log /var/log/syslog.3 doesn't exist -- won't try to dispose of it
copying /var/log/syslog to /var/log/syslog.1
truncating /var/log/syslog

glyn.hudson · 2016-05-10T12:25:00.233Z

@Jon

I have just committed to the ‘dev’ emonPi branch some changes to the update script that will look for and remove any root crontab service runner entries.

Changes have been merged into master. Please test to see if this fixed duplicate service runner entries for you.

github.com/openenergymonitor/emonpi

Fix duplicate service runner & root cron tab entries

openenergymonitor:master ← openenergymonitor:dev

opened 02:27PM - 10 May 16 UTC

glynhudson

+63 -28

After running the update the Pi should be restarted to kill the old service runner that’s mistakenly running as root. After reboot you should EUID in the update log displaying 1000 which is the Pi user (non root) EUID.

pb66 · 2016-05-10T12:32:21.782Z

glyn.hudson:

I’ve also noticed that even the log files that seem to be properly rotated /var/log/emonhub/emonhub.log are greater than 1Mb in size which should be the limit set by logrotate.conf. e.g.

pi@emonpi:~/emonpi $ du -ha /var/log/emonhub/
340K /var/log/emonhub/emonhub.log
4.9M /var/log/emonhub/emonhub.log.1
5.3M /var/log/emonhub/

Remember emonhub will rotate it’s own lofiles at ~5mb which is most probably what you saw here, rather than logrotate doing it at the wrong time/size it just wasn’t doing it at all and emonhub eventually did it.

pb66 · 2016-05-10T12:37:12.329Z

Also doesn’t apache2 set up it’s own logrotate configuration at /etc/logrotate.d/apache2 if so that may well be overriding or at least conflicting with your global config

glyn.hudson · 2016-05-10T12:38:25.234Z

pb66:

Remember emonhub will rotate it’s own lofiles at ~5mb which is most probably what you saw here, rather than logrotate doing it at the wrong time/size it just wasn’t doing it at all and emonhub eventually did it.

Ah right, that explains things. Logrotate was not running at all due to the permissions error I mentioned above. I’ve added a check to the emonPi update script (currently in the dev branch) to set /etc/logrotate.conf ownership to root which was the cause of of logrotate not running.
https://github.com/openenergymonitor/emonpi/blob/dev/emoncmsupdate#L179

Andy_Taylor · 2016-05-10T12:50:07.296Z

In addition to this; Log files can still spill over 1Mb IF they do so in-between the times that log rotate runs (hourly if I remember right).

So - if there is much being written to the log it can still reach 100Mb before the hour and it gets rotated - make sense?

@pb66 the emonpi version of the logrotate.conf excludes those add-ins, so now Glyn has fixed the permissions error that will take care of all the logs properly.

Jon · 2016-05-10T15:41:03.383Z

@glyn.hudson - I did the emonpi update and a restart. The log files are much smaller!

Before:
.
.

After:

.

I don’t see the EUID of 1000 in the emonpiupdate.log file, only EUID of 0:
2016-05-10 at 10-10-59 CDT - emonpiupdate.log.txt (2.3 KB)

And the service-runner line is missing from both the sudo crontab and the crontab.

glyn.hudson · 2016-05-10T17:25:17.389Z

Jon:

And the service-runner line is missing from both the sudo crontab and the crontab.

Really? What does $ crontab - l return? Nothing? I would be very surprised if so, since the update would not work without service runner. If no service runner is present in the pi user crontab the update script should add it in.

What do you see after another reboot and another update? Thanks so much for helping me test this.

Jon · 2016-05-10T17:34:14.012Z

here is what I see with the crontab - l and sudo crontab -l:

Screen Shot 2016-05-10 at 12.32.04 PM_thumb.png449×643 177 KB

I’ll do another reboot & update.

Jon · 2016-05-10T17:41:18.857Z

@glyn.hudson - ~~emonPi update won’t run from the webpage. I’m not sure what I need to run from the command line. Is it update from the /home/pi/emonpi directory without the sudo?~~

EDIT: OK - I think I figured it out. I did a touch /tmp/emonpiupdate and got /home/pi/emonpi/update to run. The service-runner line in now in the pi user crontab.

glyn.hudson · 2016-05-10T18:01:35.276Z

That’s what I suspected. If you manually add the service runner entry to Pi crontab using $ crontab - e update will then run from the Web page. The question is what removed it?! Try and manually add it then run update to see if it disappears. I can’t recreate this, on my system the Pi crontab service runner entry always stays as it should.

Jon · 2016-05-10T18:07:09.737Z

just curious - When looking through the log file above I saw EUID: 0. Does that mean my first emonpi update ran as root?

I’ll try the manual add and run via webpage.

Jon · 2016-05-10T18:15:13.257Z

FYI - When I started today, the service-runner was in the root crontab and not the pi crontab.

Screen Shot 2016-05-10 at 1.11.14 PM_thumb.png492×655 181 KB

I can send you a log of all of the commands I have run today if it will help.

glyn.hudson · 2016-05-10T18:28:21.934Z

Jon:

When looking through the log file above I saw EUID: 0. Does that mean my first emonpi update ran as root?

Correct. This is the problem. Looks like I’m not quite there with this. I’ll do some more investigation tomorrow and figure out what’s going on. Thanks again. EUID 1000 is what it should be running as, the Pi (non root) user.

Jon · 2016-05-10T19:01:43.332Z

If the service-runner line is in sudo crontab -l (and do a reboot) then you’ll be able to recreate what I saw. I tried this and it is repeatable.

I had a 10+ service-runner lines in sudo crontab -l and a few service-runner lines in the pi crontab -l.

Once I put a single service-runner line in pi crontab AND delete all the service-runner lines from the root user crontab then all worked as expected.

glyn.hudson · 2016-05-10T20:34:02.231Z

Ok, I think I see what’s happened. Am I correct that previously you had manually deleted the service runner entries from pi crontab (non sudo)?

The update should remove all the service runner entries from root (sudo) crontab, this is intended operation. Good to know it’s all stable now.

Jon · 2016-05-10T21:40:34.640Z

I actually tried deleting it from each crontab and then running the emonPi update. I could not figure out which was correct and picked the wrong one.