Help troubleshooting No EAP session matching...
Hi List, During periods of high load, we are seeing many messages like the following: radiusd[28187]: rlm_eap: No EAP session matching the State variable. I understand the meaning of the message, but I need some assistance on how to go about locating the source of the problem. During peak times, we have about 8K wireless logins per minute, for extended periods. We have 6 wireless controllers, from which the Access-Requests are sent. Due to the high load, I am unable to run the server with -X, because it gets crushed while running single threaded. I can use radmin, but I'm not sure what to set the debug condition to. I don't see any errors about child processes being hung, or winbind/ntlm_auth taking too long. Some values which may be relevant: radiusd.conf: max_request_time = 30 radiusd.conf: cleanup_delay = 5 radiusd.conf: max_requests = 8000000 #about 30K wireless users at peak * 256 ~= 8million radiusd.conf: start_servers = 5 radiusd.conf: max_servers = 32 radiusd.conf: min_spare_servers = 3 radiusd.conf: max_spare_servers = 10 radiusd.conf: # max_queue_size = 65536 (unsure why this is commented out) mods-enabled/eap: timer_expire = 60 mods-enabled/eap: cache = disabled $ openssl speed rsa2048 Doing 2048 bit private rsa's for 10s: 5263 2048 bit private RSA's in 10.01s Doing 2048 bit public rsa's for 10s: 176233 2048 bit public RSA's in 10.00s OpenSSL 1.0.1e-fips 11 Feb 2013 built on: Mon May 2 06:13:20 EDT 2016 options:bn(64,64) md2(int) rc4(16x,int) des(idx,cisc,16,int) aes(partial) idea(int) blowfish(idx) compiler: gcc -fPIC -DOPENSSL_PIC -DZLIB -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -DKRB5_MIT -m64 -DL_ENDIAN -DTERMIO -Wall -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic -Wa,--noexecstack -DPURIFY -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DMD5_ASM -DAES_ASM -DVPAES_ASM -DBSAES_ASM -DWHIRLPOOL_ASM -DGHASH_ASM sign verify sign/s verify/s rsa 2048 bits 0.001902s 0.000057s 525.8 17623.3 So, a couple questions: 1. Is there a way to get more info along with the message "rlm_eap: No EAP session matching the State variable." ? - eg. Which NAS it came from, calling-station-id, etc. 2. Are the aforementioned values OK? Any advice would be appreciated. Regards, Dave
On Sep 15, 2016, at 9:57 AM, Dave Aldwinckle <daldwinc@uwaterloo.ca> wrote:
During periods of high load, we are seeing many messages like the following:
radiusd[28187]: rlm_eap: No EAP session matching the State variable.
I understand the meaning of the message, but I need some assistance on how to go about locating the source of the problem.
If it's high load, the problem is starvation. Either the CPU is overloaded, or the back-end is overloaded.
During peak times, we have about 8K wireless logins per minute, for extended periods. We have 6 wireless controllers, from which the Access-Requests are sent. Due to the high load, I am unable to run the server with -X, because it gets crushed while running single threaded. I can use radmin, but I'm not sure what to set the debug condition to.
I don't see any errors about child processes being hung, or winbind/ntlm_auth taking too long.
Yeah, ntlm_auth typically maxes out at 100 to 200 authentications per second. That's likely the problem.
$ openssl speed rsa2048 Doing 2048 bit private rsa's for 10s: 5263 2048 bit private RSA's in 10.01s Doing 2048 bit public rsa's for 10s: 176233 2048 bit public RSA's in 10.00s
The server should be able to do 1000 or more EAP authentications per second.
So, a couple questions:
1. Is there a way to get more info along with the message "rlm_eap: No EAP session matching the State variable." ? - eg. Which NAS it came from, calling-station-id, etc.
The NAS information is in the other attributes. You can look at the post-auth-type Reject to log things.
2. Are the aforementioned values OK?
They're fine. Alan DeKok.
On Thu, Sep 15, 2016 at 10:16:19AM -0400, Alan DeKok wrote:
On Sep 15, 2016, at 9:57 AM, Dave Aldwinckle <daldwinc@uwaterloo.ca> wrote:
During peak times, we have about 8K wireless logins per minute, for extended periods. We have 6 wireless controllers, from which the Access-Requests are sent. Due to the high load, I am unable to run the server with -X, because it gets crushed while running single threaded. I can use radmin, but I'm not sure what to set the debug condition to.
I don't see any errors about child processes being hung, or winbind/ntlm_auth taking too long.
Yeah, ntlm_auth typically maxes out at 100 to 200 authentications per second. That's likely the problem.
In my experience, around 30-40... but does depend on hardware. Could try using libwbclient with recent FreeRADIUS - see winbind_username/winbind_domain in mods-available/mschap. It might help; it should be a bit quicker than calling out to ntlm_auth. Recent versions of Samba should be better as well IIRC. Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
On Sep 15, 2016, at 10:21 AM, Matthew Newton <mcn4@leicester.ac.uk> wrote:
In my experience, around 30-40... but does depend on hardware.
Could try using libwbclient with recent FreeRADIUS - see winbind_username/winbind_domain in mods-available/mschap. It might help; it should be a bit quicker than calling out to ntlm_auth.
Recent versions of Samba should be better as well IIRC.
Even better, enable TLS session caching. It's easier to do in v3.1.x, but even v3.0.x should be OK. That takes the load off of AD, and also FreeRADIUS. I've seen many 1000's of sessions resumed per second. Alan DeKok.
Hi,
During periods of high load, we are seeing many messages like the following:
radiusd[28187]: rlm_eap: No EAP session matching the State variable.
RADIUS protocol only allows a certain number of auths to be 'being handled' from a NAS - I'm going to guess you are using Cisco controllers? the joy of them using just one single NAS port as the ID - no extended IDs - thus all those hundreds of APs are just the one client :/
During peak times, we have about 8K wireless logins per minute, for extended periods. We have 6 wireless controllers, from which the Access-Requests are sent. Due to the high load, I am unable to run the server with -X, because it gets crushed while running single threaded. I can use radmin, but I'm not sure what to set the debug condition to.
most sites find they hit some magic numbers.... upgrading to new code on controller might help (eg cisco moved to using new NAS port ID for the accounting traffic...double your throughput then...) - then you hit a higher level...as we did... the other big issue is ntlm_auth is does take quite some time and is a mix of CPU-bound and server bound - basically you'll find it sticks like glue with older SAMBAs to just one of the KDC entries in AD.
radiusd.conf: max_request_time = 30 radiusd.conf: cleanup_delay = 5 radiusd.conf: max_requests = 8000000 #about 30K wireless users at peak * 256 ~= 8million
max_requests , please note: This should be 256 multiplied by the number of clients - this is clients of the RADIUS server - ie NAS devices... 'those' clients, not wireless clients. hence this number should be more like 256 x 6 !! ;-)
radiusd.conf: # max_queue_size = 65536 (unsure why this is commented out)
its commented out by default IIRC - you could try tweaking...but if somethings in the queue it hasnt really been handled - eg I believe its entry will not have been added to state table etc..... how many CPUs and cores? you could try increasing the number of threads to eg 64 if you have the cores for the threads
mods-enabled/eap: timer_expire = 60 mods-enabled/eap: cache = disabled
and you really should be using the cache capability. this dramatically improves the re-auth time of clients - hence shortcutting them
1. Is there a way to get more info along with the message "rlm_eap: No EAP session matching the State variable." ? - eg. Which NAS it came from, calling-station-id, etc.
you can add extra logging eg with linelog or detail log (reject log here) for debugging you can just debug particular clients (NAS) or end user clients - just follow the instructions for commands as given by 'man radmin' - you may want to up the debug log level to 5 if you dont get enough info. is this box running ina VM? the UDP performance isnt quite so good, you need a few tweaks to that part. I would advise looking at new features available in 3.1.x - the native winbind client - VERY fast and nice...and the caching is improved. you can ALSO help things out by using the 'QoS' packet handler "queue_priority" - setting that to EAP will ensure that those requests that are further along the EAP process will be handled first - which is nice for those auths that have already dealt with eg 8 or 9 of the RADIUS responses out of 11...rather than failing at that late stage.... alan
Thanks for all of the responses. There is a lot of useful info here. - Aruba controllers, so yes, about 4500 APs on 6 clients (good note about max_requests) - Will look into updating Samba, right now we are running 3.6, so too old to use the winbind_* stuff from mschap - Will add logging as suggested to auth type reject - Will trial eap:caching - We are running 3.0.10, which I understand is old. I may look into upgrading to 3.1, but I was hoping the next upgrade would be 4.0. The box is a VM, what did you mean by this?
is this box running ina VM? the UDP performance isnt quite so good, you need a few tweaks to that part.
Thanks again! Dave On 16-09-15 02:44 PM, A.L.M.Buxey@lboro.ac.uk wrote:
Hi,
During periods of high load, we are seeing many messages like the following:
radiusd[28187]: rlm_eap: No EAP session matching the State variable. RADIUS protocol only allows a certain number of auths to be 'being handled' from a NAS - I'm going to guess you are using Cisco controllers? the joy of them using just one single NAS port as the ID - no extended IDs - thus all those hundreds of APs are just the one client :/
During peak times, we have about 8K wireless logins per minute, for extended periods. We have 6 wireless controllers, from which the Access-Requests are sent. Due to the high load, I am unable to run the server with -X, because it gets crushed while running single threaded. I can use radmin, but I'm not sure what to set the debug condition to. most sites find they hit some magic numbers.... upgrading to new code on controller might help (eg cisco moved to using new NAS port ID for the accounting traffic...double your throughput then...) - then you hit a higher level...as we did...
the other big issue is ntlm_auth is does take quite some time and is a mix of CPU-bound and server bound - basically you'll find it sticks like glue with older SAMBAs to just one of the KDC entries in AD.
radiusd.conf: max_request_time = 30 radiusd.conf: cleanup_delay = 5 radiusd.conf: max_requests = 8000000 #about 30K wireless users at peak * 256 ~= 8million max_requests , please note: This should be 256 multiplied by the number of clients - this is clients of the RADIUS server - ie NAS devices... 'those' clients, not wireless clients. hence this number should be more like 256 x 6 !! ;-)
radiusd.conf: # max_queue_size = 65536 (unsure why this is commented out) its commented out by default IIRC - you could try tweaking...but if somethings in the queue it hasnt really been handled - eg I believe its entry will not have been added to state table etc.....
how many CPUs and cores? you could try increasing the number of threads to eg 64 if you have the cores for the threads
mods-enabled/eap: timer_expire = 60 mods-enabled/eap: cache = disabled and you really should be using the cache capability. this dramatically improves the re-auth time of clients - hence shortcutting them
1. Is there a way to get more info along with the message "rlm_eap: No EAP session matching the State variable." ? - eg. Which NAS it came from, calling-station-id, etc.
you can add extra logging eg with linelog or detail log (reject log here)
for debugging you can just debug particular clients (NAS) or end user clients - just follow the instructions for commands as given by 'man radmin' - you may want to up the debug log level to 5 if you dont get enough info.
is this box running ina VM? the UDP performance isnt quite so good, you need a few tweaks to that part.
I would advise looking at new features available in 3.1.x - the native winbind client - VERY fast and nice...and the caching is improved.
you can ALSO help things out by using the 'QoS' packet handler "queue_priority" - setting that to EAP will ensure that those requests that are further along the EAP process will be handled first - which is nice for those auths that have already dealt with eg 8 or 9 of the RADIUS responses out of 11...rather than failing at that late stage....
alan
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Fri, Sep 16, 2016 at 07:44:24AM -0400, Dave Aldwinckle wrote:
- Will look into updating Samba, right now we are running 3.6, so too old to use the winbind_* stuff from mschap
Yes, Samba 4 is better. 3.6 is years out of support as well.
- We are running 3.0.10, which I understand is old. I may look into upgrading to 3.1, but I was hoping the next upgrade would be 4.0.
3.0.10 is one behind current stable release, so pretty good. 4.0 is development version, you really don't want to be running that. 3.1 is sort of half way, but still devel and not necessarily stable. Unlikely to give you much benefit over 3.0 unless you need some of the newer features.
The box is a VM, what did you mean by this?
is this box running ina VM? the UDP performance isnt quite so good, you need a few tweaks to that part.
We run all our RADIUS servers as Xen VMs. Never tweaked anything regarding this here. Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
On Fri, Sep 16, 2016 at 01:37:14PM +0000, A.L.M.Buxey@lboro.ac.uk wrote:
We run all our RADIUS servers as Xen VMs. Never tweaked anything regarding this here.
well, that'll be why you have problems then! ;-)
Haven't currently got any problems :-P Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
Hi,
- We are running 3.0.10, which I understand is old. I may look into upgrading to 3.1, but I was hoping the next upgrade would be 4.0.
3.1.x is the 'old' feature track - now taken up by 4.0.x - but 4.0.x is very vbleeding edge and having massive changes..... a 3.0.x config is quite quick to upgrade to a 3.1.x config.
The box is a VM, what did you mean by this?
you need to read the docs/guides for network (especially UDP) performance for your chosen VM platform - there are OS tweaks/guides for Xen, VMware, Hyper-V, EC2 etc. alan
On Sep 16, 2016, at 9:39 AM, A.L.M.Buxey@lboro.ac.uk wrote:
- We are running 3.0.10, which I understand is old. I may look into upgrading to 3.1, but I was hoping the next upgrade would be 4.0.
3.1.x is the 'old' feature track - now taken up by 4.0.x - but 4.0.x is very vbleeding edge and having massive changes..... a 3.0.x config is quite quick to upgrade to a 3.1.x config.
I'm about to drop v4 on the floor, shake it up, and put it back together again. :( Porting configs from v3.0 /v3.1 to v4 will take some effort. The modules will be 99% similar. The contents of "authorize", etc. will be 99% similar. The names of the processing sections will change, and the "listen" sections will change. It will all be very mechanical edits, but it's tedious. Alan DeKok.
Hi,
Porting configs from v3.0 /v3.1 to v4 will take some effort. The modules will be 99% similar. The contents of "authorize", etc. will be 99% similar. The names of the processing sections will change, and the "listen" sections will change.
It will all be very mechanical edits, but it's tedious.
whilst I'd strongly advise that orgs migrate by reading their configs and reimplementing (which gives them better understanding of the process and allows them to do things in a better way) I was planning on a simple script to convert the section names from old name to new name ;-) alan
I always prefer to do a re-write of the configs when upgrading. I find the end result is much cleaner, easier to understand, and performs better. I'm still having a problem matching "No EAP session matching state" to a particular user or request. The linelog below works, but it doesn't seem to trigger at the same time that "No EAP session matching state" does. I thought about moving log_state to sites-enabled/default, but " # The "session-state" attributes are not available here" so now I'm lost again. linelog log_state { format = "Rejected user: %{outer.request:User-Name} with State ID %{State} from NAS %{outer.request:NAS-IP-Address}" filename = syslog syslog_facility = news } sites-enabled/inner-tunnel Post-Auth-Type REJECT { attr_filter.access_reject # # Let the outer session know which module failed, and why. # update outer.session-state { &Module-Failure-Message := &request:Module-Failure-Message } log_state } Off-topic, but related: This particular bit "&Module-Failure-Message := &request:Module-Failure-Message" is populated with the first ERROR that the mschap module spits out, which for us is always "No NT-Domain was found in the User-Name." Since none of our User-Names have NT domains in them, the message is confusing. Is there any way to include the other errors? "Program returned code (1) and output 'Logon failure (0xc000006d)" would be a good one: (72) mschap: Creating challenge hash with username: nstestnexus@uwaterloo.ca (72) mschap: Client is using MS-CHAPv2 (72) mschap: Executing: /usr/bin/ntlm_auth --request-nt-key --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} --domain=%{%{mschap:NT-Domain}:-NEXUS} --challenge=%{%{mschap:Challenge}:-00} --nt-response=%{%{mschap:NT-Response}:-00}: (72) mschap: EXPAND --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} (72) mschap: --> --username=nstestnexus (72) mschap: ERROR: No NT-Domain was found in the User-Name (72) mschap: EXPAND --domain=%{%{mschap:NT-Domain}:-NEXUS} (72) mschap: --> --domain=NEXUS (72) mschap: Creating challenge hash with username: nstestnexus@uwaterloo.ca (72) mschap: EXPAND --challenge=%{%{mschap:Challenge}:-00} (72) mschap: --> --challenge=8953cfebb40e879e (72) mschap: EXPAND --nt-response=%{%{mschap:NT-Response}:-00} (72) mschap: --> --nt-response=f849c79ecfbba60fe76fe6e688b24d9a0f13eadb23632ef6 (72) mschap: ERROR: Program returned code (1) and output 'Logon failure (0xc000006d)' (72) mschap: External script failed (72) mschap: ERROR: External script says: Logon failure (0xc000006d) (72) mschap: ERROR: MS-CHAP2-Response is incorrect Thanks, Dave Dave Aldwinckle Network Services Information Systems & Technology University of Waterloo (519)-888-4567, x41145 On 16-09-16 09:52 AM, A.L.M.Buxey@lboro.ac.uk wrote:
Hi,
Porting configs from v3.0 /v3.1 to v4 will take some effort. The modules will be 99% similar. The contents of "authorize", etc. will be 99% similar. The names of the processing sections will change, and the "listen" sections will change.
It will all be very mechanical edits, but it's tedious. whilst I'd strongly advise that orgs migrate by reading their configs and reimplementing (which gives them better understanding of the process and allows them to do things in a better way) I was planning on a simple script to convert the section names from old name to new name ;-)
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Fri, Sep 16, 2016 at 10:37:13AM -0400, Dave Aldwinckle wrote:
Off-topic, but related: This particular bit "&Module-Failure-Message := &request:Module-Failure-Message" is populated with the first ERROR that the mschap module spits out, which for us is always "No NT-Domain was found in the User-Name." Since none of our User-Names have NT domains in them, the message is confusing. Is there any way to include the other errors? "Program returned code (1) and output 'Logon failure (0xc000006d)" would be a good one:
(72) mschap: Creating challenge hash with username: nstestnexus@uwaterloo.ca (72) mschap: Client is using MS-CHAPv2 (72) mschap: Executing: /usr/bin/ntlm_auth --request-nt-key --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} --domain=%{%{mschap:NT-Domain}:-NEXUS}
Set this to "--domain=NEXUS" instead? It's the expansion of the mschap:NT-Domain that's causing the error. You should be able to get the other errors by looking at &Module-Failure-Message[1], &Module-Failure-Message[2], etc, I think? Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
That did it! radiusd[28517]: (1691) Login incorrect (mschap: Program returned code (1) and output 'Logon failure (0xc000006d)'): [someuser] (from client prod1-east.eduroam.ca port 0 via TLS tunnel) Thanks. On 16-09-16 10:46 AM, Matthew Newton wrote:
On Fri, Sep 16, 2016 at 10:37:13AM -0400, Dave Aldwinckle wrote:
Off-topic, but related: This particular bit "&Module-Failure-Message := &request:Module-Failure-Message" is populated with the first ERROR that the mschap module spits out, which for us is always "No NT-Domain was found in the User-Name." Since none of our User-Names have NT domains in them, the message is confusing. Is there any way to include the other errors? "Program returned code (1) and output 'Logon failure (0xc000006d)" would be a good one:
(72) mschap: Creating challenge hash with username: nstestnexus@uwaterloo.ca (72) mschap: Client is using MS-CHAPv2 (72) mschap: Executing: /usr/bin/ntlm_auth --request-nt-key --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} --domain=%{%{mschap:NT-Domain}:-NEXUS} Set this to "--domain=NEXUS" instead? It's the expansion of the mschap:NT-Domain that's causing the error.
You should be able to get the other errors by looking at &Module-Failure-Message[1], &Module-Failure-Message[2], etc, I think?
Matthew
On Fri, Sep 16, 2016 at 11:07:19AM -0400, Dave Aldwinckle wrote:
That did it!
Good
radiusd[28517]: (1691) Login incorrect (mschap: Program returned code (1) and output 'Logon failure (0xc000006d)'): [someuser] (from client prod1-east.eduroam.ca port 0 via TLS tunnel)
FWIW, if you use the winbind client stuff in the latest FR/Samba, you get much nicer error reporting. None of the "program returned code" stuff, as it's not running a program. Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
participants (4)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Dave Aldwinckle -
Matthew Newton