FreeRADIUS 2.1.10 regression in logging behaviour
hi, one eagle-eyed member spotted a small issue with our systems after the upgrade to 2.1.10 (which, frankly I'd overlooked because to me its more important that people can actually authenticate and we've got good accounting etc :-) ) anyway, its this. the standard radius.log file which records a few items of interest is no longer logrotated correctly....ie logrotate comes along, the file gets a new number/name and a new file is created for radiusd to keep using...except it doesnt. in the end you end up with eg radius.log.5 radius.log.4 radius.log.3 radius.log.2 radius.log.1 radius.log where all the newer ones are zero bytes and radius.log.5 is several meg in size the sudden obvious fix is to add the HUP/restart part to the logrotate script but we've never ever had to do this in the past...and I'm loathe to do such a thing...i wonder what has changed regarding file handling ? alan
Alan Buxey wrote:
one eagle-eyed member spotted a small issue with our systems after the upgrade to 2.1.10
It's actually in 2.1.9.
the sudden obvious fix is to add the HUP/restart part to the logrotate script but we've never ever had to do this in the past...and I'm loathe to do such a thing...i wonder what has changed regarding file handling ?
You now have to HUP after logrotate. Before, it wouldn't re-open the file, even if you did HUP it. I'm not sure why you thought it was rotating the log files before... that just didn't work. It opened the log file when the server started, and never touched it again after that. Alan DeKok.
On Fri, Nov 26, 2010 at 10:46:54PM +0100, Alan DeKok wrote:
Alan Buxey wrote:
one eagle-eyed member spotted a small issue with our systems after the upgrade to 2.1.10
It's actually in 2.1.9.
the sudden obvious fix is to add the HUP/restart part to the logrotate script but we've never ever had to do this in the past...and I'm loathe to do such a thing...i wonder what has changed regarding file handling ?
You now have to HUP after logrotate.
Before, it wouldn't re-open the file, even if you did HUP it. I'm not sure why you thought it was rotating the log files before... that just didn't work. It opened the log file when the server started, and never touched it again after that.
You keep repeating this, yet a trivial git log search for the HUP change finds cf43a8261cd89829f12e69fdb066fdec8b18579c where the removed code included: [...] if (log_fp) { struct stat buf; if (stat(myconfig->log_file, &buf) < 0) { fclose(log_fp); log_fp = fr_log_fp = NULL; } } if (!log_fp && myconfig->log_file) { fp = fopen(myconfig->log_file, "a"); [...] log_fp = fp; So logrotate would move the log file away, and the next log message from FR would run this code, which would stat the existing log_fp pointing to a missing file, and proceed to close the fp and then reopen it. Please don't add insult to injury... -- 2. That which causes joy or happiness.
Josip Rodin wrote:
On Fri, Nov 26, 2010 at 10:46:54PM +0100, Alan DeKok wrote:
Before, it wouldn't re-open the file, even if you did HUP it. I'm not sure why you thought it was rotating the log files before... that just didn't work. It opened the log file when the server started, and never touched it again after that.
You keep repeating this, yet a trivial git log search for the HUP change finds cf43a8261cd89829f12e69fdb066fdec8b18579c where the removed code included: .. So logrotate would move the log file away, and the next log message from FR would run this code, which would stat the existing log_fp pointing to a missing file, and proceed to close the fp and then reopen it.
IIRC, that had issues when I tested it, which is why the code was changed. One obvious issue is that it's not thread-safe. The log file is closed for a while, and messages can be lost.
Please don't add insult to injury...
I'm not trying to. Another issue with the previous code is that it would reopen the log file only when it had a message to write. This is also arguably wrong. See http://bugs.mysql.com/bug.php?id=55711 for a similar bug. I understand that changing the behavior is unwanted, but is it really that much of a burden to HUP the server? Alan DeKok.
Hi,
I understand that changing the behavior is unwanted, but is it really that much of a burden to HUP the server?
yes. and if i read this mailing list history I see plenty of posts saying dont HUP it...I dont think all parts of the server update/refresh when HUP'ing still so a full restart is the only clean way anyway. I understand the issues with thread-safe in this context - surely whats needed is a logging thread message handler/parser that the subthreads talk to - like Apache et al do for their log handling? alan
On Sat, Nov 27, 2010 at 09:06:08AM +0000, Alan Buxey wrote:
I see plenty of posts saying dont HUP it...I dont think all parts of the server update/refresh when HUP'ing still so a full restart is the only clean way anyway.
With regard to log rotation, that's actually contrary to what it should do :) The HUP not only reopens log files, but it also reopens the configuration. But if you have a configuration file that the unprivileged FR user can't read, esp. if it's radiusd.conf :) the reload will fail, and it also won't be able to reopen log files. IOW for the purpose of log rotation, we didn't need HUP because it's too invasive for that purpose. But a configuration reload in general is useful and HUP seems like the most appropriate method. -- 2. That which causes joy or happiness.
Josip Rodin wrote:
With regard to log rotation, that's actually contrary to what it should do :) The HUP not only reopens log files, but it also reopens the configuration. But if you have a configuration file that the unprivileged FR user can't read, esp. if it's radiusd.conf :) the reload will fail, and it also won't be able to reopen log files.
The fix there is to *not* reload the config if it's done an suid.
IOW for the purpose of log rotation, we didn't need HUP because it's too invasive for that purpose. But a configuration reload in general is useful and HUP seems like the most appropriate method.
Another fix would be to add a "radmin" command to re-open just the log files. Either patch is small, and both would be useful. Alan DeKok.
On 2010/11/27 01:32 PM, Alan DeKok wrote:
Another fix would be to add a "radmin" command to re-open just the log files.
Squid does something similar. "squid -l logrotate" reopens the log files. -- Johan Meiring Cape PC Services CC Tel: (021) 883-8271 Fax: (021) 886-7782
Alan Buxey wrote:
yes. and if i read this mailing list history I see plenty of posts saying dont HUP it...I dont think all parts of the server update/refresh when HUP'ing still so a full restart is the only clean way anyway. I understand the issues with thread-safe in this context - surely whats needed is a logging thread message handler/parser that the subthreads talk to - like Apache et al do for their log handling?
Sure. As always, patches are welcome. Right now, I've got many other things on my plate, including features needed for eduroam. :) Alan DeKok.
Alan Buxey <A.L.M.Buxey@lboro.ac.uk> wrote:
...surely whats needed is a logging thread message handler/parser that the subthreads talk to - like Apache et al do for their log handling?
Or to start logging to a central syslog service? Cheers -- Alexander Clouter .sigmonster says: HELP! MY TYPEWRITER IS BROKEN! -- E. E. CUMMINGS
Alan Buxey <A.L.M.Buxey@lboro.ac.uk> wrote:
Or to start logging to a central syslog service?
hmm, log to a disk or throw a packet out onto the network using UDP and hope that it gets to the destination and the remote logger is working. lets see...... ;-)
Raw and traditional UDP syslog is not the only option. You could also syslog to a local daemon... Cheers -- Alexander Clouter .sigmonster says: BOFH excuse #10: hardware stress fractures
On Sat, Nov 27, 2010 at 04:53:40AM +0100, Alan DeKok wrote:
I understand that changing the behavior is unwanted, but is it really that much of a burden to HUP the server?
No, I already published updated Debian packages that do the HUP. They also had to try harder to make sure that the HUP actually works - that the unprivileged user can re-read the configuration. We may still get some bug reports, but hopefully the users can figure out whatever is left over. Just remember to write better commit logs in the future, documenting all known implications of a change, so people can notice sooner. -- 2. That which causes joy or happiness.
Hi,
Before, it wouldn't re-open the file, even if you did HUP it. I'm not sure why you thought it was rotating the log files before... that just didn't work. It opened the log file when the server started, and never touched it again after that.
thats not the behaviour we saw - eg -rw-r--r-- 1 radiusd radiusd 3152191 Oct 23 04:08 radius.log.36 -rw-r--r-- 1 radiusd radiusd 2229770 Oct 24 04:09 radius.log.35 -rw-r--r-- 1 radiusd radiusd 2589987 Oct 25 04:09 radius.log.34 -rw-r--r-- 1 radiusd radiusd 4089171 Oct 26 04:11 radius.log.33 -rw-r--r-- 1 radiusd radiusd 4902736 Oct 27 04:10 radius.log.32 -rw-r--r-- 1 radiusd radiusd 4618571 Oct 28 04:07 radius.log.31 -rw-r--r-- 1 radiusd radiusd 4221713 Oct 29 04:09 radius.log.30 -rw-r--r-- 1 radiusd radiusd 3737681 Oct 30 04:09 radius.log.29 -rw-r--r-- 1 radiusd radiusd 2328756 Oct 31 04:09 radius.log.28 -rw-r--r-- 1 radiusd radiusd 2060983 Nov 1 04:09 radius.log.27 -rw-r--r-- 1 radiusd radiusd 3395059 Nov 2 04:10 radius.log.26 -rw-r--r-- 1 radiusd radiusd 4934398 Nov 3 04:11 radius.log.25 -rw-r--r-- 1 radiusd radiusd 3975604 Nov 4 04:09 radius.log.24 -rw-r--r-- 1 radiusd radiusd 3675166 Nov 5 04:09 radius.log.23 -rw-r--r-- 1 radiusd radiusd 3220017 Nov 6 04:09 radius.log.22 -rw-r--r-- 1 radiusd radiusd 2278344 Nov 7 04:09 radius.log.21 -rw-r--r-- 1 radiusd radiusd 1942965 Nov 8 04:10 radius.log.20 -rw-r--r-- 1 radiusd radiusd 3298715 Nov 9 04:11 radius.log.19 -rw-r--r-- 1 radiusd radiusd 3554339 Nov 10 04:11 radius.log.18 -rw-r--r-- 1 radiusd radiusd 3755024 Nov 11 04:09 radius.log.17 -rw-r--r-- 1 radiusd radiusd 3882586 Nov 12 04:09 radius.log.16 -rw-r--r-- 1 radiusd radiusd 3185965 Nov 13 04:08 radius.log.15 -rw-r--r-- 1 radiusd radiusd 1831972 Nov 14 04:08 radius.log.14 -rw-r--r-- 1 radiusd radiusd 1894329 Nov 15 04:10 radius.log.13 -rw-r--r-- 1 radiusd radiusd 3620635 Nov 16 04:10 radius.log.12 as you can see, each log file was created and used...and we RARELY restart the server. we certainly dont or didnt HUP it. alan
On Fri, 2010-11-26 at 21:08 +0000, Alan Buxey wrote:
hi,
one eagle-eyed member spotted a small issue with our systems after the upgrade to 2.1.10 (which, frankly I'd overlooked because to me its more important that people can actually authenticate and we've got good accounting etc :-) )
anyway, its this.
the standard radius.log file which records a few items of interest is no longer logrotated correctly....ie logrotate comes along, the file gets a new number/name and a new file is created for radiusd to keep using...except it doesnt. in the end you end up with eg
radius.log.5 radius.log.4 radius.log.3 radius.log.2 radius.log.1 radius.log
where all the newer ones are zero bytes and radius.log.5 is several meg in size
the sudden obvious fix is to add the HUP/restart part to the logrotate script but we've never ever had to do this in the past...and I'm loathe to do such a thing...
In our log rotation (on CentOS) we use: prerotate /sbin/service radiusd stop >/dev/null endscript postrotate /sbin/service radiusd start >/dev/null endscript This occurs at around 4am. We have not had any problems with it. John. -- John Horne, University of Plymouth, UK Tel: +44 (0)1752 587287 Fax: +44 (0)1752 587001
Hi,
In our log rotation (on CentOS) we use:
prerotate /sbin/service radiusd stop >/dev/null endscript postrotate /sbin/service radiusd start >/dev/null endscript
I know the workarounds - only hope you dont have someone trying to authenticate during that timeframe ;-) but seriously, this impacts the statistics etc that you get from eg radmin or from sending a stats request packet to the control-socket. . you have a clean set of stats each day but, even worse, doing this flushes the EAP cache for fast session resumption alan
participants (6)
-
Alan Buxey -
Alan DeKok -
Alexander Clouter -
Johan Meiring -
John Horne -
Josip Rodin