/var/log still filling up

That is always true with a ‘regular’ rotation mechanism unless you put in a monitoring solution like Monit as well (even with Log2Ram).

Correct, (L2R plays no part in this), it’s all down to how much log info is produced, how much space is available and how it is rotated.

With the logrotate strategy I’ve suggested (using with L2R,)

  1. the size available in ram is effectively increased significantly as the rotated logs are no longer held in ram.
  2. with dedicated “sdcard (or L2R) optimised” logrotate configs for applications the limit can be set to suit each log, who really needs 1M of any non-OEM log held in RAM? Many logs can be rotated at 1K (for example) whilst emonhub/emoncms etc are larger.
  3. do not use copytruncate so that rotating isn’t blocked by a full /var/log.
  4. forced logrotate if overall size reaches limit.
  5. increased size limit of /var/log
  6. maybe even Increase frequency of checks if needed? (perhaps better than depending on monit)

With available size in ram vastly increased and size of logs severely decreased the chance of filling up is vastly reduced. Currently (eg take 10 minor system logs ie not emonhub/emoncms) 10x logs at a permissible 1M uses 10M (25%) of available ram, given the rotations are also of a similar size (can be smaller, but can also be much larger) that’s 50% of the 40M used on a healthy system. Reduce those to 1K with no rotated logs in ram, that’s just 10K of 40M (0.00025%), much more room for “incidents”! Plus if /var/log is managed better then there is no reason not to use a bigger limit (eg 100M?) as race conditions would be fewer and better managed so the 100M (vs 40M) is less likely to impact the rest of the OS, plus, when /var/log is filling up over 40M (but less than 100M) the OS can still function, albeit serving web pages at a lower speed or taking longer to process inputs as Redis isn’t populated etc etc But no crash!!!

It would be far better to reduce the ram available to the rest of the system to a plentiful 900M than resort to using swapfile or crashing out!

[edit] remember the 40M is only a max limit not a reservation of ram. if the logs are only 10M you still have 990M for other usage even if the partition has a 100M limit.

Is that the sort of thing I should raise a bug for then?

edit: PS +1 for your suggested organization of logging.

Actually, I was wrong. I misread the message, it should be a warning level (sorry!) What it is telling you is that the data you are trying to post, is earlier that the last saved data. The data posted has a timestamp of 1557820800 (Tuesday, 14 May 2019 08:00:00 UTC) which is 1 hour earlier than the current “last data” which has a timestamp of (Tuesday, 14 May 2019 09:00:00 UTC). You cannot post (or edit) data that is before the “last data” if you are using emoncms feedwriter (which the emonSD image does). Therefore this is a warning to the user that their data is not being recorded.

Original

As editied.

Thanks for editing my quote Paul.

It is not the rotation mechanism, it is the trigger for the rotation mechanism that creates a ‘regular’ check to see if rotation is required i.e. time based. Thus between the 2 checks there is always a possibility (however slight) that the logs will runaway.

So an irregular rotation trigger (actually it is still regular just checking more often) via something like Monit, reduces the chance of a log running away to the don’t need to worry about it level.

The way weather stations send hourly observations via DataPoint is that they send the previous 24 values. This is vital if there is an interruption in service in order to avoid a gap in records. So yes, I could complicate my input program by first reading the observations already recorded by emoncms and not uploading them, but it seems to me to be simpler and safer all round to upload them all and have emoncms simply discard the ones it doesn’t need. So as far as I’m concerned it’s not an error and not something that needs warning about; it’s normal. It would be nice if I could tell emoncms that.

Id like to go forward and fix this issue by reverting to using the in-built emonhub.log.

1. I would amend emonhub/service/emonhub.service at emon-pi · openenergymonitor/emonhub · GitHub to include the --logfile parameter

ExecStart=/usr/share/emonhub/emonhub.py --config-file=/home/pi/data/emonhub.conf --logfile=/var/log/emonhub/emonhub.log

2. I would update rc.local for the stretch image to setup the emonhub log directory emonpi/stretch/rc.local at master · openenergymonitor/emonpi · GitHub

3. I would update the emonhub update script to create the emonhub log directory to avoid the need for a system restart during the update emonpi/update/emonhub.sh at master · openenergymonitor/emonpi · GitHub

4. Update the emonhub log viewer UI to use /var/log/emonhub/emonhub.log

I think I would prefer to do this than just disabling the systemd service installation, it would also fix existing systems that have already run an update. Would you be happy if I proceed with the above @pb66 @borpin?

The rc.local mod is of course temporary, to be replaced with our non rc.local requirements as part of the new emonSD image & scripts in development.

Im not sure if I need to make any logrotate modifications yet to fix this on existing systems.

I am content with the approach.

Not to fix the log folder filling up as emonhub will rotate at 5M. What is does mean is that there is a maximum of 10M of logs which is not very long in time with MQTT publish messages.

Longer term, I’d like to see a solution that enables a defined set of days of logs but that would be compatible with emonhub handling the logging.

Why not look at MQTT logs direct from the broker if they’re required? It’s very easy to just subscribe if desired, and the output can be stored in a file wherever you’d like. Emonhub publishes them as INFO so it’s easy enough to not see them there if required. Most of the time, logging MQTT messages is a waste, IMHO.

Most of the time maybe, but they helped sort out this issue (Emon MQTT data incomplete) as it showed emonhub was definitely sending them :smile:.

Well, investigating an MQTT issue is clearly a time when you would want to look at MQTT messages, yes! But that’s not most of the time. And the OP did it using mosquitto_sub, not by using emonhub logs, IIUC.

Yes but the emonhub log was important as it showed emonhub was sending the message, just the Mosquitto broker was not receiving it.

However, under normal conditions having the log just running at warn or error and setting message level appropriately would reduce number of messages. However, usually, the situation is 'emonhub stopped 10 hrs ago` and in that case being able to back into detailed logs may identify why. I prefer verbose logging, it is a small overhead to deal with them really. YMMV.

I’m confused. I just looked at the thread again and don’t see anywhere the emonhub log is mentioned.

Very first post quotes emonhub log (second code entry)…

You mean the one directly after this description?

In the emoncms.log it aappears that the data is published:

I now understand why I was confused. You’re right, it is an emonhub.log not an emoncms.log

But it just shows the same thing as the mosquitto_sub logs above, so doesn’t add any value.

I could go on but I won’t; life is too short.

I have applied the above changes, which all appear to be working as expected:

  1. –logfile parameter in emonhub service: Update emonhub.service · openenergymonitor/emonhub@8cc8e0e · GitHub

  2. rc.local update to create emonhub folder:
    Update rc.local · openenergymonitor/emonpi@813fb97 · GitHub

  3. emonhub update script modification to create emonhub log folder:
    Update emonhub.sh · openenergymonitor/emonpi@b74caff · GitHub

  4. emonhub log viewer change in config module:
    Update config_controller.php · emoncms/config@5d66119 · GitHub

1 Like

Yeah the PR to put the change on hold was purely that! Just to stop more users falling into the issue that we didn’t have an immediate agreed fix in place for, especially before the emoncms v10 was released, but that ship has sailed and the “quick fix” didn’t get any attention in almost a week! ( I know you were away, but you aren’t the only one with access).

1, 3 and 4, great, I had pretty much done the same thing in my forks but realised there was little point in doing any PR’s by that time.

Regards the logfile creation in rc.local, IMO it doesn’t matter how temporary, temporary is, it’s not temporary enough. I explored getting the service unit to create the logdir as the init.d script has done so reliably for so long. I edited my service unit to include

ExecStart=/usr/share/emonhub/emonhub.py --config-file=/etc/emonhub/emonhub.conf --logfile=/var/log/emonhub/emonhub.log
PermissionsStartOnly=true
ExecStartPre=-/bin/mkdir -p /var/log/emonhub/
ExecStartPre=-/bin/chgrp -R emonhub /var/log/emonhub/
ExecStartPre=-/bin/chmod -R 777 /var/log/emonhub/

which works fine, it also includes some minor permission changes to allow the user to manipulate logfiles without using sudo (eg truncating or removing sensitive info before posting) and to set just the group ownership so the folder ownership is more in keeping with other package maintained log folders (ie root owned).

PS I also do not think the PIDFILE is used (unless type=forking) and the word “description” doesn’t need to be in the service unit description, when you look at the service log entries, “restarted the emonhub service description” doesn’t make much sense. So I now have

[Unit]
Description=emonHub service
DefaultDependencies=no
Before=shutdown.target
Conflicts=shutdown.target
Requires=local-fs.target
After=sysinit.target syslog.target local-fs.target

[Service]
User=emonhub
ExecStart=/usr/share/emonhub/emonhub.py --config-file=/etc/emonhub/emonhub.conf --logfile=/var/log/emonhub/emonhub.log
PermissionsStartOnly=true
ExecStartPre=-/bin/mkdir -p /var/log/emonhub/
ExecStartPre=-/bin/chgrp -R emonhub /var/log/emonhub/
ExecStartPre=-/bin/chmod -R 777 /var/log/emonhub/

Type=simple
Restart=always

[Install]
WantedBy=multi-user.target

and an entry in rc.local is not needed.

This don’t need to be a temporary “fix” either. IMO making the service unit(s) create their own log folder (and files?) makes for a much more robust set up, even if L2R is used, a service that can recreate it’s own log folder (at the cost of a couple of lines of code) is belt and braces, it would mean that even if users accidentally deleted emonhub.log, a simple restart would fix it.

Whilst it is not a good idea to start meddling with all the various packages (mysql redis etc) service units, I think there is value in ensuring that OEM services, intended for use on a sdcard (not exclusively) are able to create their own logfolders. There are now at least 2 emoncms services that will be logging to emoncms.log, so even the core emoncms install can have it’s log folder created before any web pages or requests are served. This will also shorten install steps and ensure any accidental changes to permissions or ownership are corrected automatically.

I’ve looked through the logrotate install/update and it seems to be currently complete (as intended on previous emonSD images but absent on the Oct2018 image) but I wonder about how “multi-run safe” that script would be, surely the backed up files will get overwritten on every run as symlinks will pass the -f test. Also there is some confusion around the hourly vs daily cron (linking then moving?) so I was going to propose these changes Comparing master...logrotate · emoncms/emoncms · GitHub which will backup either daily or hourly cron files (but not symlinked copies) and forces a new cron symlink, just in case an existing incorrect symlink blocks a correct one being written.

I had also added the logrotate log folder check and create to the cron so that the folder is always found (ie not required in rc.local) and so that permissions are corrected even if it is there since the rc.local tries to change the ownership to pi:pi, which I didn’t understand as pi doesn’t have the authority to run logrotate properly unless using sudo and then root ownership is fine!

There is also a problem with the recent addition of a /var/log/* wildcard being added that will cause issues with rotating rotated files as if they were independent logfiles (not as previous rotations). Plus the “rotate 2” was changed to “rotate 1” at the same time, IMO this should be put back (check to see if logs require rotation hourly · emoncms/emoncms@ddb0854 · GitHub).

Plus this “fix” seems to be on/off/on Update logrotate.conf · emoncms/emoncms@7cc85b7 · GitHub which I do not think is needed if logrotate is run as root (by cron), this maybe linked to the pi:pi ownership in rc.local?

I still think there are improvements to be had to both the way logrotate is implemented and the logrotate rules thenselves as part of the L2R roll-out, but a return to emonhub.log and the old intended logrotate is a good temporary position, although not perfect, it has been ok over the last couple of years, certainly good enough to see us through to roll out of a better solution.

I suggest using systemd-tmpfiles as that is exactly what it is designed for (managing non persistent files). You could put a pre command in the service file to wait until the folder has been created but the start order means that (I think) the tmpfiles are created as soon as the FS is mounted.

@pb66 and I don’t agree on this, but I feel we should first revert the logrotate to a standard config so all the various packages pull in their own configurations (where set). The only change to the standard setup would be to change it from a daily trigger via cron, to an hourly (and that could just be for SDCard environments). In addition then, include a specific logrotate config for the emon systems to manage & rotate their logs.

This then fits with the ‘not just for an SDCard install’ philosophy of the new scripts.

This scheme could easily sit alongside L2R other than the olddir directive, as the issue there is where 2 packages have the same error.log file specified in different folders.