Failed (re-)authentification after some time...
Something strange is going on: we do re-authentification every ten seconds with one WinXP SP3 client hooked up to a Cisco 3560G Switch. The reauth interval is small to stress-test the setup. It works w/a problems for 1-2 Days, then we get: Sun Aug 15 10:00:51 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Sun Aug 15 10:00:51 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50043 cli 00-08-74-46-34-F7) Sun Aug 15 10:01:05 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Sun Aug 15 10:01:05 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50043 cli 00-08-74-46-34-F7) Sun Aug 15 10:01:20 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Sun Aug 15 10:01:20 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50043 cli 00-08-74-46-34-F7) Sun Aug 15 10:01:39 2010 : Error: Discarding duplicate request from client swba1-00-test port 1645 - ID: 157 due to unfinished request 125603 Sun Aug 15 10:01:44 2010 : Error: Child PID 30686 is taking too much time: forcing failure and killing child. Sun Aug 15 10:01:44 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Sun Aug 15 10:01:44 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50043 cli 00-08-74-46-34-F7) The last two entries are due to the crappy windows client. If auth fails once, it thinks, that the saved auth info is wrong and deletes it, querying the user to enter mschap(PEAP) login/pw again. The entry Sun Aug 15 10:01:39 2010 is interesting as no client was connected to port 1645 at that time and the two days before, however it seems as if this triggers the timeout initially. My question: can I somehow extend the timeout or do anything else to prevent this from happening?
Jan Zacharias wrote:
Sun Aug 15 10:01:39 2010 : Error: Discarding duplicate request from client swba1-00-test port 1645 - ID: 157 due to unfinished request 125603
As always, something is blocking the server.
The entry Sun Aug 15 10:01:39 2010 is interesting as no client was connected to port 1645 at that time
<shrug> The server doesn't invent packets. *Something* sent it a packet.
My question: can I somehow extend the timeout or do anything else to prevent this from happening?
Fix is so that nothing is blocking the server. Alan DeKok.
Hi Alan, I did more tests (now with two winXP clients and one OSX client), the problem is still unsolved: Wed Aug 18 18:03:21 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Wed Aug 18 18:03:21 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50043 cli 00-08-74-46-34-F7) Wed Aug 18 18:03:24 2010 : Auth: Login OK: [jan/<via Auth-Type = mschap>] (from client swba1-00-test port 0 via TLS tunnel) Wed Aug 18 18:03:24 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50039 cli 00-16-CB-AA-0F-CB) Wed Aug 18 18:03:27 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Wed Aug 18 18:03:27 2010 : Auth: Login OK: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50041 cli 00-1E-37-90-89-D2) Wed Aug 18 18:03:45 2010 : Error: Child PID 72473 is taking too much time: forcing failure and killing child. Wed Aug 18 18:03:45 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Wed Aug 18 18:03:45 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50043 cli 00-08-74-46-34-F7) Wed Aug 18 18:03:55 2010 : Error: Child PID 72474 is taking too much time: forcing failure and killing child. Wed Aug 18 18:03:55 2010 : Auth: Login incorrect: [jan/<via Auth-Type = mschap>] (from client swba1-00-test port 0 via TLS tunnel) Wed Aug 18 18:03:55 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50039 cli 00-16-CB-AA-0F-CB) Wed Aug 18 18:03:55 2010 : Error: rlm_eap: No EAP session matching the State variable. Wed Aug 18 18:03:55 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50043 cli 00-08-74-46-34-F7) Wed Aug 18 18:04:05 2010 : Error: Child PID 72475 is taking too much time: forcing failure and killing child. Wed Aug 18 18:04:05 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 0 via TLS tunnel) Wed Aug 18 18:04:05 2010 : Auth: Login incorrect: [jan/<via Auth-Type = EAP>] (from client swba1-00-test port 50041 cli 00-1E-37-90-89-D2) The strange thing: freeradius is started with the "no childs" option: freeradius 60384 0.0 0.4 11560 9240 4 S 11:57AM 0:49.13 /usr/local/sbin/radiusd -s So why does it complain about childs that take to long?! Btw: The server has a load of 0.00 and network IO is only to the ads server. If I block traffic to it, freerad does not complain about childs that take to long, so the problem hides elsewhere, I guess. Thanks for your help! Best, Jan Alan DeKok <aland@deployingradius.com> hat am 17. August 2010 um 09:47 geschrieben:
Jan Zacharias wrote:
Sun Aug 15 10:01:39 2010 : Error: Discarding duplicate request from client swba1-00-test port 1645 - ID: 157 due to unfinished request 125603
As always, something is blocking the server.
The entry Sun Aug 15 10:01:39 2010 is interesting as no client was connected to port 1645 at that time
<shrug> The server doesn't invent packets. *Something* sent it a packet.
My question: can I somehow extend the timeout or do anything else to prevent this from happening?
Fix is so that nothing is blocking the server.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Jan Zacharias wrote:
I did more tests (now with two winXP clients and one OSX client),
the problem is still unsolved:
<shrug> The solution is still the same.
The strange thing: freeradius is started with the "no childs" option:
freeradius 60384 0.0 0.4 11560 9240 4 S 11:57AM 0:49.13 /usr/local/sbin/radiusd -s
Well... something is inconsistent. The error messages you posted are produced *only* when the server has child threads.
So why does it complain about childs that take to long?!
For the same reason as before. Alan DeKok.
Hey Alan, you suggested:
Fix is so that nothing is blocking the server.
Call me dump, but I have no idea what to look for. One idea: is ntlm_auth referred to as child? Maybe I sould write a wrapper and see how long execution of this "helper program" takes, or can I somehow log what program had which PID? Best, Jan Alan DeKok <aland@deployingradius.com> hat am 30. August 2010 um 22:22 geschrieben:
Jan Zacharias wrote:
I did more tests (now with two winXP clients and one OSX client),
the problem is still unsolved:
<shrug> The solution is still the same.
The strange thing: freeradius is started with the "no childs" option: freeradius 60384 0.0 0.4 11560 9240 4 S 11:57AM 0:49.13 /usr/local/sbin/radiusd -s
Well... something is inconsistent. The error messages you posted are produced *only* when the server has child threads.
So why does it complain about childs that take to long?!
For the same reason as before.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Alan DeKok <aland@deployingradius.com> hat am 31. August 2010 um 13:18 geschrieben: > Jan Zacharias wrote: > > Call me dump, but I have no idea what to look for. > > Neither do I. It's your system... > > > One idea: is ntlm_auth referred to as child? Maybe I sould > > write a wrapper and see how long execution of this "helper program" > > takes, > > Possibly, yes. │ ├─┬◆ 65437 root sshd: root@pts/4 (sshd) │ │ └─┬◆ 65440 root -bash (bash) │ │ └─┬◆ 76322 freeradius radiusd -s -X -xx -f │ │ └─┬─ 76421 freeradius /bin/sh /usr/local/bin/ntlm_auth_wrapper --request-nt-key --domain=DFKI --username=jan --challenge=xxx --nt-response=xxx So, yes :) The wrapper logged PID and time (real,sys,user) of ntlm_auth To speed up the debugging, I introduced a sleep of varying duration in the ntlm_auth_wrapper. I found that freeradius kills the ntlm stuff if it takes longer than ten seconds to complete. My suggestion is that we introduce a configuration variable ntlm_auth_retries so that freerad kills the process, but then tries again until the retry-count is reached. This would greatly improve reliability in stress/high load/failover scenarios :) What do you think, Alan? Anyone else? Best, Jan > > Alan DeKok. > - > List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Jan Zacharias wrote:
To speed up the debugging, I introduced a sleep of varying duration in the ntlm_auth_wrapper.
I found that freeradius kills the ntlm stuff if it takes longer than ten seconds to complete.
Yes. Any child script which takes that long is broken.
My suggestion is that we introduce a configuration variable ntlm_auth_retries so that freerad kills the process,
No. You can write a shell script wrapper around ntlm_auth that does: - fork ntlm_auth - wait 1s for it to return - if it doesn't return, kill it - try to fork it again
What do you think, Alan? Anyone else?
This isn't a server problem, and changing the server isn't necessary. Alan DeKok.
Hey Alan! Alan DeKok <aland@deployingradius.com> hat am 1. September 2010 um 15:46 geschrieben:
Jan Zacharias wrote:
To speed up the debugging, I introduced a sleep of varying duration in the ntlm_auth_wrapper.
I found that freeradius kills the ntlm stuff if it takes longer than ten seconds to complete.
Yes. Any child script which takes that long is broken. No, it can also be just someone pulling a network cord/routing changes etc.etc.
My suggestion is that we introduce a configuration variable ntlm_auth_retries so that freerad kills the process,
No. You can write a shell script wrapper around ntlm_auth that does:
- fork ntlm_auth - wait 1s for it to return - if it doesn't return, kill it - try to fork it again
Yeah sure, this was also my first idea, but i'm still limited to ten seconds then :(
What do you think, Alan? Anyone else?
This isn't a server problem, and changing the server isn't necessary. Sure it's not a problem, but it would improve reliability and robustness.
This is not about finger pointing or so, I just want to help make freerad even better :) Best, Jan
Jan Zacharias wrote:
Alan DeKok <aland@deployingradius.com> hat am 1. September 2010 um 15:46 geschrieben:
Yes. Any child script which takes that long is broken.
No, it can also be just someone pulling a network cord/routing changes etc.etc.
Let me be clear: RADIUS clients and servers expect responses within a short time frame, usually milliseconds. Asking clients to wait many seconds for a slow script on the server is *impossible*. Many clients will give up, and reject the user. i.e. the RADIUS client doesn't care *why* the script is taking too long. All it knows is that the user can't log in. Please explain to your users
- fork ntlm_auth - wait 1s for it to return - if it doesn't return, kill it - try to fork it again
Yeah sure, this was also my first idea, but i'm still limited to ten seconds then :(
So... set the "don't wait" flag on the executed program. See the documentation for the "exec" module, or the "Exec-Program" attribute.
This isn't a server problem, and changing the server isn't necessary.
Sure it's not a problem, but it would improve reliability and robustness.
No, it would not improve reliability and robustness. Adding more
This is not about finger pointing or so, I just want to help make freerad even better :)
Yes... but we try not to re-invent the wheel. If you can add a feature by writing a few lines of a shell script, there is little reason to update the server source with that feature. Alan DeKok.
participants (2)
-
Alan DeKok -
Jan Zacharias