Question about how to find unfinished requests
I am trying to debug an issue on my servers with the following configuration: freeradius 2.2.0 -> proxy to AD server running radius for auth -> return auth (yes/no) then my server appends the necessary vlan attributes from its local DB I am seeing a number of these messages: Nov 11 17:57:31 dvlanc radiusd[17781]: Received conflicting packet from client resnet4-WiSM-A port 32770 - ID: 18 due to unfinished request 928878. Giving up on old request. Nov 11 17:57:35 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 205 due to unfinished request 929613. Giving up on old request. Nov 11 17:57:37 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 36 due to unfinished request 929843. Giving up on old request. Nov 11 17:57:41 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 205 due to unfinished request 930139. Giving up on old request. Nov 11 17:57:41 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 216 due to unfinished request 929934. Giving up on old request. Nov 11 17:57:44 dvlanc radiusd[17781]: Received conflicting packet from client resnet4-WiSM-A port 32770 - ID: 253 due to unfinished request 929666. Giving up on old request. Nov 11 17:57:44 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 36 due to unfinished request 930099. Giving up on old request. How do I view "into the beast" to find the start of these requests? For example, I see no way to locate the stream of events for request 928878 so that I can narrow down where the problem is. My gut says it's located down the chain at the AD server (accessed via the radius protocol) taking too long but I have to prove it before I can get some action. Would tcpdump/tshark/etc be the way to attempt to follow these authentications or is there a better way with some enhanced logging parameters? If we know the request numbers, how do you pair those with any internal logging (via maybe radmin). It would be useful if, say, all log messages like Nov 11 17:57:21 dvlanc radiusd[17781]: Login OK: [mbaker66] (from client Rich-core-WiSM-B port 13 cli e0-c9-7a-55-9b-f5) Nov 11 17:57:21 dvlanc radiusd[17781]: Login OK: [fpeterson99] (from client resnet4-WiSM-A port 13 cli a8-96-8a-f3-5f-5b) Nov 11 17:57:21 dvlanc radiusd[17781]: Login OK: [gabriwal3] (from client resnet4-WiSM-A port 13 cli 3c-d0-f8-61-f3-27) included the request numbers in their logging output (or actually ANY log messages should include the request number it is involved in). We are having some major problems as the freeradius server gets hit with load between classes and starts losing auth. We are attempting to remove the dependence upon samba by going with configuring a proxy to AD over radius for authentication rather than rely upon an ntlm_auth. Thanks for any input/advice.
On 11/11/13 23:09, John Douglass wrote:
I am seeing a number of these messages:
Nov 11 17:57:31 dvlanc radiusd[17781]: Received conflicting packet from client resnet4-WiSM-A port 32770 - ID: 18 due to unfinished request 928878. Giving up on old request.
Yeah, lots of UK universities have run into this. In brief, it seems that many academic sites running Cisco lightweight wireless, but also a couple of non-Cisco sites, have started to experience this and related issues since the start of the academic year 2013. I suspect changes in client behaviour, client numbers/mix and also on the Cisco firmware side, are all contributing to it having suddenly appeared. It seems to be related to "peak movement" times - start/end of lectures and so forth - and to a massive spike in auth load as clients roam between APs. The problem is basically that above a certain load, auths suddenly aren't answered quickly enough, and the whole system goes into this spiral of doom where retransmits and reauths dominate. In our case, it was fork/exec of ntlm_auth being slow, and moving to a faster box helped a *lot*. You should also: 1. Ensure you are running Samba 3.6 2. Look into the "winbind max domain connections" parameter 3. Consider pinning yourself to the fastest / a dedicated DC
How do I view "into the beast" to find the start of these requests? For example, I see no way to locate the stream of events for request 928878 so that I can narrow down where the problem is. My gut says it's located down the chain at the AD server (accessed via the radius protocol) taking too long but I have to prove it before I can get some action.
I have spent a lot of time on this, and here's what I found helpful: 1. Start a long-running tcpdump of both your radius and MSRPC traffic (i.e. the connection from Winbind->DC): tcpdump -s 0 -w long.cap -U port 1812 or microsoft-ds 2. At the same time, start logging how long ntlm_auth takes - see below. 3. At the same time, start running "vmstat 1" piped to a timestamped file, so you monitor system load with high granularity. Alternatively any other high-resolution - 10 seconds at most - monitoring of user/sys/wait/idle CPU, IO and context switch load. 4. When you get a "spike" find out where in the chain - radius, ntlm_auth, MSRPC - the spike actually got to, and proceed from there. In our case, we were seeing the spike on radius and ntlm_auth times, but not MSRPC, which told us it was local. A closer examination of vmstat output strongly suggested kernel load of fork/exec. A faster box with a newer Linux kernel does not have the same issues, even under significantly higher load. A few tricks needed here to process this data. To get the ntlm_auth timings, at the moment you'll need a wrapper. I wrote a quick one in C which basically does clock_getime, fork/exec/wait, clock_gettime again the logs the result and returns the child exit status. I'll try to post the code later today. To get the radius timings I wrote a python script (again will try to post) which logs them in realtime, but it should be relatively easy to use an approach similar the the MSRPC one below. To get the MSRPC timings, you can use wireshark to dump the RPC PDU header (body is encrypted) and match request/responses for on-the-wire speeds. Simple pipeline for it (the awk script assumes one TCP flow, modify as appropriate): tshark -n -r $CAP -R dcerpc -T fields \ -e ip.src -e ip.dst -e frame.time_epoch \ -e dcerpc.pkt_type -e dcerpc.cn_call_id >msrpc.log awk ' $4==0 { rq[$5]=$3 next } { d=$3-rq[$5] del rq[$5] msec=$3 % 1 * 1000000 print strftime("%Y-%m-%dT%H:%M:%S", $3) "." msec, $5, d*1000 }' msrpc.log >msrpc.dat I'll try to write some of this up somewhere more useful than an email... In the meantime, if you'd like me to expand more on this, let me know. Cheers, Phil
Phil Mayers wrote:
It seems to be related to "peak movement" times - start/end of lectures and so forth - and to a massive spike in auth load as clients roam between APs. The problem is basically that above a certain load, auths suddenly aren't answered quickly enough, and the whole system goes into this spiral of doom where retransmits and reauths dominate.
The issue is that when ntlm_auth is blocked, the entire server melts down. This is the same as when an SQL DB blocks the server, too.
In our case, it was fork/exec of ntlm_auth being slow, and moving to a faster box helped a *lot*.
fork/exec shouldn't be that bad... the # of outstanding ntlm_programs is limited, but only by the total # of threads. So maybe the issues is past fork/exec, and into ntlm_auth / winbind?
In our case, we were seeing the spike on radius and ntlm_auth times, but not MSRPC, which told us it was local. A closer examination of vmstat output strongly suggested kernel load of fork/exec. A faster box with a newer Linux kernel does not have the same issues, even under significantly higher load.
Weird, but OK.
A few tricks needed here to process this data.
To get the ntlm_auth timings, at the moment you'll need a wrapper. I wrote a quick one in C which basically does clock_getime, fork/exec/wait, clock_gettime again the logs the result and returns the child exit status. I'll try to post the code later today.
Maybe the changes in 2.2.3 will help here. If the child takes more than 1 second, you're better off giving up on the request. Alan DeKok.
On 12/11/13 20:17, Alan DeKok wrote:
In our case, it was fork/exec of ntlm_auth being slow, and moving to a faster box helped a *lot*.
fork/exec shouldn't be that bad... the # of outstanding ntlm_programs is limited, but only by the total # of threads. So maybe the issues is past fork/exec, and into ntlm_auth / winbind?
Sure; I am inferring that it was fork/exec, based on the massive surge in user/sys/iowait and run-queue/cswitch during "events", but it's entirely possible all that CPU was being burnt inside the Samba stack, and that in Samba 3.6 it's not. It's on my TODO list to go back to the old servers with a bunch of test traffic then reproduce it, and *then* change one thing at a time. Unfortunately we were a week into massive instability on our wireless at that point, and extremely pointed questions were being asked, so I moved to our new servers - therefore, new RHEL version & kernel, new Samba, faster disk, more RAM, more and faster CPUs - any or a combination could be the cause. One thing whilst I think about it - people should note that Windows processes these RPCs differently to LDAP/Kerberos traffic, specifically inside a small (10 on win2012, 2 elsewhere) thread pool. Google "MaxConcurrentApi" for details. In our case, the RPC timings proved it wasn't an issue, but people should check it, and resize the AD thread pool if needed.
Maybe the changes in 2.2.3 will help here. If the child takes more than 1 second, you're better off giving up on the request.
Yes, I should have mentioned that. It's worth noting that people without 2.2.3 could, in the meantime, use the "timeout" utilty from coreutils as a wrapper. This reminds me of *another* issue that I failed to mention, and someone pointed out to me off-list - the Cisco WLC/WISM apparently use a single UDP socket for all radius requests to a single server - auth and acct - and thus there's a 255-packet limit for in-progress requests. If the WLC reaches that limit, it just starts re-using IDs aggressively, instead of opening a socket, which is nice - if you're in the middle of processing a conflicted request, you still burn the work you're currently doing, and the result is never used. I can't prove it, but I suspect that was an issue during the largest spikes. It is certainly a problem if you run an eduroam server, where proxied traffic can have very large RTTs. They're apparently going to "improve" this in 7.6 - there will be a separate UDP socket for auth/acct! Wow, thanks Cisco!!
Hi,
In our case, it was fork/exec of ntlm_auth being slow, and moving to a faster box helped a *lot*.
You should also:
1. Ensure you are running Samba 3.6 2. Look into the "winbind max domain connections" parameter 3. Consider pinning yourself to the fastest / a dedicated DC
we've been looking into this too and should come back with results after a while alan
Hi John, We were one of the UK universities seeing high load between lectures resulting in large numbers of 'Discarding duplicate request' errors. Alan Buxey (and others) suggested the errors were due to a back-end process, and not FR (also 2.2.0 authenticating with AD). This proved the case as we were able to dramatically reduce the number of these errors by using the IPs of our AD servers and not using DNS. Our initial tests were with a single IP but we now have amended a perl module within our FR build to randomly select the IP of one of our 6 AD servers; not an ideal solution, but as much as we're prepared to do at the moment. Martin.
-----Original Message----- From: freeradius-users- bounces+martin.ubank=uwe.ac.uk@lists.freeradius.org [mailto:freeradius- users-bounces+martin.ubank=uwe.ac.uk@lists.freeradius.org] On Behalf Of John Douglass Sent: 11 November 2013 23:09 To: FreeRadius users mailing list Subject: Question about how to find unfinished requests
I am trying to debug an issue on my servers with the following configuration:
freeradius 2.2.0 -> proxy to AD server running radius for auth -> return auth (yes/no) then my server appends the necessary vlan attributes from its local DB
I am seeing a number of these messages:
Nov 11 17:57:31 dvlanc radiusd[17781]: Received conflicting packet from client resnet4-WiSM-A port 32770 - ID: 18 due to unfinished request 928878. Giving up on old request. Nov 11 17:57:35 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 205 due to unfinished request 929613. Giving up on old request. Nov 11 17:57:37 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 36 due to unfinished request 929843. Giving up on old request. Nov 11 17:57:41 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 205 due to unfinished request 930139. Giving up on old request. Nov 11 17:57:41 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 216 due to unfinished request 929934. Giving up on old request. Nov 11 17:57:44 dvlanc radiusd[17781]: Received conflicting packet from client resnet4-WiSM-A port 32770 - ID: 253 due to unfinished request 929666. Giving up on old request. Nov 11 17:57:44 dvlanc radiusd[17781]: Received conflicting packet from client Rich-core-WiSM-B port 32770 - ID: 36 due to unfinished request 930099. Giving up on old request.
How do I view "into the beast" to find the start of these requests? For example, I see no way to locate the stream of events for request 928878 so that I can narrow down where the problem is. My gut says it's located down the chain at the AD server (accessed via the radius protocol) taking too long but I have to prove it before I can get some action.
Would tcpdump/tshark/etc be the way to attempt to follow these authentications or is there a better way with some enhanced logging parameters? If we know the request numbers, how do you pair those with any internal logging (via maybe radmin). It would be useful if, say, all log messages like
Nov 11 17:57:21 dvlanc radiusd[17781]: Login OK: [mbaker66] (from client Rich-core-WiSM-B port 13 cli e0-c9-7a-55-9b-f5) Nov 11 17:57:21 dvlanc radiusd[17781]: Login OK: [fpeterson99] (from client resnet4-WiSM-A port 13 cli a8-96-8a-f3-5f-5b) Nov 11 17:57:21 dvlanc radiusd[17781]: Login OK: [gabriwal3] (from client resnet4-WiSM-A port 13 cli 3c-d0-f8-61-f3-27)
included the request numbers in their logging output (or actually ANY log messages should include the request number it is involved in).
We are having some major problems as the freeradius server gets hit with load between classes and starts losing auth. We are attempting to remove the dependence upon samba by going with configuring a proxy to AD over radius for authentication rather than rely upon an ntlm_auth.
Thanks for any input/advice. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (5)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
John Douglass -
Martin Ubank -
Phil Mayers