log2ram
log2ram copied to clipboard
azlux
Log2ram failed to start on boot
Device: raspberry pi 4 2GB kernel: 5.10.63-v7l+
I noticed that my pi took a very long time to reboot. Then I checked that boot.log and found that log2ram failed to start. When I manually restart log2ram by
sudo systemctl restart log2ram
it worked totally fine.
Then I removed log2ram via the apt method, then installed it again. The problem was gone.
It might be due to an update that I have done 3 days ago as I haven't rebooted since then.
Anyone who thinks that their raspberry pi failed to boot after reboot or just fails to boot should check if they have log2ram installed. If so, be patient and wait for about 5 minutes after power on to see if it boots up. If that is the case, try doing the following:
sudo apt update; sudo apt remove log2ram && sudo apt install log2ram
Then reboot. The first reboot may take longer, wait for at least 5 minutes before aborting. But the second one is fine.
That should no append. Have you any error into /var/log/log2ram.log or systemctl log2ram status ?
I havent seen any errors, but I havent view all of the logs, just some of them.
From what I have remembered, systemctl showed that it was terminated. boot.log shows that it waited for about 2 minutes before giving up and killed log2ram.
systemctl status log2ramseems to show that the sync was done half way? I dont quite remember.
Any way for me to view the old logs? If so I could provide them.
I manage to get it again, somehow
● log2ram.service - Log2Ram
Loaded: loaded (/etc/systemd/system/log2ram.service; enabled; vendor preset: enabled)
Active: failed (Result: timeout) since Tue 2021-10-19 17:23:41 HKT; 3min 14s ago
Process: 274 ExecStart=/usr/local/bin/log2ram start (code=killed, signal=TERM)
Main PID: 274 (code=killed, signal=TERM)
10月 19 17:23:42 raspberrypi log2ram[274]: admin/style/vendor/bootstrap/fonts/glyphicons-halflings-regular.woff
10月 19 17:23:42 raspberrypi log2ram[274]: admin/style/vendor/bootstrap/fonts/glyphicons-halflings-regular.woff2
10月 19 17:23:42 raspberrypi log2ram[274]: admin/style/vendor/bootstrap/js/
10月 19 17:23:42 raspberrypi log2ram[274]: admin/style/vendor/bootstrap/js/bootstrap.min.js
10月 19 17:23:42 raspberrypi log2ram[274]: admin/style/vendor/font-awesome/
10月 19 17:23:42 raspberrypi log2ram[274]: admin/style/vendor/font-awesome/js/
10月 19 17:23:42 raspberrypi log2ram[274]: admin/style/vendor/font-awesome/js/all.min.js
10月 19 17:23:42 raspberrypi log2ram[274]: colour/
10月 19 17:23:42 raspberrypi log2ram[274]: colour/Black.png
10月 19 17:23:42 raspberrypi log2ram[274]: colour/black.html
pi@raspberrypi:/var/log $ cat log2ram.log
building file list ... done ./ Xorg.0.log
Xorg.0.log.old alternatives.log alternatives.log.1 alternatives.log.2.gz auth.log auth.log.1 auth.log.2.gz auth.log.3.gz auth.log.4.gz
boot.log
btmp btmp.1 clean.log daemon.log
daemon.log.1 daemon.log.2.gz daemon.log.3.gz daemon.log.4.gz
debug debug.1 debug.2.gz debug.3.gz debug.4.gz dpkg.log dpkg.log.1 dpkg.log.2.gz dpkg.log.3.gz
dpkg.log.4.gz kern.log kern.log.1 kern.log.2.gz
kern.log.3.gz kern.log.4.gz lastlog log2ram.log log2ram.log.1
log2ram.log.2.gz log2ram.log.3.gz log2ram.log.4.gz
log2ram.log.5.gz log2ram.log.6.gz log2ram.log.7.gz messages messages.1
messages.2.gz messages.3.gz messages.4.gz
openvpn-status.log openvpn.log openvpn.log.1 openvpn.log.2.gz openvpn.log.3.gz
openvpn.log.4.gz php7.3-fpm.log php7.3-fpm.log.1 php7.3-fpm.log.2.gz
php7.3-fpm.log.3.gz php7.3-fpm.log.4.gz php7.3-fpm.log.5.gz php7.3-fpm.log.6.gz php7.3-fpm.log.7.gz
php7.3-fpm.log.8.gz php7.3-fpm.log.9.gz pihole-FTL.log pihole-FTL.log.1 pihole-FTL.log.2.gz
pihole-FTL.log.3.gz pihole.log pihole.log.1 pihole.log.2.gz
pihole.log.3.gz
pihole.log.4.gz pihole.log.5.gz pihole_debug.log pihole_updateGravity.log syslog
syslog.1 syslog.2.gz syslog.3.gz
syslog.4.gz syslog.5.gz syslog.6.gz syslog.7.gz user.log
user.log.1 user.log.2.gz user.log.3.gz user.log.4.gz
vncserver-x11.log vncserver-x11.log.bak wol.log wtmp
apt/
apt/eipp.log.xz apt/history.log apt/history.log.1.gz apt/history.log.2.gz
apt/history.log.3.gz apt/history.log.4.gz apt/term.log apt/term.log.1.gz
apt/term.log.2.gz
apt/term.log.3.gz apt/term.log.4.gz cups/ cups/access_log
cups/access_log.1 cups/access_log.2.gz cups/access_log.3.gz cups/access_log.4.gz cups/access_log.5.gz
cups/access_log.6.gz cups/access_log.7.gz cups/error_log cups/error_log.1 cups/error_log.2.gz cups/error_log.3.gz cups/error_log.4.gz cups/error_log.5.gz cups/error_log.6.gz cups/error_log.7.gz
forecast/ forecast/forecast.txt lightdm/ lightdm/lightdm.log
lightdm/lightdm.log.old lightdm/x-0.log lightdm/x-0.log.old lighttpd/
lighttpd/access.log
lighttpd/access.log.1 lighttpd/access.log.2.gz lighttpd/access.log.3.gz lighttpd/access.log.4.gz lighttpd/access.log.5.gz lighttpd/access.log.6.gz lighttpd/access.log.7.gz lighttpd/access.log.8.gz lighttpd/access.log.9.gz
lighttpd/error.log lighttpd/error.log.1 lighttpd/error.log.2.gz
lighttpd/error.log.3.gz lighttpd/error.log.4.gz lighttpd/error.log.5.gz lighttpd/error.log.6.gz lighttpd/error.log.7.gz
lighttpd/error.log.8.gz lighttpd/error.log.9.gz minidlna/
minidlna/minidlna.log minidlna/minidlna.log.1 minidlna/minidlna.log.2.gz minidlna/minidlna.log.3.gz minidlna/minidlna.log.4.gz
openvpn/ pihole/ private/
samba/ samba/log.nmbd samba/log.nmbd.1 samba/log.nmbd.2.gz samba/log.smbd
samba/log.smbd.1 samba/log.smbd.2.gz samba/cores/
samba/cores/nmbd/ samba/cores/smbd/ sent 44,528,583 bytes received 38,859 bytes 29,711,628.00 bytes/sec
total size is 44,799,590 speed
Both lights at ethernet port are on when booting stuck. Green act light of pi is not flashing until 2 minutes after boot.
I tried to rsync the backup logs from a old copy of the same drive to /var/log. Turns out it was a bad idea.
It's look like the copy stop somewhere. Can you try to launch the copy manually ?
/usr/local/bin/log2ram write
The issue resolved again after I reinstalled, so I could not test it.
But I remember that when I was debugging yesterday, I tried to start it manually, by sudo systemctl restart log2ram and it went fine, except there were more /dev/zram[n] than usual, where [n] is a single digit. I saw 0, 1, 3, 4, but not 2. During normal operarion I only saw /dev/zram0 and /dev/zram1
It's look like a zram issue in your case, if zram didnt start logs can be heavier the authorized size
I dont know, but the my log size was kept below 40M, tho I set the capacity to be 80M, but zram bumped that up to maybe 130M or so using lz4 compression?
I cannot know, lz4 is quite powerful with simple text data. Test show a compression at least 2.101x
I think I'm also hitting this but how can I verify it? I mean, I do get like 5-min bootup times after a reboot, but it doesn't happen consistently.
@XhmikosR the most simple solution is to check the status of log2ram right after reboot by
sudo systemctl status log2ram
If it said active (exited) its should be fine.
Make sure that you dont have any script that restarts log2ram. If any they should be in crontabs. If you dont remember setting any of those, the chances are you dont have any.
Or you could check the /var/log/boot.log, it should contain important data. Check for any lines that have at least one red charactors, or grep -i it with log2ram or fail.
Thanks for the reply. It seems /var/log/boot.log does not exist on my system (Raspbian OS 10). Running dmesg logs some warnings but no errors AFAICT. I don't see any log2ram in cron jobs AFAICT either.
Oh, well, it might be another issue then...
You may need to use sudo to read boot.log
Or you could try to reinstall log2ram, but be reminded that all logs, including the archived ones would be gone. Make sure you dont save anything important there.
I believe my issue was due to https://github.com/RPi-Distro/raspberrypi-net-mods/issues/6. So, I was getting aprox. 90-100 seconds boot delay due to that and not due to log2ram. Sorry for the mixup, I was trying to pinpoint the cause :)
EDIT: now booting is down to 15s for a headless system.
@azlux I have an idea. Maybe log2ram was configured to start before zram, so it tried to write to a non-existing drive?
Can you check the zram service on your system ?
On the log2ram service, systemd start log2ram before a service called zram-swap-conf.service
https://github.com/azlux/log2ram/blob/master/log2ram.service#L4
[Unit]
Description=Log2Ram
DefaultDependencies=no
Before=basic.target rsyslog.service syslog-ng.service syslog.target systemd-journald.service sysinit.target shutdown.target zram-swap-conf.service apache2.service lighttpd.service
After=local-fs.target
Conflicts=shutdown.target reboot.target halt.target
RequiresMountsFor=/var/log /var/hdd.log
IgnoreOnIsolate=yes
[Service]
Type=oneshot
ExecStart= /usr/local/bin/log2ram start
ExecStop= /usr/local/bin/log2ram stop
ExecReload= /usr/local/bin/log2ram write
TimeoutStartSec=120
RemainAfterExit=yes
[Install]
WantedBy=sysinit.target
It looks like this now. How should I modify it? I dont quite understand...
Also, I think I set up /var/www/html as another log2ram in the configs. Does that matter?
That was not the question.
Do you have an answer with the command : systemctl --type=service | grep zram
I had the same problem. Reinstalling log2ram solve the problem. Before and after reinstalling this (systemctl --type=service | grep zram) answer nothing. I also use log2ram for another directory.
@clavay Strange. Both my zram and log2ram are working now, but that command I just ran give me this result:
sudo systemctl --type=service | grep zram
[email protected] loaded active exited Setup zram based device zram0
[email protected] loaded active exited Setup zram based device zram1
[email protected] loaded active exited Setup zram based device zram2
zram-swap.service loaded active exited zram swap service
pi@raspberrypi:~ $ zramctl
NAME ALGORITHM DISKSIZE DATA COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram2 lz4 2.1G 32.7M 9M 13.4M 4 [SWAP]
/dev/zram1 lz4 200M 33.8M 13M 21.8M 4 /var/www/html
/dev/zram0 lz4 200M 98.3M 26.8M 53M 4 /var/log
I dont have a broken log2ram install for testing currently.
This fix should help with your issue : https://github.com/azlux/log2ram/commit/6ee7907b80cea061e0ff0b0f9479bd304f7e977c
To test the fix before I release next version, you can make the same modification than the commit on this file : /etc/systemd/system/log2ram.service
@azlux no, that does nothing.
Maybe you could try setting up /var/www/html as another log2ram to test it urself
As I don't have zram installed I don't see the difference. Should it be installed by default with log2ram ?
zram must be causing some problem. I remember not using log2ram with zram before, and nothing special happened. Zram is working properly. Is there any debugging flags for log2ram to use? Like logging the current state? For example logging "waiting for zram to start" or "starting service at [unix timestamp]"?
I think it's not related to zram but having more than one directory in log2ram conf.
Maybe both?
zram Num of dir problems
No 1 No
No 2 Not tested
Yes 1 Not tested
Yes 2 Yes
Triggering the bug is not entirely obvious yet. I suppose it was due to some apt updates? Sometimes after a apt update I got this bug, but I seldom reboots anyway, so I am not sure. I think it was waiting for something for too long, so including the time for copying files exceeds the 120s limit? If so what is hanging it off? Mounting the disks?
Maybe it log2ram isnt designed for more than 1 dir, so the service file does not add the second dir?
Looking at the service file, shouldnt log2ram starts after zram? If so, why that isnt marked as wanted? Or, why zram-swap-conf is marked in the after section, so it is started after log2ram? I dont quite understand.
Looking at the services, i see these services related to zram
[email protected] zram-swap-conf.service
[email protected] zram-swap.service
[email protected]
The status of conf one returns this: Unit zram-swap-conf.service could not be found.
The @zram012 ones all have these in common, dispite it seems that it works completely fine:
Active: active (exited)
Main PID: 655 (code=exited, status=1/FAILURE)
sh[652]: /bin/sh: 1: echo: echo: I/O error
raspberrypi systemd[1]: Started Setup zram based device zram2.
Happy new 2022 first and many thanks for the great tool - I am really addicted to it :)
Wanted to ask if any updates here? I am really frustrated as I am heavyly rely on log2ram, dont know since when log2ram is not starting due to timeout, staring time more than 2min instead of seconds, if I start log2ram manually it runs, but if I create directories in /var/log, they are gone afterwards (seems they are not written to disk), here my logs:
Jan 1 12:20:38 raspberrypi systemd[1]: Startup finished in 5.246s (kernel) + 2min 39.356s (userspace) = 2min 44.603s.
root@raspberrypi[~] # systemctl status log2ram ● log2ram.service - Log2Ram Loaded: loaded (/etc/systemd/system/log2ram.service; enabled; vendor preset: enabled) Active: failed (Result: timeout) since Fri 2021-12-31 11:42:49 CET; 23h ago Process: 276 ExecStart=/usr/local/bin/log2ram start (code=killed, signal=TERM) Main PID: 276 (code=killed, signal=TERM)
log2ram 144M 33M 112M 23% /var/log => NO /var/hdd.log
Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades-shutdown.log.2.gz Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades-shutdown.log.3.gz Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades-shutdown.log.4.gz Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades-shutdown.log.5.gz Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades-shutdown.log.6.gz Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades.log Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades.log.1.gz Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades.log.2.gz Dec 31 11:42:50 raspberrypi log2ram[276]: unattended-upgrades/unattended-upgrades.log.3.gz Jan 01 11:21:39 raspberrypi systemd[1]: log2ram.service: Unit cannot be reloaded because it is inactive.
dmesg [ 130.870620] systemd[1]: log2ram.service: Start operation timed out. Terminating. [ 130.872632] systemd[1]: log2ram.service: Main process exited, code=killed, status=15/TERM [ 130.873040] systemd[1]: log2ram.service: Failed with result 'timeout'. [ 130.875143] systemd[1]: Failed to start Log2Ram.
start manually root@raspberrypi[~] # systemctl status log2ram ● log2ram.service - Log2Ram Loaded: loaded (/etc/systemd/system/log2ram.service; enabled; vendor preset: enabled) Active: active (exited) since Sat 2022-01-01 11:25:00 CET; 4s ago Process: 2489 ExecStart=/usr/local/bin/log2ram start (code=exited, status=0/SUCCESS) Main PID: 2489 (code=exited, status=0/SUCCESS)
log2ram 144M 33M 112M 23% /var/hdd.log log2ram 144M 33M 112M 23% /var/log
apt list log2ram log2ram/oldstable,now 1.6.0 all [installed]
Problem is I cant fresh install log2ram, afterwards most of the logs in /var/log are gone
My log2ram.conf: SIZE=144M USE_RSYNC=true MAIL=true PATH_DISK="/var/log" ZL2R=false COMP_ALG=lz4 LOG_DISK_SIZE=360M
Help here is really needed and appreciated
Thx, Mike
Jan 1 12:20:38 raspberrypi systemd[1]: Startup finished in 5.246s (kernel) + 2min 39.356s (userspace) = 2min 44.603s
disabling server log2ram: Jan 1 13:02:44 raspberrypi systemd[1]: Startup finished in 5.269s (kernel) + 38.442s (userspace) = 43.712s.
I am runnin Debian Buster - Linux 5.10.63-v7+ armv7l, ii log2ram 1.6.0 all ramlog like for systemd (Put log into a ram folder)
add. info: I can manually start log2ram via sudo systemctl start log2ram, aferwards it is running:
log2ram 144M 35M 110M 24% /var/hdd.log log2ram 144M 35M 110M 24% /var/log
mount | grep -i log2ram log2ram on /var/log type tmpfs (rw,nosuid,nodev,noexec,noatime,size=147456k,mode=755) log2ram on /var/hdd.log type tmpfs (rw,nosuid,nodev,noexec,noatime,size=147456k,mode=755) log2ram on /var/log type tmpfs (rw,nosuid,nodev,noexec,noatime,size=147456k,mode=755)
so what is causing this startup crash??????
[ 10.819898] systemd[1]: Starting Log2Ram... [ 130.975678] systemd[1]: log2ram.service: Start operation timed out. Terminating. [ 130.976959] systemd[1]: log2ram.service: Main process exited, code=killed, status=15/TERM [ 130.977368] systemd[1]: log2ram.service: Failed with result 'timeout'. [ 130.979386] systemd[1]: Failed to start Log2Ram.
Timeout apprently. Maybe log2ram is waiting for something to set up? But that "something" is also waiting for log2ram?
I just obverse a strange thing into your output.
You have multiple tmpfs mount point on /var/log and /var/hdd.log. Only /var/log should have one (and only one)
Can you paste here the output of :
cat /etc/fstabcat /etc/log2ram.conf | grep PATH_DISK
Sorry for the delay, coding is a hobby I don't have at the moment.
Thx for coming back @azlux :) and no worries, really appreciate ur support here is the output
cat /etc/fstab proc /proc proc defaults 0 0 PARTUUID=738a4d67-01 /boot vfat defaults 0 2 PARTUUID=738a4d67-02 / ext4 defaults,noatime 0 1
cat /etc/log2ram.conf | grep PATH_DISK PATH_DISK="/var/log"
that one is "killing" me :) dmesg [ 130.870620] systemd[1]: log2ram.service: Start operation timed out. Terminating. [ 130.872632] systemd[1]: log2ram.service: Main process exited, code=killed, status=15/TERM [ 130.873040] systemd[1]: log2ram.service: Failed with result 'timeout'. [ 130.875143] systemd[1]: Failed to start Log2Ram.
Just my 2cp. As already said, if log2ram can be started without issues after the boot it means that there is a dependency that is slowing it down for some reasons. Therefore it's all about finding what is causing the timeout.
In this view I'd suggest to check with systemd-analyze.
This command will generate a nice svg chart of the full systemd boot timings:
systemd-analyze plot >bootup.svg
And this will tell you the critical path to the final target (it does not include the full dependency tree, but only the dependencies that are actually delaying the path):
systemd-analyze critical-chain
Also you can specify a unit to the last command, thus if you run systemd-analyze critical-chain log2ram.service you should get something like
The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.
log2ram.service +1.931s
└─var-log.mount @7.353s
└─dev-zram0.device @7.030s
And finally this one will produce a dot format output of the dependencies of log2ram.service:
systemd-analyze dot 'log2ram.service'
I think the output is already readable, but if you want it is possible to generate an SVG chart of it running the output through dot:
systemd-analyze dot 'log2ram.service' | dot -Tsvg >log2ram.svg
Note: to be able to render the chart you need the graphviz package. That can be installed with apt install graphviz.
This should help in reducing the number of possible causes.
I had what I thought was this same issue and found https://github.com/azlux/log2ram/issues/146 where log2ram errors if you try to use a directory off the root. I had added /tmp to my path list and that was causing the error. Once I removed it the problem went away. Adding the comment in the hope that it narrows down this fix a bit.
thx for the hint, but my /etc/log2ram.conf in that case looks clean: PATH_DISK="/var/log"
+1 for me. For all of you: try to start a failed log2ram-boot via
systemctl start log2ram
and reboot. For me the very next boot is often ok(!) but successive boots fail(!). So it seems that an installed log2ram does have timing/start sequencing problems and fails to start (look at start messages, it shows
A start job is configured for log2ram
and counts up to 2min.)
Starting log2ram manually "repairs" things and things run as expected including next boot. Then something gets lost again...
This may meet observations where remove/reinstalls repair log2ram...
Another hint: just restarting log2ram often doesn't solve the mount problem of /log into zram. A mount -a does (for me).
I've got two SVGs (faild and ok) but didn't find any hint to an error (but the root cause may be invisible for my knowledge). But according to my experience it seems to be a systemd dependency that is yet unresolved and is triggered by timing constellations that may vary from boot to boot / device to device.
I digged a little bit deeper and now I can confirm that the rsync call in syncFromDisk() does not come back. This causes the timeout.
No idea why this is so. cp is the offered alternative. What are the drawbacks to use cp instead?