View previous topic :: View next topic |
Author |
Message |
pa4wdh l33t
Joined: 16 Dec 2005 Posts: 811
|
Posted: Sun May 08, 2022 9:30 am Post subject: Logrotate broke syslog-ng |
|
|
Hi All,
During last night logrotate did it's job and unfortunately that broke syslog-ng in the lxc that is my mailserver (postfix/dovecot). That might not immediately be the end of the world, but it caused all processes that try to log to hang. As a result i could not log in via ssh, could not restart any process, mails could not be delivered and cron jobs stalled.
Some checks i have done during this situation:
- Disk space was ok (it's a 10GB luks volume, 2.5GB free)
- The rotation in itself seemed to be successful, the old /var/log/messages got suffixed with the date and a new /var/log/messages was created with 0 bytes
- syslog-ng was running, but the pid number was very low, which might be an indication it didn't actually stop (not conclusive of course since PIDs get reused)
- I ran strace -f /etc/init.d/sshd restart which showed start-stop-daemon to hang on opening the /dev/log socket
- As soon as i manually killed syslog-ng all hanging processes continued to do what they intended to do
- After /etc/init.d/syslog-ng zap i could /etc/init.d/syslog-ng start without issues or warnings
- A logrotate was also done a week ago with all software at the same versions and there was no problem that time
My syslog-ng setup is very basic, this is the version and use flags:
Code: |
[ebuild R ] app-admin/syslog-ng-3.35.1::gentoo USE="ipv6 -amqp -caps -dbi -geoip2 -http -json -kafka -mongodb -pacct -python -redis -smtp -snmp -spoof-source -systemd -tcpd -test" PYTHON_SINGLE_TARGET="python3_9 -python3_8 -python3_10" 0 KiB
|
It's configuration is default (comments removed for brevity):
Code: |
@version: 3.35
@include "scl.conf"
options {
threaded(yes);
chain_hostnames(no);
stats_freq(43200);
mark_freq(3600);
};
source src { system(); internal(); };
destination messages { file("/var/log/messages"); };
log { source(src); destination(messages); };
|
Has anyone else seen similar problems? And maybe more important: Is there a way to prevent it from happening? _________________ The gentoo way of bringing peace to the world:
USE="-war" emerge --newuse @world
My shared code repository: https://code.pa4wdh.nl.eu.org
Music, Free as in Freedom: https://www.jamendo.com |
|
Back to top |
|
|
freke l33t
Joined: 23 Jan 2003 Posts: 976 Location: Somewhere in Denmark
|
Posted: Sun May 08, 2022 3:31 pm Post subject: |
|
|
Never experienced that - you do have something like Code: | /var/log/messages {
delaycompress
missingok
sharedscripts
postrotate
/etc/init.d/syslog-ng reload > /dev/null 2>&1 || true
endscript
} | somewhere in your logrotate configuration? |
|
Back to top |
|
|
pa4wdh l33t
Joined: 16 Dec 2005 Posts: 811
|
Posted: Sun May 08, 2022 5:41 pm Post subject: |
|
|
Yes, my logrotate config for syslog-ng is also default:
Code: |
/var/log/messages {
delaycompress
missingok
sharedscripts
postrotate
/etc/init.d/syslog-ng reload > /dev/null 2>&1 || true
endscript
}
|
I also found something in the logs which might be part of the symptoms.
When the logrotate is successful the last lines of the rotated log file are:
Code: |
May 1 03:09:02 lxc-mail start-stop-daemon[5119]: Will stop PID 822
May 1 03:09:02 lxc-mail start-stop-daemon[5119]: Sending signal 1 to PID 822
|
In the unsuccessful rotate the last line is only:
Code: |
May 8 03:09:01 lxc-mail start-stop-daemon[6095]: Will stop PID 822
|
Where PID 822 was syslog-ng before i manually restarted it.
Maybe there is/was a bug in syslog-ng but which triggers when the HUP signal is send? _________________ The gentoo way of bringing peace to the world:
USE="-war" emerge --newuse @world
My shared code repository: https://code.pa4wdh.nl.eu.org
Music, Free as in Freedom: https://www.jamendo.com |
|
Back to top |
|
|
freke l33t
Joined: 23 Jan 2003 Posts: 976 Location: Somewhere in Denmark
|
Posted: Mon May 09, 2022 7:22 am Post subject: |
|
|
pa4wdh wrote: | I also found something in the logs which might be part of the symptoms.
When the logrotate is successful the last lines of the rotated log file are:
Code: |
May 1 03:09:02 lxc-mail start-stop-daemon[5119]: Will stop PID 822
May 1 03:09:02 lxc-mail start-stop-daemon[5119]: Sending signal 1 to PID 822
|
In the unsuccessful rotate the last line is only:
Code: |
May 8 03:09:01 lxc-mail start-stop-daemon[6095]: Will stop PID 822
|
Where PID 822 was syslog-ng before i manually restarted it.
Maybe there is/was a bug in syslog-ng but which triggers when the HUP signal is send? |
Actually I think logrotate/start-stop-daemon didn't send the signal to syslog-ng - wouldn't the 'Sending signal 1 to PID' be there if it did send the signal? |
|
Back to top |
|
|
pa4wdh l33t
Joined: 16 Dec 2005 Posts: 811
|
Posted: Mon May 09, 2022 1:16 pm Post subject: |
|
|
The problem is that we don't know ...
It could be that start-stop-daemon indeed didn't send the signal
It could also be that start-stop-daemon did send the signal but the log message was not recorded because of the problem with syslog-ng
The log messages from syslog-ng which indicate the arrival of the signal are usually written to the next log file, which didn't happen because of the problem _________________ The gentoo way of bringing peace to the world:
USE="-war" emerge --newuse @world
My shared code repository: https://code.pa4wdh.nl.eu.org
Music, Free as in Freedom: https://www.jamendo.com |
|
Back to top |
|
|
pa4wdh l33t
Joined: 16 Dec 2005 Posts: 811
|
Posted: Tue May 10, 2022 8:53 am Post subject: |
|
|
I've been looking at the code for start-stop-daemon and syslog-ng to see if there is anything obvious i can find. I didn't find anything related to the problem i was seeing, but i did see something interesting in syslog-ng's code:
Right now when logrotate wants syslog-ng to re-open the log files it calls /etc/init.d/syslog-ng reload. The initscript sends the HUP signal to syslog-ng via start-stop-daemon.
The HUP signal triggers syslog-ng to re-read it's configuration files and re-open all output files. Judging from the amount of code involved this is a pretty complex process.
I found syslog-ng also triggers on the USR1 signal, and then it only re-opens all output files. This seems pretty straight-forward and easy.
Wouldn't it be better to let logrotate use the USR1 signal? _________________ The gentoo way of bringing peace to the world:
USE="-war" emerge --newuse @world
My shared code repository: https://code.pa4wdh.nl.eu.org
Music, Free as in Freedom: https://www.jamendo.com |
|
Back to top |
|
|
pa4wdh l33t
Joined: 16 Dec 2005 Posts: 811
|
Posted: Mon Jun 27, 2022 5:20 pm Post subject: |
|
|
Today this happened again. Since my last post in this topic there have been successful rotates June 5th, June 12th, June 19th (and probably earlier but those files are deleted) and it broke again yesterday.
I've now changed /etc/logrotate.d/syslog-ng to:
Code: |
/var/log/messages {
delaycompress
missingok
sharedscripts
postrotate
killall -USR1 syslog-ng
endscript
}
|
To see if using USR1 fixes the problem.
Is anyone else seeing similar behavior? _________________ The gentoo way of bringing peace to the world:
USE="-war" emerge --newuse @world
My shared code repository: https://code.pa4wdh.nl.eu.org
Music, Free as in Freedom: https://www.jamendo.com |
|
Back to top |
|
|
gentoo_ram Guru
Joined: 25 Oct 2007 Posts: 474 Location: San Diego, California USA
|
Posted: Tue Jun 28, 2022 12:27 am Post subject: |
|
|
Maybe something to do with the output of the init script? I see a couple other examples of getting syslog-ng to re-open files in my logrotate directory. Maybe try the other form by using '-q' as an argument to the script. I think that turns off logging.
Code: | gateway:/etc/logrotate.d$ grep syslog-ng *
dovecot: /etc/init.d/syslog-ng -q reload
maillog: /etc/init.d/syslog-ng -q reload
messages: /etc/init.d/syslog-ng reload > /dev/null 2>&1 || true
smartd: /etc/init.d/syslog-ng -q reload
|
|
|
Back to top |
|
|
Goverp Veteran
Joined: 07 Mar 2007 Posts: 1998
|
Posted: Tue Jun 28, 2022 7:22 am Post subject: |
|
|
Mine works fine with the default /etc/logrotate.d/sylog-ng file. While digging, I note that /etc/logrotate.conf has a line Code: | include /etc/logrotate.d | I wonder if that's gotten lost? _________________ Greybeard |
|
Back to top |
|
|
pa4wdh l33t
Joined: 16 Dec 2005 Posts: 811
|
Posted: Tue Jun 28, 2022 5:03 pm Post subject: |
|
|
Quote: | Maybe something to do with the output of the init script? I see a couple other examples of getting syslog-ng to re-open files in my logrotate directory. Maybe try the other form by using '-q' as an argument to the script. I think that turns off logging. |
That's an interesting suggestion. One thing i've been thinking about is that this could be some kind of race condition because of the output (the syslog message which has to be processed on one hand, syslog-ng (which has to process that message) which is restarted on the other).
Quote: | I wonder if that's gotten lost? |
The line is there, the rotation itself is done, it's just hat syslog-ng hangs afterwards which hangs every process that wants to send messages to syslog-ng.
Anyway, it might take a while before we know if the problem is solved now, as you can see from the time between my posts there is almost 1,5 month between the two occurrences of the problem ... _________________ The gentoo way of bringing peace to the world:
USE="-war" emerge --newuse @world
My shared code repository: https://code.pa4wdh.nl.eu.org
Music, Free as in Freedom: https://www.jamendo.com |
|
Back to top |
|
|
pa4wdh l33t
Joined: 16 Dec 2005 Posts: 811
|
Posted: Sun Dec 18, 2022 12:23 pm Post subject: |
|
|
It has been almost half a year since the last time this happened, so i think it's quite save to say that my modification to the logrotate configuration solved the problem. _________________ The gentoo way of bringing peace to the world:
USE="-war" emerge --newuse @world
My shared code repository: https://code.pa4wdh.nl.eu.org
Music, Free as in Freedom: https://www.jamendo.com |
|
Back to top |
|
|
|