System Log on SD card with logrotate not working

[fractal-duck]

Hello, first post here, but have been using OpenWrt for a long time, but still a relative newbie to Linux.

Router/AP ZyXEL NBG6817 (aka Armor_Z2)
Currently using 22.03.2, initially configured/tested with 21.02.0.

I want to establish system logging to an SD card attached to the USB2 port. I followed the User Guides and was able to setup the SD card and change the log path, as well as setup logrotate to run every day with a configuration to rotate on the 1st of the month and retain 12 log files.

However, I have a problem that the on the 1st of each month a new system.log is created and the old one is archived to system.log.1 (and all older ones are incremented to the next sequence number), but the log contents of system.log remains empty (0 byte length). Using a logread shows current logs, and restarting the log service starts writing new logs to the file, but the contents of the log buffer are lost.

What are the best practices to achieve my goals of:

1. Having the logging always go to the sdcard on reboot/logrotate with no log data loss
2. Maintaining monthly log files for 12 periods/1 year
3. Setting a 10 MB limit on log file size to override the monthly break point as needed

Also, is there a command to "flush" the log buffer to the file prior/during log service restart?

Here are the configurations I believe are relevant:

package fstab

config global
        option anon_swap '0'
        option anon_mount '0'
        option auto_swap '1'
        option auto_mount '1'
        option delay_root '5'
        option check_fs '0'
...
config mount
        option target '/mnt/sda1'
        option uuid 'ed726797-f7da-452e-94b8-bd96e5d01a2d'
        option enabled '1'

package system

config system
        option ttylogin '0'
        option urandom_seed '0'
        option timezone 'EST5EDT,M3.2.0,M11.1.0'
        option zonename 'America/New York'
        option hostname 'Armor_Z2'
        option log_buffer_size '256'
        option log_size '10240'
        option log_type 'file'
        option log_remote '0'
        option log_file '/mnt/sda1/logs/system.log'

cat /etc/logrotate.conf
weekly

# keep 4 weeks worth of backlogs
rotate 4

# create new (empty) log files after rotating old ones
create

notifempty
nomail
missingok

#System log on SD card
/mnt/sda1/logs/system.log {
    monthly
    rotate 12
    missingok
}

crontab -l
0 0 1 * * /usr/sbin/logrotate /etc/logrotate.conf
1 0 1 * * service log restart

I have been checking on the logs and manually issuing a service log restart command, which explains why the times on the logs do not match the cron schedule.

ls -l -h /mnt/sda1/logs
-rw-------    1 root     root        1.1M Oct 29 11:08 system.log
-rw-------    1 root     root       48.1M Oct  2 17:03 system.log.1
-rw-------    1 root     root        2.9M Aug  1 18:30 system.log.2
-rw-------    1 root     root        3.1M Jul  2 18:33 system.log.3
-rw-------    1 root     root        1.6M Jun  1 20:12 system.log.4
-rw-------    1 root     root        2.8M May 15 09:32 system.log.5
-rw-------    1 root     root        2.5M Apr  5  2022 system.log.6
-rw-------    1 root     root       10.0M Feb 24  2022 system.log.7

I have noticed in the kernel log that the SD card is detected early in the process (11s) but does not mount until later (50s), probably because it is waiting for the filing system module (kmod-fs-f2fs?) to load. This may explain why on device restart the log does not go to the file, but does not explain the logging gap using logrotate.

[   11.371799] scsi 0:0:0:0: Direct-Access     SanDisk' Cruzer Fit       1.00 PQ: 0 ANSI: 6
[   11.375956] sd 0:0:0:0: [sda] 60088320 512-byte logical blocks: (30.8 GB/28.7 GiB)
[   11.381692] sd 0:0:0:0: [sda] Write Protect is off
[   11.386336] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[   11.388852] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[   11.423216]  sda: sda1
[   11.427878] sd 0:0:0:0: [sda] Attached SCSI removable disk
[   11.804016] block: attempting to load /etc/config/fstab
[   11.804234] block: unable to load configuration (fstab: Entry not found)
[   11.808117] block: no usable configuration
[   11.816563] mount_root: switching to ext4 overlay

[   50.707426] F2FS-fs (sda1): Mounted with checkpoint version = 634e1666

[   82.198567] kmodloader: done loading kernel modules from /etc/modules.d/*

Thank you,
Chris

[fractal-duck]

SOLVED
When logrotate renames the old files and creates the new file, logd continues to log to the same file, now renamed system.log.1. A restart of logd is required to switch to the new file. During the restart there is a very small time period where a new log could be lost.

I think my problem was with the 2 cron jobs. I created a shell script that creates a separate log and captures the state of the log folder, /var/lib/logrotate.status, runs logrotate in verbose mode, sleeps for 5 seconds, and then creates a log message. I changed my log config to a daily interval to test and ran the script manually, and observed it working. I then updated crontab to call the script instead, and the next day it rotated the logs and switched over.

I think this solves my problem, but I have to confirm that logging to the file still functions after a reboot.

[boardlord1]

Could you share that script? I'm in the same boat

[fractal-duck]

Here you go, with a few important points before you use it:

• Most of the script contains echo, cat, and ls statements redirected to a log file to help me debug what is happening. You can remove most/all of them to suit your taste.
• The 2 variables (this_log and logrotate_log) must set to match your log folder path.
• I have not tested a router restart to see what happens to the log. This has nothing to do with logrotate, but I suspect for my router/config that logd may start before SD is mounted. I may have to tinker with another script that runs late in startup to dump the buffer to the log file and then restart logd.

/etc/log_rotate.sh

#!/bin/sh
# Setup 2 log files, 1 for this script, another for logrotate
this_log=/mnt/sda1/logs/log_rotate.log
logrotate_log=/mnt/sda1/logs/logrotate.log

echo >>${this_log}
echo "**************************************************">>${this_log}
date >>${this_log}
echo "current user is $USER" >>${this_log}

# Log state of files and logrotate status
echo >>${this_log}
ls -l -h /mnt/sda1/logs/system.* >>${this_log}

echo >>${this_log}
cat /var/lib/logrotate.status >>${this_log}

# Call log rotate and redirect STDERR and STDOUT to a dedicated log file
echo "**************************************************">>${logrotate_log}
date >>${logrotate_log}
echo >>${logrotate_log}
logrotate -v /etc/logrotate.conf 2>&1 | tee -a >>${logrotate_log} 
#>/dev/null

# Capture logrotate status to see if any changes were made
echo >>${this_log}
cat /var/lib/logrotate.status >>${this_log}

# Restart the log service and wait 5 seconds to allow for restart to complete
echo >>${this_log}
echo "service log restarting" >>${this_log}
logger log_rotate "service log restarting"

service log restart
sleep 5 

# Create a test message, which can be grepped from logread and system.log to verify all is working
echo >>${this_log}
echo "service log restarted" >>${this_log}
logger log_rotate "service log restarted"

My new crontab:
0 0 1 * * sh /etc/log_rotate.sh

To test this without waiting another month, I changed /etc/logrotate.conf to rotate daily (keep 30) to test, and then modified cron to run the job a few minutes later.

After the time elapsed I ran the following commands to confirm it had switched over to the new file. Note that the log buffer gets reset by the service restart, so you see the restarted message but not the restarting message. The latter is the last message in the old log file (now system.log.1).

cat /mnt/sda1/logs/system.log.1 | grep log_rotate
Wed Nov  2 07:25:00 2022 cron.err crond[16554]: USER root pid 16685 cmd sh /etc/log_rotate.sh
Wed Nov  2 07:25:00 2022 user.notice root: log_rotate service log restarting

cat /mnt/sda1/logs/system.log | grep log_rotate
Wed Nov  2 07:25:05 2022 user.notice root: log_rotate service log restarted

logread | grep log_rotate
Wed Nov  2 07:25:05 2022 user.notice root: log_rotate service log restarted

Here are the logs from the successful rotation:

log_rotate.log

**************************************************
Wed Nov  2 07:25:00 EDT 2022
current user is root

-rw-------    1 root     root       95.8K Nov  2 07:25 /mnt/sda1/logs/system.log
-rw-------    1 root     root        1.3M Nov  1 07:21 /mnt/sda1/logs/system.log.1
-rw-------    1 root     root       48.1M Oct  2 17:03 /mnt/sda1/logs/system.log.2
-rw-------    1 root     root        2.9M Aug  1 18:30 /mnt/sda1/logs/system.log.3
-rw-------    1 root     root        3.1M Jul  2 18:33 /mnt/sda1/logs/system.log.4
-rw-------    1 root     root        1.6M Jun  1 20:12 /mnt/sda1/logs/system.log.5
-rw-------    1 root     root        2.8M May 15 09:32 /mnt/sda1/logs/system.log.6
-rw-------    1 root     root        2.5M Apr  5  2022 /mnt/sda1/logs/system.log.7
-rw-------    1 root     root       10.0M Feb 24  2022 /mnt/sda1/logs/system.log.8

logrotate state -- version 2
"/mnt/sda1/logs/system.log" 2022-11-1-7:12:2

logrotate state -- version 2
"/mnt/sda1/logs/system.log" 2022-11-2-7:25:0

service log restarting

service log restarted

logrotate.log

**************************************************
Wed Nov  2 07:25:00 EDT 2022

reading config file /etc/logrotate.conf
including /etc/logrotate.d
warning: 'daily' overrides previously specified 'weekly'
Reading state from file: /var/lib/logrotate.status
Allocating hash table for state file, size 64 entries
Creating new state

Handling 1 logs

rotating pattern: /mnt/sda1/logs/system.log  after 1 days (30 rotations)
empty log files are not rotated, old logs are removed
considering log /mnt/sda1/logs/system.log
  Now: 2022-11-02 07:25
  Last rotated at 2022-11-01 07:12
  log needs rotating
rotating log /mnt/sda1/logs/system.log, log->rotateCount is 30
dateext suffix '-20221102'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /mnt/sda1/logs/system.log.30 to /mnt/sda1/logs/system.log.31 (rotatecount 30, logstart 1, i 30), 
old log /mnt/sda1/logs/system.log.30 does not exist
renaming /mnt/sda1/logs/system.log.29 to /mnt/sda1/logs/system.log.30 (rotatecount 30, logstart 1, i 29), 
old log /mnt/sda1/logs/system.log.29 does not exist
renaming /mnt/sda1/logs/system.log.28 to /mnt/sda1/logs/system.log.29 (rotatecount 30, logstart 1, i 28), 
old log /mnt/sda1/logs/system.log.28 does not exist
renaming /mnt/sda1/logs/system.log.27 to /mnt/sda1/logs/system.log.28 (rotatecount 30, logstart 1, i 27), 
old log /mnt/sda1/logs/system.log.27 does not exist
renaming /mnt/sda1/logs/system.log.26 to /mnt/sda1/logs/system.log.27 (rotatecount 30, logstart 1, i 26), 
old log /mnt/sda1/logs/system.log.26 does not exist
renaming /mnt/sda1/logs/system.log.25 to /mnt/sda1/logs/system.log.26 (rotatecount 30, logstart 1, i 25), 
old log /mnt/sda1/logs/system.log.25 does not exist
renaming /mnt/sda1/logs/system.log.24 to /mnt/sda1/logs/system.log.25 (rotatecount 30, logstart 1, i 24), 
old log /mnt/sda1/logs/system.log.24 does not exist
renaming /mnt/sda1/logs/system.log.23 to /mnt/sda1/logs/system.log.24 (rotatecount 30, logstart 1, i 23), 
old log /mnt/sda1/logs/system.log.23 does not exist
renaming /mnt/sda1/logs/system.log.22 to /mnt/sda1/logs/system.log.23 (rotatecount 30, logstart 1, i 22), 
old log /mnt/sda1/logs/system.log.22 does not exist
renaming /mnt/sda1/logs/system.log.21 to /mnt/sda1/logs/system.log.22 (rotatecount 30, logstart 1, i 21), 
old log /mnt/sda1/logs/system.log.21 does not exist
renaming /mnt/sda1/logs/system.log.20 to /mnt/sda1/logs/system.log.21 (rotatecount 30, logstart 1, i 20), 
old log /mnt/sda1/logs/system.log.20 does not exist
renaming /mnt/sda1/logs/system.log.19 to /mnt/sda1/logs/system.log.20 (rotatecount 30, logstart 1, i 19), 
old log /mnt/sda1/logs/system.log.19 does not exist
renaming /mnt/sda1/logs/system.log.18 to /mnt/sda1/logs/system.log.19 (rotatecount 30, logstart 1, i 18), 
old log /mnt/sda1/logs/system.log.18 does not exist
renaming /mnt/sda1/logs/system.log.17 to /mnt/sda1/logs/system.log.18 (rotatecount 30, logstart 1, i 17), 
old log /mnt/sda1/logs/system.log.17 does not exist
renaming /mnt/sda1/logs/system.log.16 to /mnt/sda1/logs/system.log.17 (rotatecount 30, logstart 1, i 16), 
old log /mnt/sda1/logs/system.log.16 does not exist
renaming /mnt/sda1/logs/system.log.15 to /mnt/sda1/logs/system.log.16 (rotatecount 30, logstart 1, i 15), 
old log /mnt/sda1/logs/system.log.15 does not exist
renaming /mnt/sda1/logs/system.log.14 to /mnt/sda1/logs/system.log.15 (rotatecount 30, logstart 1, i 14), 
old log /mnt/sda1/logs/system.log.14 does not exist
renaming /mnt/sda1/logs/system.log.13 to /mnt/sda1/logs/system.log.14 (rotatecount 30, logstart 1, i 13), 
old log /mnt/sda1/logs/system.log.13 does not exist
renaming /mnt/sda1/logs/system.log.12 to /mnt/sda1/logs/system.log.13 (rotatecount 30, logstart 1, i 12), 
old log /mnt/sda1/logs/system.log.12 does not exist
renaming /mnt/sda1/logs/system.log.11 to /mnt/sda1/logs/system.log.12 (rotatecount 30, logstart 1, i 11), 
old log /mnt/sda1/logs/system.log.11 does not exist
renaming /mnt/sda1/logs/system.log.10 to /mnt/sda1/logs/system.log.11 (rotatecount 30, logstart 1, i 10), 
old log /mnt/sda1/logs/system.log.10 does not exist
renaming /mnt/sda1/logs/system.log.9 to /mnt/sda1/logs/system.log.10 (rotatecount 30, logstart 1, i 9), 
old log /mnt/sda1/logs/system.log.9 does not exist
renaming /mnt/sda1/logs/system.log.8 to /mnt/sda1/logs/system.log.9 (rotatecount 30, logstart 1, i 8), 
renaming /mnt/sda1/logs/system.log.7 to /mnt/sda1/logs/system.log.8 (rotatecount 30, logstart 1, i 7), 
renaming /mnt/sda1/logs/system.log.6 to /mnt/sda1/logs/system.log.7 (rotatecount 30, logstart 1, i 6), 
renaming /mnt/sda1/logs/system.log.5 to /mnt/sda1/logs/system.log.6 (rotatecount 30, logstart 1, i 5), 
renaming /mnt/sda1/logs/system.log.4 to /mnt/sda1/logs/system.log.5 (rotatecount 30, logstart 1, i 4), 
renaming /mnt/sda1/logs/system.log.3 to /mnt/sda1/logs/system.log.4 (rotatecount 30, logstart 1, i 3), 
renaming /mnt/sda1/logs/system.log.2 to /mnt/sda1/logs/system.log.3 (rotatecount 30, logstart 1, i 2), 
renaming /mnt/sda1/logs/system.log.1 to /mnt/sda1/logs/system.log.2 (rotatecount 30, logstart 1, i 1), 
renaming /mnt/sda1/logs/system.log.0 to /mnt/sda1/logs/system.log.1 (rotatecount 30, logstart 1, i 0), 
old log /mnt/sda1/logs/system.log.0 does not exist
log /mnt/sda1/logs/system.log.31 doesn't exist -- won't try to dispose of it
renaming /mnt/sda1/logs/system.log to /mnt/sda1/logs/system.log.1
creating new /mnt/sda1/logs/system.log mode = 0600 uid = 0 gid = 0

[tart]

Here's an alternative using just logrotate.conf:

include /etc/logrotate.d

/mnt/sda1/logs/system.log {
    monthly
    rotate 12
    missingok
    notifempty
    postrotate
        service log restart
        sleep 1
        logger -p warn -s "Log rotation complete."
    endscript
}

Then in crontab:

0 0 1 * * logrotate /etc/logrotate.conf