Mosquitto won't start on boot after raspbian and emonsd update

Me too!

I had a quick look and found some related files in the emoncms repo, there’s a readme too.(emoncms/scripts/logger at master · emoncms/emoncms · GitHub) but in the emonPi repo, which is essentially the emonSD repo, there are also some logrotate files but there is a note in one saying

# NOT USED - SEE https://github.com/emoncms/emoncms/blob/master/scripts/logger/

why that is I cannot say. But there doesn’t seem to be any mention of logrotate in the build guide or update script so I’m not at all sure how and when it’s implemented. Or why the files are even in the emoncms repo, the “rc.local” file that is in that same directory is not used, the latest rc.local is in the emonPi repo. So I can only guess the rc.local is added by the emoncms logger install script and then overwritten by the emonpi update script.

Absolutely. I agree. I would like to eventually separate out all the “read-only” stuff to a separate install script/guide so that users can implement read-only or not as they choose and everything for “read-only” is in one place.

[edit]
Found a ref to the logger install script in the “low-write” install guide

Hello,

I finally did not use postrotate feature of logrotate as is only runs if it effectively rotate at least one file. So you’re not sure there will be a backup every hour. So I just added an hourly cron which runs every hour.

As of now, here is what is done :

  • At startup : Content of ~/emonpi/logtools/log.template and ~/data/logtools/log.template are copied over to /var/log/
  • On shutdown : Structure (directories and files with no content) is copied to ~/data/logtools/log.template so it can be restored on next boot
  • Every hour (crontab.hourly) : /var/log is archived to ~/data/logtools/log.archive

I put all scripts, service unit, templates… in a dedicated directory ~/emonpi/logtools

Everything is there as usual : emonpi/logtools at var-log-files · jsiobj/emonpi · GitHub

There are still a few things to do :

  • Thinking about it, on startup, not only the structure but the whole content should be restored. Or I need to “rotate” the log archive to that it is not erased with a new archive of empty files
  • I wrote a litlle install script but I don’t know where this should be run from. emonpiupdate script ?
  • Thinking (again) about all this… shouldn’t a persistent fs be used for log files ? :thinking: This would make it simple. On my dev pi, I added a usb key which I mounted on /var/log

I think this is to reduce the number of write cycles to the SD card.

Can the archiving be done as part of the rotate cron script so only one cron event is called? Is there a risk of the archiving and rotating scripts getting horribly out of sync.

Can you cascade logrotate? so rotate the hourly into a daily into a weekly?

I agree, but this is a difficult question as any new logs created during the prior boot up will be overwritten by either the blank file structure or the log files back up, I cannot see a way around that unless the logfiles are parsed, eg the pre-existing auto created logs content is appended to the end of the restored back up logs.

Again a tough one. I too like to see the logs persisted and what we are trying to achieve with backing up the ram logs every hour is a “low-write” persisted log, rather than several processes writing and rewriting log files in real time we are buffering the writes and “backing up” the logfiles periodically.

There is a risk here that something gets lost if the Pi is not shutdown gracefully in the 59th minuet of the hour, but the alternative is too increase the backup frequency to every 1min or 10 mins etc, which may add to the workload but the emoncms buffered write is already every 1min (AFAICR).

I would like to consider another feature for this logfile manager, and that is too have the option to add a remote location to stash logfiles, using rsync or similar, a duplicate set of logfiles could be maintained remotely, the frequenct that these are synced could be more frequent than the integral backups, thus less data lost in a crash instance.

This is a good option, I suggested this for the 3rd writable “data” partition on an emonPi, the advantage is that if the increased writes are fatal to the USB stick, it doesn’t effect the root filesystem, and It can be easily pulled out to backup or read in another PC.

But for now I think you have a good system evolving, just the initial log content to debate.

That issue could be worked around by using ramlog. Here’s an excerpt from the ramlog web page:

Ramlog act as a system daemon. On startup it creates ramdisk, it copies files from /var/log into ramdisk and mounts ramdisk as /var/log. All logs after that will be updated on ramdisk. Logs on harddrive are kept in folder /var/log.hdd which is updated when ramlog is restarted or stopped. On shutdown it saves log files back to harddisk so logs are consistent. Ramlog 2.x is using tmpfs by default, ramfs and kernel ramdisk are suppored as well. Program rsync is used for log synchronization.

1 Like

Good call Bill, I wonder why you haven’t mentioned it before :wink::wink::grin:

Some previous mentions
https://openenergymonitor.org/forum-archive/node/10773.html
https://openenergymonitor.org/forum-archive/node/11803.html
and it is used in DietPi too
https://openenergymonitor.org/forum-archive/node/12384.html

it hasn’t had a warm reception when Bill has previously suggested it and I’m not entirely sure why, perhaps it was considered too complex for simply writing the files to RAM. But now we are considering adding all this functionality, perhaps we should take another look.

I recall previously I wasn’t overly happy about the fact I can find no changes to the code (or the website) since 2010 and the info is fairly limited. that doesn’t mean it’s a non-runner for me, but I like to see activity and peruse the repos/issues. Plus I prefer installing via a repo such as debian or PECL or PIP etc rather than private zip’s, again not a show stopper.

I have since seen this project

which is still active (last updated 4 days ago). I haven’t looked at either in-depth so I cannot say if they would work for us or which is more suitable (or are there any others?)

Perhaps we can learn something from those projects even if we don’t fully embrace any one of them.

[Edit] - Just having a nose around the log2ram repo and see there are a couple of familiar faces using it @Tim (Current rsync usage may cause excessive SD card writes · Issue #45 · azlux/log2ram · GitHub) and Peter Scargill (Mosquitto and Apache · Issue #18 · azlux/log2ram · GitHub)

I have attached a copy of ramlog in a zipped folder for easier viewing. There is a file in there called “copying” and it states it’s ok to copy/distribute ramlog but not to modify it, I wonder if that includes repackaging it for systemd? I can see how/why log2ram might have started.

ramlog-2.0.0.zip (25.7 KB)

1 Like

I think this is what DietPi uses by default.

Indeed it is. PB made mention of that a couple of posts above this one. :wink:

Yip, I spotted that too late … :frowning_face:

Thanks Paul. 'preciate it.

YVW! 

Hello,

I thought adding this to the script but is is located in emoncms dir, not emonpi dir. So it would require also an update in the emoncms repo. I finally found it simpler to add a new cron entry.

At worst, if it runs just before the rotation, an hour worth of log may be lost in case of a crash. But, it is just logs… The backup frequency could be increased though as Paul suggest :

The other risk I see is rsync running at the very same time. I’ll check if this could be avoid (using some flag.)

Not sure to understand what you mean.

I agree… to both statement :yum:

I find ramlog quite complex (more than a thousand line of shell script… way too much shell for me to read :wink:) Also, it is a bit old and seems not to be suited for systemd (may be it could be adapted ?)

I just had a look at log2ram which is way simpler ! It makes use of mount --bindand mount --make-private. I’ll have a look of what this does precisely.

And finally, digging around, I found this : Setting up overlayFS on Raspberry Pi. May be an overlay fs would would work, using SD card FS as the “lower” FS and ramfs as “upper” FS. Yet, a “commit” needs to be run from time to time to write upper FS updates to the lower FS.Do you think overlayFS is something worth looking at ?

I think this has changed on later versions of logrotate. The most recent man page says

The directory must be on the same physical device as the log file being rotated, unless copy, copytruncate or renamecopy option is used. (my emphasis)

From the ChangeLog I think it changed in version 3.8.8. however, checking an older Jessie based Pi it looks like the logrotate version is only 3.8.7 (and this appears to be the latest version in this repo).

Hello Brian,

We could use this to archive log files on a persistent fs. But there is still the log file backup on shutdown and restore at boot time to take care of. I could not find any option to run a rotation on shutdown but instead of running a backup script, we could run logrotate with a specific configuration so that it archive existing logs.

What would be the “policy” about upgrading logrotate on emonpi ?

I had a deeper look at log2ram. I find it quite similar to what I’ve done so far (apart from the fact I am only restoring file structure and not the whole logs for now…)

One main difference with what I am doing is the way it uses file systems. The scripts manages the tmpfs. It is not mounted using fstab. First it “binds” /var/log (in root fs) to /var/hdd.log and make the bind private so that it can mount a tmpfs to /var/log and still see the content of the “hidden” /var/log (because of the tmpfs mount) through /var/hdd.log.

hmmmm… not sure I am clear…

Hello,

I had a look to overlayFS but it seems that you cannot “commit” the changes without unmounting the upper fs so it makes it tricky. And I definitely found ramlog too complex.

I finally pushed a new version of the logfile init/backup/restore here on github. It is working much as log2ram

So here are the results

On startup : it restores the backup if any and restore the default logfile “template” if needed.
Every hour and on shutdown, it makes a backup.

I did a test and it seems to work quite nicely. Looking at /var/log/messages :

Mar 14 20:35:32 emonpi rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="534" x-info="http://www.rsyslog.com"] start
Mar 14 20:35:32 emonpi kernel: [    0.000000] Booting Linux on physical CPU 0x0
...
Mar 14 20:40:06 emonpi rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="534" x-info="http://www.rsyslog.com"] exiting on signal 15.
Mar 14 20:40:16 emonpi rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="544" x-info="http://www.rsyslog.com"] start

So it seems :

  • last backup on shutdown occurs after rsyslogd is stopped which may be late enough
  • restore on boot occurs before rsyslogd starts which may be soon enough

I will push that to my live emonpi a see how it goes.
Any comment, correction, improvement is welcome.

If you think it is usefull, I will do a PR !

1 Like

How is this looking on your emonPi @jsroques?

Apologies (again) for the lack of engagement. I haven’t had the time to look at your work in depth and felt it demanded a proper evaluation rather than a “quick look” especially as I do not use the emonSD or anything else from the emonpi repo, so I will have to pick out the bits and build an image to fit them to to try this out properly.

I have come back here today just to add a couple of notes that maybe of interest following on from the “Data not logged locally” discussion.

Firstly it might be worth while having the log-rotation triggered by something other than cron. If the log partition fills up, cron can fail, so the bloated logs will not get rotated out. If (for example) a service (perhaps the same one as the log backups so they are sync’d?) was to time one hour and trigger, in a loop rather than using cron, even if the log partition fills up to the point cron doesn’t work, the files will still get rotated on the hourly timer service. This would have a minor benefit of removing some of the lorotate mods for RO OS as the original daily cron can remain, we do not need to add an hourly one.

Secondly, since this log file management is pretty much all related and all required if and only if the OS is RO, perhaps it could check the log partition usage and trigger a rotation at 90 or 95%, yes theoretically we lose 5-10% of the space but I’m thinking headroom for runaway errors, if it’s only checked every few secs it could fill up before the next check, this then presents the question over whether we need to rotate hourly if we are monitoring the partition size? perhaps just run rotate at 80% full and forget hourly rotations, just back up hourly instead?

These are not finished thoughts or feature requests, just some observations and related thoughts for possible consideration.

Hello @pb66,

I had some trouble with my emonpi. I don’t know why but my data partition is rather small (<200MB). Not such a big deal though but I wanted to solve this before anything else, and did not have the time to do it… So the log stuff is not yet running on my “production” emonpi. I guess I will have to make a backup, flash a new SD, and restore… But May is a good month for bank holidays in France :smile: so I will get some time to work again on this.

Is that a know problem problem with cron ? Or did you experience this ?

But then in case of a crash you would lose all logs. The one hour rotation / backup allows limited loss in case of OS crash.

That being said… In the first place, this was about allowing (dumb) services which are not able the create their own log file to start by creating the files in the ram drive at startup. Aren’t we trying to build something overly complex to backup a few logs ? I mean, if emonpi is to be used for some kind of “mission critical” stuff, then… may be a USB thumb drive, or better, a USB HDD or SSD should be used for all RW partitions.

What do you think ?

Sounds like the image wasn’t expanded, the data partition is less than 200MB to make the compressed size smaller and to make it possible to run on a 4GB sdcard. When you first boot the new image you should run emonSDexpand. Assuming you are using a sdcard larger than 4GB the data partition should grow significantly.

I used to experience it a lot, I have measures in place to avoid it, but to my knowledge there has been no specific fix. and to be honest I have not noticed if the rare occasions I’ve still seen it are on a recent OS or not, so I cannot confirm this is still an issue, only that it was an issue and that I’m not aware of any changes to that.

But the post I previously linked, does seem to confirm it’s still an issue.

Do the rotation and backup need to occur together? I wasn’t suggesting it shouldn’t be backed up hourly, just pondering on whether it needs to be rotated hourly. But it was just that, pondering, wondering what the optimum setup was.

For me the most important part is the backup and retention of the logs. Creating the empty log files and folders is a trivial task that just shouldn’t be done in rc.local, and preferably not use a harcoded list of log files.

The most valuable thing here IMO is the fact that users do not need to check their emonPi is still running every hour just in case any useful info is rotated out of the logs if they’re not quick enough and that they do not need to wait for a forum discussion or somehow copy all thier logs out of the emonPi so that they can try a reboot without fear of losing info to help debug.

Ok… I’m dumb… :roll_eyes: I probably thought this was done because latest Raspbian is doing this on first startup. So I took it for granted… Anyway… it is off topic.Thanks for the tip. Ran it last night, now got almost 4GB

Ah… sorry. Misinterpreted what you wrote. Missed the “just back up hourly instead”…
They are independent anyway (2 distincts cron jobs).

That would not prevent file system from filling up anyway as archiving is done on the very same file system (and archives are not compressed as of today). This would work if we could rotate logs on another fs which is not possible with the current version but may be possible with latest version as @borpin suggested. Next question is : what would be emonpi policy regarding OS / tools upgrade ?

And rethinking about this… if fs is full… :face_with_raised_eyebrow: logrotate will fail anyway as there is no more space

Yep… you’re right. I did have hard time with that while starting this log file stuff as I lost log files on each reboot and make troubleshooting… a bit tricky.

If logrotate allows crossing fs boundary, we could

  • run logrotate every hour, day, on fs space trigger… (which ever seems appropriate) on a persistent fs (data typically). That would
    • prevent space problems on /var/log (but may cause some on target fs. we would limit the risk of bloating persistent fs by limiting number of archive or could we use quotas on a directory ? We definitely don’t want to fill another fs up with logs…)
    • serve as a persistent log history
  • run a backup of current logs (without the history) every minute, hour… so in case of crash, we loose minimum logs
  • run a backup on shutdown so that we keep the most recent history in case of a reboot
  • restore the backup on restart so that we restart logging where we left it

Does that make sense ?

My thinking was to take the trigger out of the hands of cron so that it cannot be blocked by a full log partition. If the new script had an inbuilt timer/sleep and did it’s checks and found the log partition full, it could still rotate out the files when cron might not run. And if it was on it’s own “shorter” timer loop, it could discover the 95% limit much sooner than an hourly rotation cron.

I really must do some proper tests to see if this is still an issue in both Stretch and whatever the emonPi is running after a (full?) update. Although I’m tempted to just develop for the latest OS and assume the emonSD/emonPi will get revised at some point, it seems foolish to develop for an out of date OS.

Already covered in the answer above?

Just to add a note here about the emonSD log files in general, IMO they need tidying up somewhat. Whilst looking into something else I fired up a emonpi (older image) and this was the log folder

pi@emonpi(rw):~$ ls -la /var/log
total 1920
drwxr-xr-x 11 root        root            640 Apr 30 11:17 .
drwxr-xr-x 12 root        root           4096 Nov  7  2016 ..
drwxr-xr-x  2 root        adm              60 Mar  8 17:17 apache2
-rw-r-----  1 root        adm           36044 Apr 30 11:26 auth.log
-rw-r--r--  1 root        root           8997 Apr 30 10:14 boot.log
-rw-------  1 root        utmp              0 Mar  8 17:17 btmp
-rw-r-----  1 root        adm           56899 Apr 30 11:17 daemon.log
-rw-r--r--  1 root        root           1344 Apr 30 10:14 dataplicity.log
-rw-r-----  1 root        adm            1093 Mar  8 17:17 debug
-rw-rw-rw-  1 root        root         318915 Apr 30 11:26 emoncms.log
-rw-rw-rw-  1 root        root        1325267 Apr 30 11:17 emoncms.log.1
drwxr-xr-x  2 emonhub     root             80 Apr 30 11:17 emonhub
drwxr-xr-x  2 pi          root             60 Mar  8 17:17 emonpilcd
-rw-r-----  1 root        adm           32712 Apr 30 11:25 kern.log
drwxr-xr-x  2 pi          pi               80 Apr 30 11:17 logrotate
-rw-r-----  1 root        adm             251 Apr 30 11:17 mail.err
-rw-r-----  1 root        adm             545 Apr 30 11:17 mail.info
-rw-r-----  1 root        adm             545 Apr 30 11:17 mail.log
-rw-r-----  1 root        adm             251 Apr 30 11:17 mail.warn
-rw-r-----  1 root        adm           31619 Apr 30 11:25 messages
drwxr-xr-x  2 mosquitto   mosquitto        60 Apr 30 10:14 mosquitto
-rw-rw-rw-  1 root        root              0 Mar  8 17:17 mqtt_input.log
drwxr-xr-x  2 mysql       adm              60 Mar  8 17:17 mysql
-rw-rw-rw-  1 root        root              0 Mar  8 17:17 mysql.log
-rw-rw-rw-  1 root        root              0 Mar  8 17:17 ntp_update.log
drwxr-xr-x  2 openhab     openhab          80 Apr 30 10:14 openhab
drwxr-xr-x  2 redis       redis            60 Mar  8 17:17 redis
-rw-rw-rw-  1 root        root           1898 Apr 30 11:26 service-runner.log
drwxr-xr-x  2 dataplicity dataplicity      60 Mar  8 17:17 supervisor
-rw-r-----  1 root        adm          100992 Apr 30 11:26 syslog
-rw-r-----  1 root        adm            5373 Apr 30 11:25 ufw.log
-rw-rw-r--  1 root        utmp           2304 Apr 30 10:17 wtmp

IMO there should be a wider use of sub folders eg

emoncms.log
emoncms.log.1
mqtt_input.log (not sure if this is still used)

should be in a emoncms folder (there is an unfinished discussion about emoncms file structure at Move data & settings file to a common location?)

and

service-runner.log
emonpilcd/emonpilcd.log
emonpiupdate.log
wificheck.log

should probably all be in a single “emonsd” subfolder, since the logs will be persisted across reboots, there would no longer be a need to put any logs on the writable “data” partition (unless they are backups) but this isn’t directly the responsibility of the log rotate/persist script, although I guess it is related due to the “template”.