Extra service-runner commands in crontab - Part II

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

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

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

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 ?

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 :frowning:

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…

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.

[email protected]:~/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

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

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.

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.

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

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

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.

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

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.

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

I’ll do another reboot & update.

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

1 Like

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.

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.

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

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

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.

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.

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.

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.