Bug#988652: logrotate: kern.log,syslog and other files in /var/log not rotating

[UN-pi]

Package: logrotate
Version: 3.14.0-4
Severity: normal
Tags: newcomer

Dear Maintainer,

I noticed that some log files in /var/log are not being rotated.
e.g. kern.log, syslog etc.
There are no files ending with .1 or .gz. The files keep getting bigger.

I found on the internet:
https://askubuntu.com/questions/695999/var-log-syslog-not-rotating.

After I make the change it seems to work.
Extract from the website:
"
Based on Samuel's comment, modified /usr/lib/rsyslog/rsyslog-rotate
#!/bin/sh

if [-d /run/systemd/system]; then
systemctl kill -s HUP --kill-who = main rsyslog.service
else
invoke-rc.d rsyslog rotate> /dev/null
fi
"

Is it a bug or do I have an understanding problem somewhere?


-- Package-specific info:
Contents of /etc/logrotate.d
total 100
-rw-r--r-- 1 root root 120 Apr 19 2019 alternatives
-rw-r--r-- 1 root root 442 Jun 18 2020 apache2
-rw-r--r-- 1 root root 173 May 28 2019 apt
-rw-r--r-- 1 root root 79 Feb 13 2019 aptitude
-rw-r--r-- 1 root root 297 Aug 20 2019 asterisk
-rw-r--r-- 1 root root 130 Aug 29 2018 btmp
-rw-r--r-- 1 root root 82 May 26 2018 certbot
-rw-r--r-- 1 root root 112 Apr 19 2019 dpkg
-rw-r--r-- 1 root root 313 Apr 4 2018 fail2ban
-rw-r--r-- 1 root root 234 Mar 1 2018 iaxmodem
-rw-r--r-- 1 root root 419 Jan 28 2019 lighttpd
-rw-r--r-- 1 root root 97 Jun 18 2020 log2ram
-rw-r--r-- 1 root root 802 Jan 29 2020 mysql-server
-r--r--r-- 1 root root 111 May 15 07:45 ncp
-rw-r--r-- 1 root root 182 Nov 11 2020 openvpn
-rw-r--r-- 1 root root 155 Oct 26 2019 php7.3-fpm
-rw-r--r-- 1 root root 1029 Jan 25 2019 psaccs_atop
-rw-r--r-- 1 root root 541 Jan 25 2019 psaccu_atop
-rw-r--r-- 1 root root 124 Jul 10 2019 redis-server
-rw-r--r-- 1 root root 501 Feb 26 2019 rsyslog
-rw-r--r-- 1 root root 891 Sep 2 2019 samba
-rw-r--r-- 1 root root 188 Jun 15 2020 ufw
-rw-r--r-- 1 root root 235 Jun 8 2019 unattended-upgrades
-rw-r--r-- 1 root root 305 Sep 2 2019 winbind
-rw-r--r-- 1 root root 145 Feb 19 2018 wtmp


-- System Information:
Debian Release: 10.9
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: arm64 (aarch64)
Foreign Architectures: armhf

Kernel: Linux 5.10.17-v8+ (SMP w/4 CPU cores; PREEMPT)
Kernel taint flags: TAINT_CRAP
Locale: LANG=de_DE.UTF-8, LC_CTYPE=de_DE.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to de_DE.UTF-8), LANGUAGE=de_DE.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to de_DE.UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages logrotate depends on:
ii cron [cron-daemon] 3.0pl1-134+deb10u1
ii libacl1 2.2.53-4
ii libc6 2.28-10
ii libpopt0 1.16-12
ii libselinux1 2.8-1+b1
ii systemd-sysv 241-7~deb10u7

Versions of packages logrotate recommends:
ii bsd-mailx [mailx] 8.1.2-0.20180807cvs-1

logrotate suggests no packages.

-- no debconf information

[Christian Göttsche]

Control: notfixed -1 logrotate/3.18.0-2
Control: reassign -1 src:rsyslog
Control: tags -1 -newcomer
Control: affects -1 logrotate

Post by UN-pi
I noticed that some log files in /var/log are not being rotated.
e.g. kern.log, syslog etc.
There are no files ending with .1 or .gz. The files keep getting bigger.

Are there any relevant logs from logrotate (i.e. `journalctl -u logrotate`)?
Do you still have a system with this issue and be able to run
`logrotate -v /etc/logrotate.conf` on it?

Post by UN-pi
https://askubuntu.com/questions/695999/var-log-syslog-not-rotating.
After I make the change it seems to work.
"
Based on Samuel's comment, modified /usr/lib/rsyslog/rsyslog-rotate
#!/bin/sh
if [-d /run/systemd/system]; then
systemctl kill -s HUP --kill-who = main rsyslog.service
else
invoke-rc.d rsyslog rotate> /dev/null
fi
"
Is it a bug or do I have an understanding problem somewhere?

I am not quite sure why changing this script resolved your issue, it
might solve rsyslog writing to the old log files but logrotate should
have created a `.1` file.

As the configuration of kern.log and syslog in
/etc/logrotate.d/rsyslog and the script
/usr/lib/rsyslog/rsyslog-rotate are part of src:rsyslog, I am
reassigning the bug.


p.s.: the tag newcomer is meant for bugs to be resolved by newcomers,
see https://www.debian.org/Bugs/Developer#tags

[Michael Biebl]

On Tue, 18 May 2021 14:10:08 +0200 =?UTF-8?Q?Christian_G=C3=B6ttsche?=

Post by UN-pi
Based on Samuel's comment, modified /usr/lib/rsyslog/rsyslog-rotate
#!/bin/sh
if [-d /run/systemd/system]; then
systemctl kill -s HUP --kill-who = main rsyslog.service
else
invoke-rc.d rsyslog rotate> /dev/null
fi
"
Is it a bug or do I have an understanding problem somewhere?

What exactly did you change in the script? Please post a diff (or the
file before and after the modifications you did).

[UN-pi]

Post by Michael Biebl
On Tue, 18 May 2021 14:10:08 +0200 =?UTF-8?Q?Christian_G=C3=B6ttsche?=

Post by UN-pi
Based on Samuel's comment, modified /usr/lib/rsyslog/rsyslog-rotate
#!/bin/sh
if [-d /run/systemd/system]; then
systemctl kill -s HUP --kill-who = main rsyslog.service
else
invoke-rc.d rsyslog rotate> /dev/null
fi
"
Is it a bug or do I have an understanding problem somewhere?

What exactly did you change in the script? Please post a diff (or the
file before and after the modifications you did).

This is my actual file:

#!/bin/sh
#based on
#https://askubuntu.com/questions/695999/var-log-syslog-not-rotating

#if [ -d /run/systemd/system ]; then
#    systemctl kill -s HUP rsyslog.service
#else
#    invoke-rc.d rsyslog rotate > /dev/null
#fi

if [ -d /run/systemd/system ]; then
    systemctl kill -s HUP --kill-who=main rsyslog.service
else
    invoke-rc.d rsyslog rotate > /dev/null
fi

-----------------------------
 logrotate -v /etc/logrotate.conf        is running

 journalctl -u logrotate                         says:

-- Logs begin at Sat 2021-05-15 07:00:01 CEST, end at Tue 2021-05-18
14:51:27 CEST. --
Mai 16 00:00:01 debian64 systemd[1]: Starting Rotate log files...
Mai 16 00:00:03 debian64 systemd[1]: logrotate.service: Succeeded.
Mai 16 00:00:03 debian64 systemd[1]: Started Rotate log files.
Mai 17 00:00:01 debian64 systemd[1]: Starting Rotate log files...
Mai 17 00:00:03 debian64 systemd[1]: logrotate.service: Succeeded.
Mai 17 00:00:03 debian64 systemd[1]: Started Rotate log files.
Mai 18 00:00:01 debian64 systemd[1]: Starting Rotate log files...
Mai 18 00:00:02 debian64 systemd[1]: logrotate.service: Succeeded.
Mai 18 00:00:02 debian64 systemd[1]: Started Rotate log files.

It is the first time that I have made such a report via reportbug.
I can only hope that I comply with the reporting rules to some extent.

[Michael Biebl]

Post by UN-pi

Post by Michael Biebl
What exactly did you change in the script? Please post a diff (or the
file before and after the modifications you did).

#!/bin/sh
#based on
#https://askubuntu.com/questions/695999/var-log-syslog-not-rotating
#if [ -d /run/systemd/system ]; then
#    systemctl kill -s HUP rsyslog.service
#else
#    invoke-rc.d rsyslog rotate > /dev/null
#fi
if [ -d /run/systemd/system ]; then
    systemctl kill -s HUP --kill-who=main rsyslog.service
else
    invoke-rc.d rsyslog rotate > /dev/null
fi

What was the file before the change (i.e. the file which triggered this
problem)?

[Michael Biebl]

[please always CC the bug report on replies]

---------------------------------------
#!/bin/sh
if [ -d /run/systemd/system ]; then
    systemctl kill -s HUP rsyslog.service
else
    invoke-rc.d rsyslog rotate > /dev/null
fi
------------------------------------------
I commented out the lines with #
and added a memo for me for UNDO reasons.
-----------------------------------------
#!/bin/sh
#based on
#https://askubuntu.com/questions/695999/var-log-syslog-not-rotating
#if [ -d /run/systemd/system ]; then
#    systemctl kill -s HUP rsyslog.service
#else
#    invoke-rc.d rsyslog rotate > /dev/null
#fi
if [ -d /run/systemd/system ]; then
     systemctl kill -s HUP --kill-who=main rsyslog.service
else
     invoke-rc.d rsyslog rotate > /dev/null
fi
---------------
So I added :       --kill-who=main
--------------

Ok, thanks for the additional information. I don't see how this is going
to fix your issue though. Typically, rsyslog only has a single process,
so using main or all shouldn't really make any difference.

If you run "systemctl status rsyslog.service", does it show more then
one process? Can you paste the output please.

[Michael Biebl]

Post by Michael Biebl

Post by UN-pi
---------------
So I added :       --kill-who=main
--------------

Ok, thanks for the additional information. I don't see how this is going
to fix your issue though. Typically, rsyslog only has a single process,
so using main or all shouldn't really make any difference.
If you run "systemctl status rsyslog.service", does it show more then
one process? Can you paste the output please.

Fwiw, adding --kill-who=main is probably not a bad idea in itself and it
probably makes sense to do so. But I don't see, how this is fixing your
issue.

[UN-pi]

"systemctl status rsyslog.service" say:

 rsyslog.service - System Logging Service
   Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor
preset: enabled)
   Active: active (running) since Wed 2021-05-12 17:27:41 CEST; 5 days ago
     Docs: man:rsyslogd(8)
           https://www.rsyslog.com/doc/
 Main PID: 302 (rsyslogd)
    Tasks: 4 (limit: 1968)
   CGroup: /system.slice/rsyslog.service
           └─302 /usr/sbin/rsyslogd -n -iNONE

Mai 16 00:00:03 debian64 rsyslogd[302]:  [origin software="rsyslogd"
swVersion="8.1901.0" x-pid="302" x-info="https://www.rsyslog.com"]
rsyslogd was HUPed
Mai 16 00:00:03 debian64 rsyslogd[302]:  [origin software="rsyslogd"
swVersion="8.1901.0" x-pid="302" x-info="https://www.rsyslog.com"]
rsyslogd was HUPed
Mai 17 00:00:03 debian64 rsyslogd[302]:  [origin software="rsyslogd"
swVersion="8.1901.0" x-pid="302" x-info="https://www.rsyslog.com"]
rsyslogd was HUPed
Mai 18 00:00:02 debian64 rsyslogd[302]:  [origin software="rsyslogd"
swVersion="8.1901.0" x-pid="302" x-info="https://www.rsyslog.com"]
rsyslogd was HUPed
Warning: Journal has been rotated since unit was started. Log output is
incomplete or unavailable.

--------------

The htop-program has 1 main task and 3 childs.

[Michael Biebl]

 rsyslog.service - System Logging Service
   Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor
preset: enabled)
   Active: active (running) since Wed 2021-05-12 17:27:41 CEST;5 days ago
     Docs: man:rsyslogd(8)
           https://www.rsyslog.com/doc/
 Main PID: 302 (rsyslogd)
    Tasks: 4 (limit: 1968)
   CGroup: /system.slice/rsyslog.service
           └─302 /usr/sbin/rsyslogd -n -iNONE

Ok, so you have single process. I don't see how --kill-who=main is going
to make a difference here.

[Michael Biebl]

Post by Michael Biebl

  rsyslog.service - System Logging Service
    Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor
preset: enabled)
    Active: active (running) since Wed 2021-05-12 17:27:41 CEST;5 days
ago
      Docs: man:rsyslogd(8)
            https://www.rsyslog.com/doc/
  Main PID: 302 (rsyslogd)
     Tasks: 4 (limit: 1968)
    CGroup: /system.slice/rsyslog.service
            └─302 /usr/sbin/rsyslogd -n -iNONE

Ok, so you have single process. I don't see how --kill-who=main is going
to make a difference here.

Could you switch back to the original version without "--kill-who=main"

and verify that this reintroduces the problem for you?

[UN-pi]

Yes, it is very easy.But I think that I will only be able to see in a
few days whether the old behavior will return.Please be patient.

Post by Michael Biebl

Post by Michael Biebl

  rsyslog.service - System Logging Service
    Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor
preset: enabled)
    Active: active (running) since Wed 2021-05-12 17:27:41 CEST;5 days
ago
      Docs: man:rsyslogd(8)
            https://www.rsyslog.com/doc/
  Main PID: 302 (rsyslogd)
     Tasks: 4 (limit: 1968)
    CGroup: /system.slice/rsyslog.service
            └─302 /usr/sbin/rsyslogd -n -iNONE

Ok, so you have single process. I don't see how --kill-who=main is going
to make a difference here.

Could you switch back to the original version without "--kill-who=main"
and verify that this reintroduces the problem for you?

[UN-pi]

I found this in the internet:

https://github.com/rsyslog/rsyslog/issues/3952

I will give it a try by changing

|#!/bin/sh if [ -d /run/systemd/system ]; then systemctl kill -s HUP
rsyslog.service else invoke-rc.d rsyslog rotate > /dev/null fi to ||#!/bin/sh if [ -d /run/systemd/system ]; then ||killall -HUP rsyslogd else ||killall -HUP rsyslogd fi Then I manually restarted the rsyslog.service
and startet journalctl --rotate. I will see. |||

[Michael Biebl]

Post by UN-pi
https://github.com/rsyslog/rsyslog/issues/3952
I will give it a try by changing
|#!/bin/sh if [ -d /run/systemd/system ]; then systemctl kill -s HUP
rsyslog.service else invoke-rc.d rsyslog rotate > /dev/null fi to ||#!/bin/sh if [ -d /run/systemd/system ]; then ||killall -HUP rsyslogd else ||killall -HUP rsyslogd fi Then I manually restarted the rsyslog.service
and startet journalctl --rotate. I will see. |||

While you can test this, I'm certainly not going to use "killall" in
logrotate.d/rsyslog, as it is dangerous.

[UN-pi]

The actual situation is today the same than yesterday.
The system is writing to the old files.

using a

   systemctl kill -s HUP --kill-who=main rsyslog.service

didn't help. The system was still writing to the old syslog.1-file while the new syslog content's kern.log messages.
Only a

    pkill -HUP rsyslogd

helped.

the kernel is

  Linux debian64 5.10.17-v8+ #1414 SMP PREEMPT Fri Apr 30 13:23:25 BST
2021 aarch64 GNU/Linux

cat /etc/os-release

PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

----------------------
Looking on a second server with the original

/usr/lib/rsyslog/rsyslog-rotate -version

and kernel

Linux localhost 4.19.0-16-amd64 #1 SMP Debian 4.19.181-1 (2021-03-19) x86_64 GNU/Linux

cat /etc/os-release

PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

Here everything works fine.

[Michael Biebl]

Post by UN-pi
The actual situation is today the same than yesterday.
The system is writing to the old files.
using a
   systemctl kill -s HUP --kill-who=main rsyslog.service
didn't help.

Ok, that is good, I guess. I would have been suprised if it
--kill-who=main would have made a difference.

The system was still writing to the old syslog.1-file while the new
syslog content's kern.log messages.

Post by UN-pi
Only a
    pkill -HUP rsyslogd
helped.

I think what you see here is a race condition (i.e. another instance of
#720096) and pkill probably slightly changes the timing of how the HUP
signal is delivered.

I suppose
https://salsa.debian.org/debian/rsyslog/-/commit/651236c2319eb0ca13fd1d376eaf239a6dcd5c49
would help as well in you case.

Michael

[Michael Biebl]

Maybe a helpful  idea/reason/solution for the problem?
https://debianforum.de/forum/viewtopic.php?f=32&t=180761&hilit=syslog

Similar symptoms, different cause afaics.

[UN-pi]

With the removed delaycompress-option it is working a little bit better :

-rw-r-----  1 root adm                   0 Mai 22 00:00 kern.log
-rw-r-----  1 root     adm               17152 Mai 21 18:02 kern.log.1.gz
-rw-rw-r--  1 root     utmp             298368 Mai 22 02:29 lastlog
drwx------  2 root     root               4096 Mai 22 00:55 letsencrypt
drwxr-x---  2 www-data www-data           4096 Mai 21 05:31 lighttpd
-rw-r-----  1 root     adm                   0 Okt 18  2020 mail.err
-rw-r-----  1 root     adm                 867 Mai 22 01:00 mail.info
-rw-r-----  1 root     adm                 462 Mai 21 17:54 mail.info.1.gz
-rw-r-----  1 root     adm                 867 Mai 22 01:00 mail.log
-rw-r-----  1 root     adm                 462 Mai 21 17:54 mail.log.1.gz
-rw-r-----  1 root     adm                   0 Mai 22 00:00 mail.warn
-rw-r-----  1 root     adm                 142 Mai 21 17:54 mail.warn.1.gz
-rw-r-----  1 root     adm                 154 Mai 22 00:00 messages
-rw-r-----  1 root     adm               17462 Mai 21 21:09 messages.1.gz
drwxr-s---  2 mysql    adm                4096 Mai 22 00:00 mysql
-rw-r-----  1 root     www-data           1042 Mai 22 02:00 ncp.log
drwxr-xr-x  2 root     root               4096 Feb 20  2019 openvpn
-rw-r-----  1 root     adm               54483 Mai 22 02:28 openvpn.log
-rw-------  1 root     root                669 Mai 22 02:38
openvpn-status.log
-rw-r--r--  1 root     root               2516 Feb 15 07:22 pcas.txt
-rw-------  1 root     root                186 Mai 21 21:21 php7.3-fpm.log
drwxr-xr-x  2 pihole   pihole             4096 Jun 15  2020 pihole
-rw-r--r--  1 pihole   pihole                0 Mai 22 00:00 pihole-FTL.log
-rw-r--r--  1 pihole   pihole            11945 Mai 22 00:00 pihole-FTL.log.1
-rw-r--r--  1 pihole   pihole                0 Mai 22 00:00 pihole.log
-rw-r--r--  1 pihole   pihole             2156 Mai 22 00:00 pihole.log.1
-rw-r--r--  1 root     root               9908 Mai 16 03:11
pihole_updateGravity.log
-rw-r--r--  1 root     root              48265 Mai 15 18:34
popularity-contest
-rw-r--r--  1 root     root              16226 Mai 15 18:34
popularity-contest.new.gpg
drwx------  2 root     root               4096 Mai 27  2020 private
drwxr-s---  2 redis    adm                4096 Mai 21 05:31 redis
-rw-r-----  1 root     adm               23506 Mai 22 01:54 rng.log
drwxr-x---  3 root     adm                4096 Mai 18 05:47 samba
-rw-r-----  1 root     adm               16815 Mai 22 02:36 syslog
-rw-r-----  1 root     adm               51224 Mai 22 00:00 syslog.1.gz


syslog is starting with:

May 22 00:00:02 debian64 rsyslogd:  [origin software="rsyslogd"
swVersion="8.1901.0" x-pid="6765" x-info="https://www.rsyslog.com"]
rsyslogd was HUPed
May 22 00:00:02 debian64 systemd[1]: logrotate.service: Succeeded.
May 22 00:00:02 debian64 systemd[1]: Started Rotate log files.
May 22 00:00:02 debian64 systemd[1]: man-db.service: Succeeded.
May 22 00:00:02 debian64 systemd[1]: Started Daily man-db regeneration.
May 22 00:01:01 debian64 CRON[10633]: (root) CMD (/root/checkipv6.sh >
/dev/null 2>&1)
May 22 00:02:01 debian64 CRON[10647]: (root) CMD (/root/checkwebmin.sh >
/dev/null 2>&1)
May 22 00:05:01 debian64 CRON[10671]: (www-data) CMD (php -f
/var/www/nextcloud/cron.php)

Notice: The man-db-regeneration succeeded BEFORE starting.

I noticed that there are NEW log-entries in the OLD-syslog.1.gz-file
which belong to the new day.

May 21 23:59:01 debian64 CRON[10390]: (daemon) CMD (test -x
/usr/bin/debsecan && /usr/bin/debsecan --cron)
May 22 00:00:01 debian64 systemd[1]: Starting Daily man-db regeneration...
May 22 00:00:01 debian64 systemd[1]: Starting Rotate log files...
May 22 00:00:01 debian64 systemd[1]: Reloading The Apache HTTP Server.
May 22 00:00:01 debian64 systemd[1]: Reloaded The Apache HTTP Server.
May 22 00:00:01 debian64 CRON[10559]: (root) CMD (
PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole flush once quiet)
May 22 00:00:01 debian64 CRON[10564]: (root) CMD (
PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
May 22 00:00:01 debian64 CRON[10565]: (www-data) CMD (php -f
/var/www/nextcloud/cron.php)
May 22 00:00:01 debian64 CRON[10567]: (root) CMD
(/root/checkfritzreboot.sh > /dev/null 2>&1)
May 22 00:00:01 debian64 CRON[10568]: (root) CMD (/root/check6tunnel.sh

/dev/null 2>&1)

[Michael Biebl]

I adjusted the settings for /etc/logrotate.d/rsyslog
-------------------------------------------
/var/log/syslog
/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
{
        rotate 4
        daily
        missingok
        notifempty
        compress
        delaycompress
        sharedscripts
        postrotate
                /usr/lib/rsyslog/rsyslog-rotate
        endscript
}
based on
https://salsa.debian.org/debian/rsyslog/-/commit/651236c2319eb0ca13fd1d376eaf239a6dcd5c49 <https://salsa.debian.org/debian/rsyslog/-/commit/651236c2319eb0ca13fd1d376eaf239a6dcd5c49>
an with "daily".
-rw-r-----  1 root     adm                 606 Mai 21 04:30 messages
-rw-r-----  1 root     adm                4404 Mai 21 04:00 messages.1
-rw-r-----  1 root     adm                 606 Mai 21 04:30 syslog
-rw-r-----  1 root     adm              131397 Mai 21 04:55 syslog.1

syslog.1 is newer then syslog. So some log messages ended up in syslog,
but rsyslog then continued to write to syslog.1 ?
If you were referring to that problem, can you share what has been
written to syslog and syslog.1?

[UN-pi]

Post by Michael Biebl
syslog.1 is newer then syslog. So some log messages ended up in syslog,
but rsyslog then continued to write to syslog.1 ?
If you were referring to that problem, can you share what has been
written to syslog and syslog.1?

Please take a look on my message from Sat, 22 May 2021 03:18:01 +0200,
where I uploaded parts of syslog und syslog.1.

The protocols look similar today.The entries in syslog.1 do not end at
midnight.

[Eneko Lacunza]

Hi,

We have a VM with this issue happening right now.

ii  rsyslog        8.2102.0-2+deb11u1 amd64        reliable system and
kernel logging daemon

VM is uptodate with latest security patches.

I only list syslog/user but other log files have the same issue:

# ls -l /var/log/syslog*
-rw-r----- 1 root adm 51352703 feb 27 12:56 /var/log/syslog
-rw-r----- 1 root adm     4175 feb 17 13:45 /var/log/syslog.4.gz
-rw-r----- 1 root adm 76150956 feb 17 13:29 /var/log/syslog.5.gz

# ls -l /var/log/user*
-rw-r----- 1 root adm 436103 feb 22 17:09 /var/log/user.log
-rw-r----- 1 root adm 425984 ene 16  2185 /var/log/user.log.1
-rw-r----- 1 root adm   5703 may 12  2022 /var/log/user.log.2.gz
-rw-r----- 1 root adm   2357 abr 19  2022 /var/log/user.log.3.gz
-rw-r----- 1 root adm   1753 abr 11  2022 /var/log/user.log.4.gz

We have forced various rotations last week. Notice there is a wrong year
in user.log.1 . I tried fixing that without result:

# ls -l /var/log/user*
-rw-r----- 1 root adm 436103 feb 22 17:09 /var/log/user.log
-rw-r----- 1 root adm 425984 ene 16 03:20 /var/log/user.log.1
-rw-r----- 1 root adm   5703 may 12  2022 /var/log/user.log.2.gz
-rw-r----- 1 root adm   2357 abr 19  2022 /var/log/user.log.3.gz
-rw-r----- 1 root adm   1753 abr 11  2022 /var/log/user.log.4.gz


# logrotate -v /etc/logrotate.d/rsyslog
reading config file /etc/logrotate.d/rsyslog
Reading state from file: /var/lib/logrotate/status
Allocating hash table for state file, size 64 entries
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state

Handling 1 logs

rotating pattern: /var/log/syslog
/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
 weekly (4 rotations)
empty log files are not rotated, old logs are removed
considering log /var/log/syslog
  Now: 2023-02-27 13:01
  Last rotated at 2023-02-27 12:47
  log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/mail.info
  log /var/log/mail.info does not exist -- skipping
considering log /var/log/mail.warn
  log /var/log/mail.warn does not exist -- skipping
considering log /var/log/mail.err
  log /var/log/mail.err does not exist -- skipping
considering log /var/log/mail.log
  log /var/log/mail.log does not exist -- skipping
considering log /var/log/daemon.log
  Now: 2023-02-27 13:01
  Last rotated at 2023-02-27 12:47
  log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/kern.log
  Now: 2023-02-27 13:01
  Last rotated at 2023-02-27 12:47
  log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/auth.log
  Now: 2023-02-27 13:01
  Last rotated at 2023-02-27 12:47
  log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/user.log
  Now: 2023-02-27 13:01
  Last rotated at 2023-02-27 12:47
  log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/lpr.log
  log /var/log/lpr.log does not exist -- skipping
considering log /var/log/cron.log
  log /var/log/cron.log does not exist -- skipping
considering log /var/log/debug
  Now: 2023-02-27 13:01
  Last rotated at 2023-02-27 12:47
  log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/messages
  Now: 2023-02-27 13:01
  Last rotated at 2023-02-27 12:47
  log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
not running postrotate script, since no logs were rotated

She thinks syslog has been rotated, but it is obvious that it wasn't :)

Our (I think unchanged) /etc/logrotate.d/rsyslog:


# cat /etc/logrotate.d/rsyslog
/var/log/syslog
/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
{
    rotate 4
    weekly
    missingok
    notifempty
    compress
    delaycompress
    sharedscripts
    postrotate
        /usr/lib/rsyslog/rsyslog-rotate
    endscript
}


Thanks

Eneko Lacunza
Zuzendari teknikoa | Director técnico
Binovo IT Human Project

Tel. [phone] | https://www.binovo.es
Astigarragako Bidea, 2 - 2º izda. Oficina 10-11, 20180 Oiartzun

https://www.youtube.com/user/CANALBINOVO
https://www.linkedin.com/company/37269706/

[Christian Göttsche]

Post by Eneko Lacunza
Hi,
We have a VM with this issue happening right now.
ii rsyslog 8.2102.0-2+deb11u1 amd64 reliable system and
kernel logging daemon

From the rsyslog version I assume you are using logrotate version
3.18.0-2+deb11u1.

Post by Eneko Lacunza
VM is uptodate with latest security patches.
# ls -l /var/log/syslog*
-rw-r----- 1 root adm 51352703 feb 27 12:56 /var/log/syslog

syslog.{1,2,3}.gz are missing

Post by Eneko Lacunza
-rw-r----- 1 root adm 4175 feb 17 13:45 /var/log/syslog.4.gz
-rw-r----- 1 root adm 76150956 feb 17 13:29 /var/log/syslog.5.gz
# ls -l /var/log/user*
-rw-r----- 1 root adm 436103 feb 22 17:09 /var/log/user.log
-rw-r----- 1 root adm 425984 ene 16 2185 /var/log/user.log.1

My only guesses for the timestamp are be either a gzip issue or a power outage.

Post by Eneko Lacunza
-rw-r----- 1 root adm 5703 may 12 2022 /var/log/user.log.2.gz
-rw-r----- 1 root adm 2357 abr 19 2022 /var/log/user.log.3.gz
-rw-r----- 1 root adm 1753 abr 11 2022 /var/log/user.log.4.gz
We have forced various rotations last week. Notice there is a wrong year
# ls -l /var/log/user*
-rw-r----- 1 root adm 436103 feb 22 17:09 /var/log/user.log
-rw-r----- 1 root adm 425984 ene 16 03:20 /var/log/user.log.1
-rw-r----- 1 root adm 5703 may 12 2022 /var/log/user.log.2.gz
-rw-r----- 1 root adm 2357 abr 19 2022 /var/log/user.log.3.gz
-rw-r----- 1 root adm 1753 abr 11 2022 /var/log/user.log.4.gz
# logrotate -v /etc/logrotate.d/rsyslog
reading config file /etc/logrotate.d/rsyslog
Reading state from file: /var/lib/logrotate/status
Allocating hash table for state file, size 64 entries
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Handling 1 logs
rotating pattern: /var/log/syslog
/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
weekly (4 rotations)
empty log files are not rotated, old logs are removed
considering log /var/log/syslog
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)

So logrotate thinks the log has been rotated at 2023-02-27 12:47 due
to this date being stored in the state file
(/var/lib/logrotate/status).
Did you manually run logrotate then? Did you modify the state file manually?

Also assuming you are using systemd, are there any errors or relevant
messages in `journalctl -u logrotate.service`?

Please also verify logrotate is acutally enabled and running
(`systemctl status logrotate.timer`).

Post by Eneko Lacunza
considering log /var/log/mail.info
log /var/log/mail.info does not exist -- skipping
considering log /var/log/mail.warn
log /var/log/mail.warn does not exist -- skipping
considering log /var/log/mail.err
log /var/log/mail.err does not exist -- skipping
considering log /var/log/mail.log
log /var/log/mail.log does not exist -- skipping
considering log /var/log/daemon.log
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/kern.log
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/auth.log
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/user.log
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/lpr.log
log /var/log/lpr.log does not exist -- skipping
considering log /var/log/cron.log
log /var/log/cron.log does not exist -- skipping
considering log /var/log/debug
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
considering log /var/log/messages
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)
not running postrotate script, since no logs were rotated
She thinks syslog has been rotated, but it is obvious that it wasn't :)
# cat /etc/logrotate.d/rsyslog
/var/log/syslog
/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
{
rotate 4
weekly
missingok
notifempty
compress
delaycompress
sharedscripts
postrotate
/usr/lib/rsyslog/rsyslog-rotate
endscript
}
Thanks
Eneko Lacunza
Zuzendari teknikoa | Director técnico
Binovo IT Human Project
Tel. [phone] | https://www.binovo.es
Astigarragako Bidea, 2 - 2º izda. Oficina 10-11, 20180 Oiartzun
https://www.youtube.com/user/CANALBINOVO
https://www.linkedin.com/company/37269706/
--

[Eneko Lacunza]

Post by Christian Göttsche

Post by Eneko Lacunza
We have a VM with this issue happening right now.
ii rsyslog 8.2102.0-2+deb11u1 amd64 reliable system and
kernel logging daemon

From the rsyslog version I assume you are using logrotate version
3.18.0-2+deb11u1.

Yes.

Post by Christian Göttsche

Post by Eneko Lacunza
VM is uptodate with latest security patches.
# ls -l /var/log/syslog*
-rw-r----- 1 root adm 51352703 feb 27 12:56 /var/log/syslog

syslog.{1,2,3}.gz are missing

Yes, when forcing the rotation those were rotated but not the
main/current log.

Post by Christian Göttsche

Post by Eneko Lacunza
-rw-r----- 1 root adm 4175 feb 17 13:45 /var/log/syslog.4.gz
-rw-r----- 1 root adm 76150956 feb 17 13:29 /var/log/syslog.5.gz
# ls -l /var/log/user*
-rw-r----- 1 root adm 436103 feb 22 17:09 /var/log/user.log
-rw-r----- 1 root adm 425984 ene 16 2185 /var/log/user.log.1

My only guesses for the timestamp are be either a gzip issue or a power outage.

Maybe some live migration crash, I can fix that if it doesn't seem
revelant to the issue.

Post by Christian Göttsche

Post by Eneko Lacunza
-rw-r----- 1 root adm 5703 may 12 2022 /var/log/user.log.2.gz
-rw-r----- 1 root adm 2357 abr 19 2022 /var/log/user.log.3.gz
-rw-r----- 1 root adm 1753 abr 11 2022 /var/log/user.log.4.gz
We have forced various rotations last week. Notice there is a wrong year
# ls -l /var/log/user*
-rw-r----- 1 root adm 436103 feb 22 17:09 /var/log/user.log
-rw-r----- 1 root adm 425984 ene 16 03:20 /var/log/user.log.1
-rw-r----- 1 root adm 5703 may 12 2022 /var/log/user.log.2.gz
-rw-r----- 1 root adm 2357 abr 19 2022 /var/log/user.log.3.gz
-rw-r----- 1 root adm 1753 abr 11 2022 /var/log/user.log.4.gz
# logrotate -v /etc/logrotate.d/rsyslog
reading config file /etc/logrotate.d/rsyslog
Reading state from file: /var/lib/logrotate/status
Allocating hash table for state file, size 64 entries
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Creating new state
Handling 1 logs
rotating pattern: /var/log/syslog
/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
weekly (4 rotations)
empty log files are not rotated, old logs are removed
considering log /var/log/syslog
Now: 2023-02-27 13:01
Last rotated at 2023-02-27 12:47
log does not need rotating (log has been rotated at 2023-02-27 12:47,
which is less than a week ago)

So logrotate thinks the log has been rotated at 2023-02-27 12:47 due
to this date being stored in the state file
(/var/lib/logrotate/status).
Did you manually run logrotate then? Did you modify the state file manually?

Yes, we did run logrotate manually, but did not modify state file manually.

Post by Christian Göttsche
Also assuming you are using systemd, are there any errors or relevant
messages in `journalctl -u logrotate.service`?

[...]
feb 25 00:00:00 monitor-cloud systemd[1]: Starting Rotate log files...
feb 25 00:00:00 monitor-cloud systemd[1]: logrotate.service: Succeeded.
feb 25 00:00:00 monitor-cloud systemd[1]: Finished Rotate log files.
feb 26 00:00:02 monitor-cloud systemd[1]: Starting Rotate log files...
feb 26 00:00:02 monitor-cloud logrotate[2500662]: error: Compressing
program wrote following message to stderr when compressing log
/var/log/user.log.1:
feb 26 00:00:02 monitor-cloud logrotate[2500662]: gzip: stdin: warning:
file timestamp out of range for gzip format
feb 26 00:00:02 monitor-cloud logrotate[2500662]: error: failed to
compress log /var/log/user.log.1
feb 26 00:00:02 monitor-cloud systemd[1]: logrotate.service: Main
process exited, code=exited, status=1/FAILURE
feb 26 00:00:02 monitor-cloud systemd[1]: logrotate.service: Failed with
result 'exit-code'.
feb 26 00:00:02 monitor-cloud systemd[1]: Failed to start Rotate log files.
feb 27 00:00:00 monitor-cloud systemd[1]: Starting Rotate log files...
feb 27 00:00:00 monitor-cloud systemd[1]: logrotate.service: Succeeded.
feb 27 00:00:00 monitor-cloud systemd[1]: Finished Rotate log files.
[...]

It only seems anoyed with the strange date in user.log.1 , last logs a
replication of the logs of 27th.

Post by Christian Göttsche
Please also verify logrotate is acutally enabled and running
(`systemctl status logrotate.timer`).

# systemctl status logrotate.timer
● logrotate.timer - Daily rotation of log files
     Loaded: loaded (/lib/systemd/system/logrotate.timer; enabled;
vendor preset: enabled)
     Active: active (waiting) since Wed 2023-02-15 11:04:21 CET; 2
weeks 5 days ago
    Trigger: Tue 2023-03-07 00:00:00 CET; 7h left
   Triggers: ● logrotate.service
       Docs: man:logrotate(8)
man:logrotate.conf(5)

Warning: journal has been rotated since unit was started, output may be
incomplete.

Thanks


EnekoLacunza

Director Técnico | Zuzendari teknikoa

Binovo IT Human Project

943 569 206 <tel:[phone]>

***@binovo.es <mailto:***@binovo.es>

binovo.es <//binovo.es>

Astigarragako Bidea, 2 - 2 izda. Oficina 10-11, 20180 Oiartzun


youtube <https://www.youtube.com/user/CANALBINOVO/>
linkedin <https://www.linkedin.com/company/37269706/>

[Eneko Lacunza]

Hi,

The virtual machine that was having this issue, is now working correctly.

We did nothing (that we are aware of) to fix the issue. Server is
patched regularly, but I see no new rsyslog version installed in dpkg.log.

Thanks

Eneko Lacunza
Zuzendari teknikoa | Director técnico
Binovo IT Human Project

Tel. [phone] | https://www.binovo.es
Astigarragako Bidea, 2 - 2º izda. Oficina 10-11, 20180 Oiartzun

https://www.youtube.com/user/CANALBINOVO
https://www.linkedin.com/company/37269706/