nightly system crash: caused by armbian-truncate-logs ?

[EwaldC]

Since at least one week I find the system every morning with solid red led, waiting for a command in uboot.

When looking at the journal messages, the last messages are always:

Feb 10 23:45:01 etnas2 CRON[5176]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 10 23:45:01 etnas2 CRON[5177]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Feb 10 23:45:01 etnas2 CRON[5176]: pam_unix(cron:session): session closed for user root
Feb 11 00:00:01 etnas2 CRON[5213]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 11 00:00:01 etnas2 CRON[5212]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 11 00:00:01 etnas2 CRON[5215]: (root) CMD (/usr/lib/armbian/armbian-apt-updates)
Feb 11 00:00:01 etnas2 CRON[5214]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Feb 11 00:00:01 etnas2 CRON[5212]: pam_unix(cron:session): session closed for user root
Feb 11 00:00:03 etnas2 CRON[5213]: pam_unix(cron:session): session closed for user root
Feb 11 00:00:49 etnas2 systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service...
Feb 11 00:00:49 etnas2 systemd[1]: Starting logrotate.service - Rotate log files...
Feb 11 00:00:49 etnas2 systemd[1]: dpkg-db-backup.service: Deactivated successfully.
Feb 11 00:00:49 etnas2 systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service.
Feb 11 00:00:49 etnas2 armbian-ramlog[5278]: Tue Feb 11 12:00:49 AM CET 2025: Syncing logs to storage
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: sending incremental file list
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: ./
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: Xorg.0.log
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: Xorg.0.log.old
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: armbian-hardware-monitor.log
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: auth.log
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: boot.log
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: btmp
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: cron.log
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: kern.log
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: lastlog
Feb 11 00:00:49 etnas2 armbian-ramlog[5281]: syslog
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: user.log
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: wtmp
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: cups/access_log
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: lightdm/
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: lightdm/lightdm.log
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: lightdm/lightdm.log.old
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: lightdm/seat0-greeter.log
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: lightdm/seat0-greeter.log.old
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: lightdm/x-0.log
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: lightdm/x-0.log.old
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: samba/log.nmbd
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: samba/log.smbd
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: sent 3,469,661 bytes  received 448 bytes  2,313,406.00 bytes/sec
Feb 11 00:00:50 etnas2 armbian-ramlog[5281]: total size is 4,794,812  speedup is 1.38
Feb 11 00:00:50 etnas2 systemd-journald[588]: Time spent on flushing to /var/log/journal/1141762e43884d8b9eb5d35b11be4daa is 55.926ms for 1057 entries.
Feb 11 00:00:50 etnas2 systemd-journald[588]: System Journal (/var/log/journal/1141762e43884d8b9eb5d35b11be4daa) is 17.4M, max 20.0M, 2.5M free.
Feb 11 00:00:50 etnas2 systemd-journald[588]: Received client request to flush runtime journal.
Feb 11 00:00:50 etnas2 systemd-journald[588]: Data hash table of /var/log/journal/1141762e43884d8b9eb5d35b11be4daa/system.journal has a fill level at 122.2 (5561 of 4551 items, 2621440 file size, 471 bytes per hash table item), suggesting rotation.
Feb 11 00:00:50 etnas2 systemd-journald[588]: /var/log/journal/1141762e43884d8b9eb5d35b11be4daa/system.journal: Journal header limits reached or header out-of-date, rotating.

 

After that no more messages, until the system gets booted again.   The issue seems similar to this post.  Power supply and system temperatures are fine, the system is running from EMMC memory so issues with  SD cards are ruled out.  When I boot off e.g. Jonathan Riek's Ubuntu 24.04 using the NVME drive, then all is fine: no nightly crashes.  I don't recall this issue when I installed Armbian 24.11.2 back in December, so possibly it came when I upgraded to 24.11.3 using `apt upgrade` (but could be wrong!)

 

I have added the cron job `*/1 * * * * /usr/bin/dmesg > $HOME/kernel-dmesg.txt` as suggested.

 

Looking at `/etc/cron.d` and more precisely `armbian-trunctate-log`, I see that `armbian-trunctate-logs` runs every 15 minutes, but it invokes `armbian-ramlog` in practice only just after mignight probably because `/var/log` is over 75% full.  Then `/usr/lib/armbian/armbian-truncate-logs` proceeds to synchronize (using `rsysnc`)  the logs files in zram (`/var/log`).     

After that, the script calls `/usr/sbin/logrotate --force /etc/logrotate.conf` but this rotation takes place on `/var/log.hdd/`. 

Somehow that does not sound right...  I would have thought it would be the other way around....

Finally, it just truncates the files in `/var/log`.   That could be dangerous as processes have these files open...  Logrotate sends a signal to processes to let them know they should reopen the log files. 

 

armbianmonitor -u

 

Thanks in advance for any help.

[EwaldC]

I disabled ram logging and as expected the problem went away.  For an EMMC based system it is less beneficial anyway.

 

1. Changed /etc/default/armbian-ramlog (disable ramlog)

ENABLED=false

2. Comment out cron root user truncate-logs by editing `/etc/cron.d/armbian-truncate-logs`.  Probably not needed but since this runs every 15 minutes it is creating quite some journal logs.

# 0,15,30,45 * * * * root /usr/lib/armbian/armbian-truncate-logs

3. Comment out /etc/cron.daily/armbian-ram-logging:

#!/bin/sh
#/usr/lib/armbian/armbian-ramlog write >/dev/null 2>&1

4. Restart system.

 

If this is stable for a week and survives systemd based logrotate, I will re-enable ramlog and try to find out where is goes wrong. 

[rcr]

Hi, EwaldC!

 

I had the same issue with Debian Bookworm and Ubuntu Noble on my Cubietruck. I've disabled ram logging as you describe and have 3 days uptime. Thank you for solution. Please let know if you figure out how to get ram logging working without crashes.

 

Best regards

rcr

 

[EwaldC]

Hi rcr,

 

Sorry to say, but I have not been able to fix the problem.   IMHO there are 3 areas where there could be potential problems that explain the hangs...

• File Descriptors and Log Files:

If a kernel driver or a kernel module is writing to a log file (e.g., via printk or a custom logging mechanism), and logrotate moves or deletes that log file, the driver might continue writing to the old file descriptor. This could lead to logs being written to a deleted file or lost until the file descriptor is refreshed (e.g., by restarting the driver or the logging service), but if improperly handled could cause a crash.

• Resource Deplation:

Logrotate, when configured to compress very large log files, consumes significant CPU or I/O resources.   It could cause a watchdog to time out.  When zram is involved, the load will be higher because zram is faster than disk access

• Custom kernel driver logging:

If a kernel driver uses a custom logging mechanism that interacts with user-space log files (e.g. via a custom device file), improper handling of log rotation could cause issues. For example, if the driver expects the log file to exist and it doesn't, it might fail or behave unexpectedly.  I suspect it might be related to a driver in the 6.12.x kernel that comes with these releases.  For Rockchip 3588 I have not seen the issue with the vendor drivers (5.10, 6.1).