kill -HUP sometimes causes "rlm_pap: mschap xlat failed"
Hi, I've got a strange problem with FR 2.1.12, sometimes (not always) when logrotate ran, freeradius goes bonkers and responds to every pap request with "mschap xlat failed". Restarting FR fixes this magically and all works fine again. I created a small and hackish script, which restarts FR when this happens. The output showed that about every second week (logrotate runs weekly) this happens. Because FR works fine again after a restart, restarting FR in debug mode is not an option to get more information. But here is a snipped from my radiusd.log showing the symptom: Sun Apr 8 06:49:50 2012 : Info: HUP - loading modules Sun Apr 8 06:49:50 2012 : Info: Module: Reloaded module "attr_filter.access_reject" Sun Apr 8 06:49:50 2012 : Info: Module: Reloaded module "mschap" Sun Apr 8 06:49:50 2012 : Info: Module: Reloaded module "radutmp" Sun Apr 8 06:49:50 2012 : Info: Module: Reloaded module "macs" Sun Apr 8 06:49:50 2012 : Info: Module: Reloaded module "pap" Sun Apr 8 06:49:50 2012 : Info: Loaded virtual server <default> Sun Apr 8 06:49:50 2012 : Info: Loaded virtual server inner-tunnel-ldap Sun Apr 8 06:50:01 2012 : Auth: Login incorrect (rlm_pap: mschap xlat failed): [someuser] (from client watchdog port 0) Sun Apr 8 06:50:02 2012 : Info: Signalled to terminate Sun Apr 8 06:50:02 2012 : Info: Exiting normally. Sun Apr 8 06:50:02 2012 : Info: Loaded virtual server <default> Sun Apr 8 06:50:02 2012 : Info: Loaded virtual server inner-tunnel-ldap Sun Apr 8 06:50:02 2012 : Info: Ready to process requests. Sun Apr 8 06:55:01 2012 : Auth: Login OK: [someuser] (from client watchdog port 0) So my script ran radtest with the "someuser" credentials (which should always work), which failed, it then restarted FR and all worked fine again... Is there any more information I can provide? all the best, Jan
On 04/12/2012 09:59 AM, Jan Weiher wrote:
Hi,
I've got a strange problem with FR 2.1.12, sometimes (not always) when logrotate ran, freeradius goes bonkers and responds to every pap request with "mschap xlat failed". Restarting FR fixes this magically and all works fine again. I created a small and hackish script, which restarts FR when this happens. The output showed that about every second week (logrotate runs weekly) this happens. Because FR works fine again after a restart, restarting FR in debug mode is not an option to get more information. But here is a snipped from my radiusd.log showing the symptom:
Is there any more information I can provide?
Yes, what is the contents of your logrotate script. There are two typical strategies, either it directly does a "kill -HUP" to the freeradius pid, or it invokes the initscript passing it the "reload" option. If it's the later we would need to know what the reload option does, e.g. does it also just do a "kill -HUP" or does it do something else? -- John Dennis <jdennis@redhat.com> Looking to carve out IT costs? www.redhat.com/carveoutcosts/
Hi, it does the first - calling kill -HUP on postrotate: /var/log/freeradius/*.log { weekly rotate 52 compress notifempty postrotate kill -HUP `cat /var/run/freeradius/freeradius.pid` endscript } I checked the init script as well, it does not offer a reload option, just restart and force-reload, doing both the same: calling the stop option and then the start option again... Jan Am 12.04.2012 16:16, schrieb John Dennis:
On 04/12/2012 09:59 AM, Jan Weiher wrote:
Hi,
I've got a strange problem with FR 2.1.12, sometimes (not always) when logrotate ran, freeradius goes bonkers and responds to every pap request with "mschap xlat failed". Restarting FR fixes this magically and all works fine again. I created a small and hackish script, which restarts FR when this happens. The output showed that about every second week (logrotate runs weekly) this happens. Because FR works fine again after a restart, restarting FR in debug mode is not an option to get more information. But here is a snipped from my radiusd.log showing the symptom:
Is there any more information I can provide?
Yes, what is the contents of your logrotate script. There are two typical strategies, either it directly does a "kill -HUP" to the freeradius pid, or it invokes the initscript passing it the "reload" option. If it's the later we would need to know what the reload option does, e.g. does it also just do a "kill -HUP" or does it do something else?
Hi, On Thu, Apr 12, 2012 at 03:59:56PM +0200, Jan Weiher wrote:
I've got a strange problem with FR 2.1.12, sometimes (not always) when logrotate ran, freeradius goes bonkers and responds to every pap request with "mschap xlat failed". Restarting FR fixes this magically and all works fine again. I created a small and hackish script, which restarts FR when this happens. The output showed that about every second week (logrotate runs weekly) this happens. Because FR works fine again after a restart, restarting FR in debug mode is not an option to get more information. But here is a snipped from my radiusd.log showing the symptom:
We've been hitting the same problem for a while, on just one (of three) radius server. Every couple of weeks, at FR logrotation time, all auths fail. In this case, it's EAP/MS-CHAPv2. After logrotation, the auths all give Thu Apr 12 15:21:31 2012 : Auth: Login incorrect (mschap: External script says NT_STATUS_WRONG_PASSWORD: Wrong Password (0xc000006a)): [xxxxx@leicester.ac.uk] (from client WLC5508-CC-1 port 13 cli 58-1f-aa-50-59-ef via TLS tunnel) I've been meaning to try and sort this for a while, so you prompted me to look at it. I had been thinking that it was winbind being restarted at the same time, and was going to blame winbind. However, it seems winbind isn't being restarted, so it's unlikely to be that. Our logrotate -HUPs the server, not stop/start. I've just replicated the problem by repeatedly HUPping freeradius, with about 10 second gaps between. On the 8th or so try, the same issue hit. Stopping and starting FR fixed it. I'm wondering if the mschap module somehow gets its internal state muddled on a HUP, and starts sending the wrong challenge response. ntlm_auth from the command line works fine when FR has a problem. I'll dig a bit more, but the easy solution is to change the logrotate script to restart, rather than reload/HUP. Cheers, Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Architect (UNIX and Networks), Network Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
Hi, Am 12.04.2012 16:32, schrieb Matthew Newton:
I'll dig a bit more, but the easy solution is to change the logrotate script to restart, rather than reload/HUP.
Yes, that would be a solution for me as well, because when logrotate runs, the freeradius server is basically idle, but I dont think this is a solution for somebody who needs the server 24/7. best, Jan
On Thu, Apr 12, 2012 at 04:45:56PM +0200, Jan Weiher wrote:
Am 12.04.2012 16:32, schrieb Matthew Newton:
I'll dig a bit more, but the easy solution is to change the logrotate script to restart, rather than reload/HUP.
Yes, that would be a solution for me as well, because when logrotate runs, the freeradius server is basically idle, but I dont think this is a solution for somebody who needs the server 24/7.
Although a reload takes 0.02 seconds, a restart still only takes 0.3 seconds, which is so quick our NASes wouldn't even notice. I wouldn't worry about it. I've found out why only one of our servers is affected - the other two have an old init script that don't implement reload, which means logrotate hasn't actually been restarting the daemon... :) So that seems to indicate it's the HUP that causes the problem. Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Architect (UNIX and Networks), Network Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
Matthew Newton wrote:
I've just replicated the problem by repeatedly HUPping freeradius, with about 10 second gaps between. On the 8th or so try, the same issue hit. Stopping and starting FR fixed it.
Maybe valgrind helps. It doesn't say anything for me...
I'm wondering if the mschap module somehow gets its internal state muddled on a HUP, and starts sending the wrong challenge response. ntlm_auth from the command line works fine when FR has a problem.
I'm not sure how. Alan DeKok.
I'm wondering if the mschap module somehow gets its internal state muddled on a HUP, and starts sending the wrong challenge response. ntlm_auth from the command line works fine when FR has a problem.
Hi, I had some sparetime and was able to have a deeper look at it. What I did is basically running freeradius -X and then hup'd it until it got borked. Seems to me like the mschap module gets somehow lost during the hup: # Executing group from file /etc/freeradius/sites-enabled/default +- entering group PAP {...} [pap] login attempt with password "thepassword" [pap] Using NT encryption. [pap] WARNING: Unknown module "mschap" in string expansion "%" [pap] mschap xlat failed [pap] Passwords don't match ++[pap] returns reject Failed to authenticate the user. But, the message "Unkown module" is strange, because after the HUP (when reloading the modules) it says: Module: Trying to reload module "mschap" mschap { ... } Module: Reloaded module "mschap"
Maybe valgrind helps. It doesn't say anything for me...
anything more I can provide? I might be able to dig around with valgrind, but it needs a debug build, if I remember correctly? all the best, Jan
Jan Weiher wrote:
I had some sparetime and was able to have a deeper look at it. What I did is basically running freeradius -X and then hup'd it until it got borked. Seems to me like the mschap module gets somehow lost during the hup:
That's enough to tell what's going on. Try grabbing the "v2.1.x" branch from git. It has a fix. Alan DeKok.
Hi, On Fri, Apr 13, 2012 at 05:23:22PM +0200, Alan DeKok wrote:
Jan Weiher wrote:
I had some sparetime and was able to have a deeper look at it. What I did is basically running freeradius -X and then hup'd it until it got borked. Seems to me like the mschap module gets somehow lost during the hup:
That's enough to tell what's going on.
Try grabbing the "v2.1.x" branch from git. It has a fix.
Just to confirm, I've been trying to cause 'death by HUP' with the latest v2.1.x, and can't get it to. Backing out the last patch, I can cause failure in about 8-10 HUPs. I wondered where we used xlats for EAP/MSCHAPv2, but realise they are in the ntlm_auth line for the Challenge/Response. So, looking good so far - thanks Alan! Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Architect (UNIX and Networks), Network Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
Am 13.04.2012 18:48, schrieb Matthew Newton:
Hi,
On Fri, Apr 13, 2012 at 05:23:22PM +0200, Alan DeKok wrote:
Jan Weiher wrote:
I had some sparetime and was able to have a deeper look at it. What I did is basically running freeradius -X and then hup'd it until it got borked. Seems to me like the mschap module gets somehow lost during the hup:
That's enough to tell what's going on.
Try grabbing the "v2.1.x" branch from git. It has a fix.
Just to confirm, I've been trying to cause 'death by HUP' with the latest v2.1.x, and can't get it to. Backing out the last patch, I can cause failure in about 8-10 HUPs.
I can confirm as well that this is fixed: after hup'ing 30 minutes every 6 seconds, FR is still working as it should. Thanks a lot! - Jan
participants (4)
-
Alan DeKok -
Jan Weiher -
John Dennis -
Matthew Newton