So, I've just compiled up the current "master", and a few things stand out. Using my existing 2.1.12 config: 1. EAP-TTLS/MSCHAP doesn't seem to work any more; the MS-CHAP challenge/response are wrong. PEAP works fine. Haven't looked into this yet. 2. rlm_eap_tls now mandates "private_key_password" even if the key is not encrypted on disk. You can specify anything - but you must specify it. Behaviour change, but not particularly onerous. 3. Fast Session resumption seems to give a segfault - request_finish calls pairfree on process.c:1085 and the value seems to be corrupt. The backtrace is a bit useless, since most of the values are optimised out (grr gcc) but I will try to get more info. Will follow up with more as I figure out the cause(s)
On 10/09/2011 11:20 AM, Phil Mayers wrote:
So, I've just compiled up the current "master", and a few things stand out. Using my existing 2.1.12 config:
1. EAP-TTLS/MSCHAP doesn't seem to work any more; the MS-CHAP challenge/response are wrong. PEAP works fine. Haven't looked into this yet.
I can't figure this out at all. eapol_test and FreeRADIUS 2.1.12 seem to work, but not against master. What's REALLY weird is what I noticed accidentally; if I kick off eapol_test when FreeRADIUS isn't running, it sends the 1st packet and gets and error and sleeps for a second or two; if I then switch to another window and START FreeRADIUS, EAP-TTLS/MSCHAPv2 then works ONCE. Very, very weird.
Phil Mayers wrote:
What's REALLY weird is what I noticed accidentally; if I kick off eapol_test when FreeRADIUS isn't running, it sends the 1st packet and gets and error and sleeps for a second or two; if I then switch to another window and START FreeRADIUS, EAP-TTLS/MSCHAPv2 then works ONCE.
Very, very weird.
Hmm... after a bit more testing, it seems to work for me. I managed to get multiple versions of OpenSSL installe don my dev machine. Once I fixed that, everything was OK. Alan DeKok.
On 10/09/2011 11:20 AM, Phil Mayers wrote:
So, I've just compiled up the current "master", and a few things stand out. Using my existing 2.1.12 config:
Also: update control { Virtual-Server := eap-inner2 } ...gives me warnings: WARNING: You are modifying the value of virtual attribute Virtual-Server. This is not supported. Am I doing this wrong? I was under the impression you could set Virtual-Server in the outer tunnel, to control which inner tunnel you used?
Phil Mayers wrote:
Also:
update control { Virtual-Server := eap-inner2 }
...gives me warnings:
WARNING: You are modifying the value of virtual attribute Virtual-Server. This is not supported.
Am I doing this wrong? I was under the impression you could set Virtual-Server in the outer tunnel, to control which inner tunnel you used?
Yes, that's allowed. The issue is there should be *two* attributes. One to say "which virtual server am I in", and another to say "go use this virtual server". Right now there's one. Hence the confusion. Alan DeKok.
Phil Mayers wrote:
So, I've just compiled up the current "master", and a few things stand out. Using my existing 2.1.12 config:
1. EAP-TTLS/MSCHAP doesn't seem to work any more; the MS-CHAP challenge/response are wrong. PEAP works fine. Haven't looked into this yet.
Ugh. Segv. The SSL session variable is NULL. :( It looks like the "free session" code is being called before the "generate MPPE keys" code.
2. rlm_eap_tls now mandates "private_key_password" even if the key is not encrypted on disk. You can specify anything - but you must specify it. Behaviour change, but not particularly onerous.
I'll take a look.
3. Fast Session resumption seems to give a segfault - request_finish calls pairfree on process.c:1085 and the value seems to be corrupt. The backtrace is a bit useless, since most of the values are optimised out (grr gcc) but I will try to get more info.
Edit Make.inc, delete CFLAGS ... "-O2" Alan DeKok.
On 09/10/11 11:20, Phil Mayers wrote:
So, I've just compiled up the current "master", and a few things stand
All, FYI we just had a segfault on the "master" server. This machine is only handling periodic nagios probes, so it wasn't under load. Annoyingly I had core dumps disabled, which I've now enabled, so I have little idea what caused it, but the last thing it logged was: Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as zombie (it looks like it is dead). Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as dead. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert entry into proxy list. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert retransmission into the proxy list. Wed Oct 12 13:03:01 2011 : Error: No response to status check 20332 for home server 194.83.56.249 port 1812 Still haven't found the time to look into the SSL session resumption or TTLS issues I found; it'll be middle of next week before I have free time.
Phil Mayers wrote:
FYI we just had a segfault on the "master" server. This machine is only handling periodic nagios probes, so it wasn't under load.
Annoyingly I had core dumps disabled, which I've now enabled, so I have little idea what caused it, but the last thing it logged was:
Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as zombie (it looks like it is dead). Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as dead. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert entry into proxy list. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert retransmission into the proxy list.
Yeah... Arran has seen that too. I can't reproduce it on my dev machine. ????
Wed Oct 12 13:03:01 2011 : Error: No response to status check 20332 for home server 194.83.56.249 port 1812
Still haven't found the time to look into the SSL session resumption or TTLS issues I found; it'll be middle of next week before I have free time.
I'm out of circulation for ~4 days while I do real work. Alan DeKok.
On 12 Oct 2011, at 17:01, Alan DeKok wrote:
Phil Mayers wrote:
FYI we just had a segfault on the "master" server. This machine is only handling periodic nagios probes, so it wasn't under load.
Annoyingly I had core dumps disabled, which I've now enabled, so I have little idea what caused it, but the last thing it logged was:
Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as zombie (it looks like it is dead). Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as dead. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert entry into proxy list. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert retransmission into the proxy list.
Yeah... Arran has seen that too. I can't reproduce it on my dev machine. ????
Phil: I can't reproduce it artificially, only on a live server, so if you can that'd be a huge help! Arran Cudbard-Bell a.cudbardb@freeradius.org Betelwiki, Betelwiki, Betelwiki.... http://wiki.freeradius.org/ !
On 12/10/11 16:06, Arran Cudbard-Bell wrote:
On 12 Oct 2011, at 17:01, Alan DeKok wrote:
Phil Mayers wrote:
FYI we just had a segfault on the "master" server. This machine is only handling periodic nagios probes, so it wasn't under load.
Annoyingly I had core dumps disabled, which I've now enabled, so I have little idea what caused it, but the last thing it logged was:
Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as zombie (it looks like it is dead). Wed Oct 12 13:02:57 2011 : Proxy: Marking home server 194.83.56.249 port 1812 as dead. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert entry into proxy list. Wed Oct 12 13:03:00 2011 : Proxy: (20331) Failed to insert retransmission into the proxy list.
Yeah... Arran has seen that too. I can't reproduce it on my dev machine. ????
Phil: I can't reproduce it artificially, only on a live server, so if you can that'd be a huge help!
Well, it took the best part of a week, and it might have been a chance/timing issue. I've enabled core dumps and will see if it happens again...
On 12 Oct 2011, at 21:02, Alan Buxey wrote:
Hi,
Well, it took the best part of a week, and it might have been a chance/timing issue. I've enabled core dumps and will see if it happens again...
...do what I was doing for RADSEC checks - just use eg iptables to block the remote proxy when its needed...
No, i've tried that, it's something more complex. The server behaves normally when a proxy server is down. Arran Cudbard-Bell a.cudbardb@freeradius.org Betelwiki, Betelwiki, Betelwiki.... http://wiki.freeradius.org/ !
Hi,
No, i've tried that, it's something more complex. The server behaves normally when a proxy server is down.
with status-check enabled for it? I ask because it was 100% reproducable for RADSEC in 3.x which is one reason why the server doesnt let you do status-check for RADSEC proxies...(it does another method now...) alan
On 12 Oct 2011, at 21:44, Alan Buxey wrote:
Hi,
No, i've tried that, it's something more complex. The server behaves normally when a proxy server is down.
with status-check enabled for it?
Yes. What's really weird is that the server thats apparently down is one of the belnet servers, which you wouldn't expect to be unreachable... Arran Cudbard-Bell a.cudbardb@freeradius.org Betelwiki, Betelwiki, Betelwiki.... http://wiki.freeradius.org/ !
Hi, I have a test server running Freeradius 3.0.0 from git and I can reproduce this bug easily, let me know if I can provide anything help debug. regards -- View this message in context: http://freeradius.1045715.n5.nabble.com/Testing-3-0-master-tp4884800p4909911... Sent from the FreeRadius - Dev mailing list archive at Nabble.com.
On 17 Oct 2011, at 15:47, Steven Coutts wrote:
Hi,
I have a test server running Freeradius 3.0.0 from git and I can reproduce this bug easily, let me know if I can provide anything help debug.
Procedure to reproduce the bug ? :) -Arran Arran Cudbard-Bell a.cudbardb@freeradius.org Betelwiki, Betelwiki, Betelwiki.... http://wiki.freeradius.org/ !
On Monday 17 Oct 2011 14:49:33 Arran Cudbard-Bell wrote:
Procedure to reproduce the bug ? :)
If I fire anything off to the upstream eduroam proxies, it either just fails or segfaults, normally fails on the first try, then segfaults when I re-try. Marking home server 194.82.174.185 port 1812 as zombie (it looks like it is dead). PING: Zombie period is over for home server jrs0 Marking home server 194.82.174.185 port 1812 as dead. PING: Already pinging home server jrs0 PING: Waiting 4 seconds for response to ping Sending Status-Server of id 136 to 194.82.174.185 port 1812 Message-Authenticator := 0x00 NAS-Identifier := "Status Check 0. Are you alive?" PING: Next status packet in 30 seconds Waking up in 3.9 seconds. rad_recv: Access-Request packet from host 10.0.2.52 port 32769, id=4, length=206 (2) Failed to insert entry into proxy list. (2) Failed to insert initial packet into the proxy list. No Post-Proxy-Type Fail: ignoring Waking up in 2.8 seconds. rad_recv: Access-Request packet from host 10.0.2.52 port 32769, id=4, length=206 Segmentation fault Program received signal SIGSEGV, Segmentation fault. 0x000000000042a6f4 in request_proxied (request=0x87f720, action=3) at process.c:2691 2691 if ((home->state == HOME_STATE_IS_DEAD) || (gdb) bt #0 0x000000000042a6f4 in request_proxied (request=0x87f720, action=3) at process.c:2691 #1 0x000000000042e65b in request_receive (listener=0x871d30, packet=0x883e40, client=0x822890, fun=0x40b5f0 <rad_authenticate>) at process.c:1245 #2 0x0000000000419746 in auth_socket_recv (listener=0x871d30) at listen.c:1359 #3 0x0000000000429348 in event_socket_handler (xel=<value optimized out>, fd=0, ctx=0x1c) at process.c:3269 #4 0x00002aaaaaad6854 in fr_event_loop (el=0x85c3d0) at event.c:415 #5 0x00000000004203de in main (argc=<value optimized out>, argv=<value optimized out>) at radiusd.c:424 The home server isn't dead, but when using 3.0.0 it always says it's dead :( Regards -- Steven Coutts stevec@couttsnet.com
On Monday 17 Oct 2011 15:13:28 Steven Coutts wrote:
If I fire anything off to the upstream eduroam proxies, it either just fails or segfaults, normally fails on the first try, then segfaults when I re-try.
Hmm rather annoyingly it's stopped happening now :( I re-compiled after taking -O2 out of Make.inc so I could see some of the <value optimized out> from gdb output, and it started working, compiled again after replacing -O2 and it is still working. -- Steven Coutts stevec@couttsnet.com
On 17 Oct 2011, at 16:48, Steven Coutts wrote:
On Monday 17 Oct 2011 15:13:28 Steven Coutts wrote:
If I fire anything off to the upstream eduroam proxies, it either just fails or segfaults, normally fails on the first try, then segfaults when I re-try.
Hmm rather annoyingly it's stopped happening now :(
I re-compiled after taking -O2 out of Make.inc so I could see some of the <value optimized out> from gdb output, and it started working, compiled again after replacing -O2 and it is still working.
I managed to catch it under GDB and Alan has committed a hacky fix. -Arran Arran Cudbard-Bell a.cudbardb@freeradius.org Betelwiki, Betelwiki, Betelwiki.... http://wiki.freeradius.org/ !
On 10/09/2011 11:20 AM, Phil Mayers wrote:
So, I've just compiled up the current "master", and a few things stand out. Using my existing 2.1.12 config:
1. EAP-TTLS/MSCHAP doesn't seem to work any more; the MS-CHAP challenge/response are wrong. PEAP works fine. Haven't looked into this yet.
2. rlm_eap_tls now mandates "private_key_password" even if the key is not encrypted on disk. You can specify anything - but you must specify it. Behaviour change, but not particularly onerous.
3. Fast Session resumption seems to give a segfault - request_finish calls pairfree on process.c:1085 and the value seems to be corrupt. The backtrace is a bit useless, since most of the values are optimised out (grr gcc) but I will try to get more info.
More info - todays HEAD dies with: (14) peap : Success (14) peap : Adding cached attributes to the reply: 8:��9 <INVALID-TOKEN> <INVALID-TOKEN> (14) eap : Freeing handler *** glibc detected *** /usr/local/sbin/radiusd: double free or corruption (out): 0x000000000086f670 *** ======= Backtrace: ========= /lib64/libc.so.6[0x398767245f] /lib64/libc.so.6(cfree+0x4b)[0x39876728bb] /usr/local/lib/libfreeradius-radius-3.0.0.so(pairfree+0x1f)[0x2aaaaaac3e1f] /usr/local/sbin/radiusd(session_close+0x39)[0x4387f9] /usr/local/sbin/radiusd(session_free+0x36)[0x4388a6] /usr/local/lib/rlm_eap.so(eap_handler_free+0x97)[0x2aaaac139837] /usr/local/lib/rlm_eap.so[0x2aaaac1379ce] /usr/local/sbin/radiusd(modcall+0xa2d)[0x41f6dd] /usr/local/sbin/radiusd(indexed_modcall+0xc5)[0x41c6e5] /usr/local/sbin/radiusd(rad_authenticate+0x855)[0x40be55] /usr/local/sbin/radiusd[0x42bfa3] /usr/local/sbin/radiusd[0x429e9b] /usr/local/sbin/radiusd(request_insert+0x240)[0x42bdb0] /usr/local/sbin/radiusd(request_receive+0xa9)[0x42e559] /usr/local/sbin/radiusd[0x419756] /usr/local/sbin/radiusd[0x429378] /usr/local/lib/libfreeradius-radius-3.0.0.so(fr_event_loop+0x344)[0x2aaaaaac7814] /usr/local/sbin/radiusd(main+0x57e)[0x4203fe] /lib64/libc.so.6(__libc_start_main+0xf4)[0x398761d994] ...when doing an SSL session resume. No more time to look today, will investigate tomorrow. p.s. I like the new quieter build!
On 17 Oct 2011, at 20:58, Phil Mayers wrote:
On 10/09/2011 11:20 AM, Phil Mayers wrote:
So, I've just compiled up the current "master", and a few things stand out. Using my existing 2.1.12 config:
1. EAP-TTLS/MSCHAP doesn't seem to work any more; the MS-CHAP challenge/response are wrong. PEAP works fine. Haven't looked into this yet.
2. rlm_eap_tls now mandates "private_key_password" even if the key is not encrypted on disk. You can specify anything - but you must specify it. Behaviour change, but not particularly onerous.
3. Fast Session resumption seems to give a segfault - request_finish calls pairfree on process.c:1085 and the value seems to be corrupt. The backtrace is a bit useless, since most of the values are optimised out (grr gcc) but I will try to get more info.
Backtrace please. -Arran Arran Cudbard-Bell a.cudbardb@freeradius.org Betelwiki, Betelwiki, Betelwiki.... http://wiki.freeradius.org/ !
On 17 Oct 2011, at 21:47, Arran Cudbard-Bell wrote:
On 17 Oct 2011, at 20:58, Phil Mayers wrote:
On 10/09/2011 11:20 AM, Phil Mayers wrote:
So, I've just compiled up the current "master", and a few things stand out. Using my existing 2.1.12 config:
1. EAP-TTLS/MSCHAP doesn't seem to work any more; the MS-CHAP challenge/response are wrong. PEAP works fine. Haven't looked into this yet.
2. rlm_eap_tls now mandates "private_key_password" even if the key is not encrypted on disk. You can specify anything - but you must specify it. Behaviour change, but not particularly onerous.
3. Fast Session resumption seems to give a segfault - request_finish calls pairfree on process.c:1085 and the value seems to be corrupt. The backtrace is a bit useless, since most of the values are optimised out (grr gcc) but I will try to get more info.
Backtrace please.
Oops didn't see it, sorry. Arran Cudbard-Bell a.cudbardb@freeradius.org Betelwiki, Betelwiki, Betelwiki.... http://wiki.freeradius.org/ !
Phil Mayers wrote:
More info - todays HEAD dies with:
(14) peap : Success (14) peap : Adding cached attributes to the reply: 8:��9 <INVALID-TOKEN> <INVALID-TOKEN> (14) eap : Freeing handler *** glibc detected *** /usr/local/sbin/radiusd: double free or
Hmm... my quick checks a while ago showed that the same pointer was being passed into the cache as was coming out. So the corrupt data above really seems to indicate that the memory was free'd and re-used. The sad thing is that I run it under "valgrind", and all I get is the SEGV. I don't see a double free. :(
p.s. I like the new quieter build!
Yeah, much better. Alan DeKok.
On 17/10/11 21:03, Alan DeKok wrote:
Phil Mayers wrote:
More info - todays HEAD dies with:
(14) peap : Success (14) peap : Adding cached attributes to the reply: 8:��9<INVALID-TOKEN> <INVALID-TOKEN> (14) eap : Freeing handler *** glibc detected *** /usr/local/sbin/radiusd: double free or
Hmm... my quick checks a while ago showed that the same pointer was being passed into the cache as was coming out. So the corrupt data above really seems to indicate that the memory was free'd and re-used.
The sad thing is that I run it under "valgrind", and all I get is the SEGV. I don't see a double free. :(
The double free seems to be timing-related; for example, just now it did this: (14) peap : Adding cached attributes to the reply: 8>��9 <INVALID-TOKEN> "" (14) eap : Freeing handler (14) [eap] = ok <snip> (14) [detail] = ok Sending Access-Accept of id 14 to 155.198.51.229 port 42514 MS-MPPE-Recv-Key = 0x6... MS-MPPE-Send-Key = 0x3... EAP-Message = 0x03030004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "@ic.ac.uk" *** glibc detected *** /usr/local/sbin/radiusd: double free or corruption (!prev): 0x0000000016c80c70 *** Segmentation fault i.e. it managed to send the Access-Accept for the resumed session before the accident! Weirder and weirder. I am looking into it now.
On 18/10/11 15:16, Phil Mayers wrote:
On 17/10/11 21:03, Alan DeKok wrote:
Phil Mayers wrote:
More info - todays HEAD dies with:
(14) peap : Success (14) peap : Adding cached attributes to the reply: 8:��9<INVALID-TOKEN> <INVALID-TOKEN> (14) eap : Freeing handler *** glibc detected *** /usr/local/sbin/radiusd: double free or
Hmm... my quick checks a while ago showed that the same pointer was being passed into the cache as was coming out. So the corrupt data above really seems to indicate that the memory was free'd and re-used.
The sad thing is that I run it under "valgrind", and all I get is the SEGV. I don't see a double free. :(
The double free seems to be timing-related; for example, just now it did this:
Ok, valgrind seems to be catching lots of: Invalid read of size 4 at 0x4C18E5B: vp_prints (print.c:493) by 0x4C18F43: vp_print (print.c:525) by 0x4259EB: debug_pair_list (valuepair.c:820) by 0x4367FE: tls_success (tls.c:2068) by 0x688C974: eaptls_success (eap_tls.c:118) by 0x66854D9: eaptype_call (eap.c:189) by 0x6685E9D: eaptype_select (eap.c:424) by 0x66847E3: eap_authenticate (rlm_eap.c:327) by 0x41F6DC: modcall (modcall.c:298) by 0x41C6E4: indexed_modcall (modules.c:788) by 0x40BE54: rad_authenticate (auth.c:381) by 0x42BFA2: request_running (process.c:1137) Address 0x6f338c0 is 32 bytes inside a block of size 320 free'd at 0x4A05D21: free (vg_replace_malloc.c:325) by 0x4C21E1E: pairfree (valuepair.c:224) by 0x4387F8: session_close (tls.c:436) by 0x4388A5: session_free (tls.c:475) by 0x6686836: eap_handler_free (mem.c:167) by 0x66849CD: eap_authenticate (rlm_eap.c:455) by 0x41F6DC: modcall (modcall.c:298) by 0x41C6E4: indexed_modcall (modules.c:788) by 0x40BE54: rad_authenticate (auth.c:381) by 0x42BFA2: request_running (process.c:1137) by 0x429E9A: request_queue_or_run (process.c:786) by 0x42BDAF: request_insert (process.c:1387) ...for me. I'm not very familiar with valgrind, but from what I can see, the 1st call stack is reading memory (the cached VALUE_PAIR* stuff I guess) that was freed at the location given in the 2nd call stack. Any suggestions for more magical incantations? (I haven't had much time today - our so-called NREN burnt 2 hours of my time moving patch leads from one port on a core router to another)
Hi, hmmm...i wonder...is it the new state machine that is native in 3.0 ? not sure if setting the flag DEBUG_STATE_MACHINE (which will print out every state transition that the request goes through...) will help solve this? alan
Phil Mayers wrote:
Ok, valgrind seems to be catching lots of:
Weird. I don't recall seeing that on my runs with valgrind.
...for me. I'm not very familiar with valgrind, but from what I can see, the 1st call stack is reading memory (the cached VALUE_PAIR* stuff I guess) that was freed at the location given in the 2nd call stack.
Yes.
Any suggestions for more magical incantations?
$ git pull :) The issue is that the cached VPs were being free'd too early. They should be freed only when SSL does the "free session" callback. The bug was that they were being free'd when the EAP "success" was being sent back. With session caching, those VPs should stick around until OpenSSL thinks that the session is free'd. There's a callback just for that, too. The code is fixed in "master", and a related memory leak is closed in the v2.1.x branch. Alan DeKok.
On 10/19/2011 09:47 AM, Alan DeKok wrote:
$ git pull
:)
Awesome, that's working now.
The issue is that the cached VPs were being free'd too early. They should be freed only when SSL does the "free session" callback. The bug was that they were being free'd when the EAP "success" was being sent back.
With session caching, those VPs should stick around until OpenSSL thinks that the session is free'd. There's a callback just for that, too.
The code is fixed in "master", and a related memory leak is closed in the v2.1.x branch.
Ah ha - presumably that was why my 2.1.12 install ballooned it's RAM; it was nothing to do with 2.1.12, but the fact I'd enabled session resumption. I guess everyone out there is restarting their servers nightly!
Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Ah ha - presumably that was why my 2.1.12 install ballooned it's RAM; it was nothing to do with 2.1.12, but the fact I'd enabled session resumption.
I guess everyone out there is restarting their servers nightly!
We have session resumption enabled (lifetime 24 and max_entries 8192) and we do not have any problems: ---- ac56@iodine:~$ stat /proc/$(pgrep freeradius) File: `/proc/6397' Size: 0 Blocks: 0 IO Block: 1024 directory Device: 3h/3d Inode: 65547285 Links: 7 Access: (0555/dr-xr-xr-x) Uid: ( 104/ freerad) Gid: ( 107/ freerad) Access: 2011-10-14 10:11:20.817205244 +0100 Modify: 2011-10-14 10:11:20.817205244 +0100 Change: 2011-10-14 10:11:20.817205244 +0100 TOP: 6397 freerad 20 0 214m 68m 3752 S 0.8 13.6 231:24.81 freeradius ---- ac56@chlorine:~$ stat /proc/$(pgrep freeradius) File: `/proc/28449' Size: 0 Blocks: 0 IO Block: 1024 directory Device: 3h/3d Inode: 42368844 Links: 7 Access: (0555/dr-xr-xr-x) Uid: ( 103/ freerad) Gid: ( 104/ freerad) Access: 2011-10-14 10:11:45.126296091 +0100 Modify: 2011-10-14 10:11:45.126296091 +0100 Change: 2011-10-14 10:11:45.126296091 +0100 28449 freerad 20 0 94276 26m 3796 S 3.1 5.3 69:32.58 freeradius ---- Only restarted on the 14th as I was adding a new configuration tweaking (that nice rlm_replicate bits for eduroam accounting proxying) but our setup can run for weeks with no memory leak woes. Ages ago we did have a rlm_detail related memory leak but I think that was fixed in 2.1.11. The extra high memory usage on ours is probably related to the rlm_perl instance[1]. Cheers [1] http://www.mail-archive.com/freeradius-users@lists.freeradius.org/msg65781.h... -- Alexander Clouter .sigmonster says: BOFH excuse #58: high pressure system failure
On 19/10/11 12:17, Alexander Clouter wrote:
Phil Mayers<p.mayers@imperial.ac.uk> wrote:
Ah ha - presumably that was why my 2.1.12 install ballooned it's RAM; it was nothing to do with 2.1.12, but the fact I'd enabled session resumption.
I guess everyone out there is restarting their servers nightly!
We have session resumption enabled (lifetime 24 and max_entries 8192) and we do not have any problems:
Weird; AFAICT there's a clear memory leak prior to Alan's fix. Which version are you running? Are you perhaps not caching any reply VPs?
Phil Mayers <p.mayers@imperial.ac.uk> wrote:
We have session resumption enabled (lifetime 24 and max_entries 8192) and we do not have any problems:
Weird; AFAICT there's a clear memory leak prior to Alan's fix. Which version are you running?
~70c2285ish
Are you perhaps not caching any reply VPs?
Just the User-Name. Cheers -- Alexander Clouter .sigmonster says: Learn to pause -- or nothing worthwhile can catch up to you.
On 10/20/2011 03:46 PM, Alexander Clouter wrote:
Phil Mayers<p.mayers@imperial.ac.uk> wrote:
We have session resumption enabled (lifetime 24 and max_entries 8192) and we do not have any problems:
Weird; AFAICT there's a clear memory leak prior to Alan's fix. Which version are you running?
~70c2285ish
Ok, so 2.1.12 basically. I honestly don't understand how we're having problems and you're not. How many auths are you doing per day? How many are actually triggering session resumption? What are your "cache { }" settings?
Are you perhaps not caching any reply VPs?
Just the User-Name.
Interesting. I am setting Cached-Session-Policy on inner-tunnel, then extracting it in post-auth on outer and doing all decisions there. It's segfaulted a couple of times since then. The most recent occurrence was inside the "detail" module we run in post-auth, and I was able to examine the reply VPs - sure enough, the first VP in the list was a corrupted version of the Cached-Session-Reply VP; the ->next pointer and all the rest of the VPs were intact, but that one VP had corrupted payload, and an absurd length. Weird stuff...
Phil Mayers wrote:
It's segfaulted a couple of times since then. The most recent occurrence was inside the "detail" module we run in post-auth, and I was able to examine the reply VPs - sure enough, the first VP in the list was a corrupted version of the Cached-Session-Reply VP; the ->next pointer and all the rest of the VPs were intact, but that one VP had corrupted payload, and an absurd length.
Weird stuff...
I put in a hack to set the cached VPs to NULL when the session is free'd. Maybe that will help. Alan DeKok.
On 10/20/2011 04:26 PM, Alan DeKok wrote:
Phil Mayers wrote:
It's segfaulted a couple of times since then. The most recent occurrence was inside the "detail" module we run in post-auth, and I was able to examine the reply VPs - sure enough, the first VP in the list was a corrupted version of the Cached-Session-Reply VP; the ->next pointer and all the rest of the VPs were intact, but that one VP had corrupted payload, and an absurd length.
Weird stuff...
I put in a hack to set the cached VPs to NULL when the session is free'd. Maybe that will help.
I saw; I was about to apply it and re-build our package, when I had an awful thought... Is it possible that the following sequence of events is occurring: 1. thread #1: client does session resumption a split second before expiry, gets cached VPs 2. thread #1: blocks (e.g. doing SQL) 3. thread #2: receives new TLS session, calls SSL_CTX_flush_sessions 4. thread #2: calls pairfree() on VPs from session 1, now expired 5. thread #1: resumes - boom It might explain why it happens very rarely, and why we see it but Alex doesn't (load-related - Imperial has a few more students that SOAS IIRC)
On 10/20/2011 05:01 PM, Phil Mayers wrote:
Is it possible that the following sequence of events is occurring:
1. thread #1: client does session resumption a split second before expiry, gets cached VPs 2. thread #1: blocks (e.g. doing SQL) 3. thread #2: receives new TLS session, calls SSL_CTX_flush_sessions 4. thread #2: calls pairfree() on VPs from session 1, now expired 5. thread #1: resumes - boom
It might explain why it happens very rarely, and why we see it but Alex doesn't (load-related - Imperial has a few more students that SOAS IIRC)
Having gone for a run and thought about this en-route, I'm sure this must be the cause. Alex of course doesn't see it because he's not running c145c7dabbd4 in which the "free" occurs (why he's not seeing the memory leak I don't know - maybe *that* is load-related) Quite how we solve it I don't know... I'm going to (shudder) look at the OpenSSL source to see if it does any locking around session objects; I just don't see from the API how you can used the get/set_ex_data functions safely in a threaded environment!
On 10/20/2011 07:18 PM, Phil Mayers wrote:
Quite how we solve it I don't know... I'm going to (shudder) look at the OpenSSL source to see if it does any locking around session objects; I just don't see from the API how you can used the get/set_ex_data functions safely in a threaded environment!
Oh dear oh dear oh dear... So - it turns out the session callbacks that we set with: SSL_CTX_sess_set_{new,get,remove}_cb ...are not in fact called when you would think. In particular, the "remove" callback is NOT called when the session refcount==0. It is called when it's removed from the list of "will accept a resume". The actual session object refcount can go to zero at a later time, so freeing the "ex_data" in the "remove" callback is definitely the wrong thing to do. It gets worse: OpenSSL does provide a way to register create/duplicate/delete callbacks for "ex_data" objects that will be called at the proper time; but the API is extremely verbose and AFAICT largely undocumented. But to remove the cached VPs, that's what we would need to do. Sigh. It's like they were deliberately trying to make life difficult...
Phil Mayers wrote:
Oh dear oh dear oh dear...
So - it turns out the session callbacks that we set with:
SSL_CTX_sess_set_{new,get,remove}_cb
...are not in fact called when you would think.
I love OpenSSL. <sigh>
Sigh. It's like they were deliberately trying to make life difficult...
And people say FreeRADIUS is hard. Right... Alan DeKok.
On 10/20/2011 10:35 PM, Alan DeKok wrote:
Sigh. It's like they were deliberately trying to make life difficult...
And people say FreeRADIUS is hard. Right...
For those not watching the commits, Alan has just pulled a couple of fixes for this into master and v2.1.x; I have tested both and they seem to work - testing would be good. The patch to v2.1.x is quite small - the eaptls_session_free function is already there and unused, it was just a case of creating the "ex data" index on the session rather than SSL object; the code in master is full of a bunch of more logging noise, but is basically the same thing.
Phil Mayers <p.mayers@imperial.ac.uk> wrote:
We have session resumption enabled (lifetime 24 and max_entries 8192) and we do not have any problems:
Weird; AFAICT there's a clear memory leak prior to Alan's fix. Which version are you running?
~70c2285ish
Ok, so 2.1.12 basically. I honestly don't understand how we're having problems and you're not.
How many auths are you doing per day? How many are actually triggering session resumption? What are your "cache { }" settings?
Most of our 802.1X authentications hit a single FreeRADIUS box (anycast'ing reasons) and the '@soas.ac.uk' only authentications make up about 2/3'rd of the requests: 13;32175 14;26469 15;6454 16;4803 17;29634 18;33874 19;30787 20;28765 MAC-auth[2]'s to the same boxes (more evenly distributed): 13;4547 14;3601 15;1520 16;1287 17;3997 18;5205 19;4919 20;4366 Bear in mind, these RADIUS servers are *low* powered ARM boxen[3], our authentications (and authorisation policy) comes all via LDAP. SQL is only used to log to.
Are you perhaps not caching any reply VPs?
Just the User-Name.
Interesting.
I am setting Cached-Session-Policy on inner-tunnel, then extracting it in post-auth on outer and doing all decisions there.
We do *all* our authorisation on the outer post-auth layer too but all around User-Name. I use rlm_perl to cache Ldap-UserDn from the first EAP packet to make it available on the final one (so we only make two LDAP lookups per EAP *session*).
Weird stuff...
In case you are curious, here's everything (minus secrets): http://stuff.digriz.org.uk/freeradius.tar.gz sites-enabled/* and LOCAL is where the action is. I plan to put the bulk of it up on my personal website one day... Cheers [1] SELECT extract(day from timestamp), COUNT(*) FROM dot1x_auth WHERE realm != 'NULL' AND packet_type = 'Access-Accept' AND timestamp > 'today'::date - '7 days'::interval GROUP BY extract(day from timestamp) ORDER BY extract(day from timestamp); [2] same as [1] but realm != 'NULL -> realm = 'NULL' [3] http://www.globalscaletechnologies.com/p-35-openrd-ultimate.aspx -- Alexander Clouter .sigmonster says: Editing is a rewording activity.
On 10/19/2011 10:10 AM, Phil Mayers wrote:
Ah ha - presumably that was why my 2.1.12 install ballooned it's RAM; it was nothing to do with 2.1.12, but the fact I'd enabled session resumption.
Oops; I applied the patch in c145c7dabbd48 to my 2.1.12 servers, and last night we had a segfault after running fine for several hours. I restarted under GDB and caught a backtrace: #0 paircopyvp (vp=0x101010101010101) at valuepair.c:327 n = <value optimized out> #1 0x00002af27098632c in paircopy2 (vp=0x101010101010101, attr=-1) at valuepair.c:372 first = (VALUE_PAIR *) 0x2aaab0289b60 n = (VALUE_PAIR *) 0x2aaab0289b60 last = (VALUE_PAIR **) 0x2aaab0289b88 #2 0x00002af272007b6e in eaptls_success (handler=0x177ce3a0, peap_flag=0) at eap_tls.c:183 reply = {code = 3 '\003', id = 230 '�', length = 4, flags = 0 '\0', data = 0x0, dlen = 0} vp = (VALUE_PAIR *) 0x101010101010101 vps = (VALUE_PAIR *) 0x0 request = (REQUEST *) 0x2aaab010b880 tls_session = (tls_session_t *) 0x177b4a00 Not sure if it's a new or old bug. Sadly I was using my smartphone from a restaurant to debug (!) and accidentally closed gdb before dumping a core file.
Phil Mayers wrote:
Oops; I applied the patch in c145c7dabbd48 to my 2.1.12 servers, and last night we had a segfault after running fine for several hours. I restarted under GDB and caught a backtrace:
#0 paircopyvp (vp=0x101010101010101) at valuepair.c:327
That's not a real pointer... I've pushed a "fix". It sets the cached VP pointer to NULL when it gets deleted. That may help... Otherwise, it's an OpenSSL bug for it to return an invalid pointer. Alan DeKok.
On 10/20/2011 01:25 PM, Alan DeKok wrote:
Phil Mayers wrote:
Oops; I applied the patch in c145c7dabbd48 to my 2.1.12 servers, and last night we had a segfault after running fine for several hours. I restarted under GDB and caught a backtrace:
#0 paircopyvp (vp=0x101010101010101) at valuepair.c:327
That's not a real pointer...
Indeed not. I hate OpenSSL...
On 10/20/2011 01:25 PM, Alan DeKok wrote:
Phil Mayers wrote:
Oops; I applied the patch in c145c7dabbd48 to my 2.1.12 servers, and last night we had a segfault after running fine for several hours. I restarted under GDB and caught a backtrace:
#0 paircopyvp (vp=0x101010101010101) at valuepair.c:327
That's not a real pointer...
I've pushed a "fix". It sets the cached VP pointer to NULL when it gets deleted. That may help...
Otherwise, it's an OpenSSL bug for it to return an invalid pointer.
I'm looking at the code for handling SSL sessions, and I'm not sure it's right with regards reference counting. I'm comparing it with the code in mod_ssl, which I'm assuming is definitely right; in their "delete" callback, they don't call SSL_SESSION_free(). They also return "0" from their "new" callback, indicating as they say: /* * return 0 which means to OpenSSL that the pNew is still * valid and was not freed by us with SSL_SESSION_free(). */ return 0; Are we sure the session code is doing the right things? Of course, the crappy OpenSSL API is really, really badly documented so it's hard to be sure...
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
Phil Mayers wrote:
On 10/20/2011 01:25 PM, Alan DeKok wrote: I'm looking at the code for handling SSL sessions, and I'm not sure it's right with regards reference counting.
I have no idea...
I'm comparing it with the code in mod_ssl, which I'm assuming is definitely right; in their "delete" callback, they don't call SSL_SESSION_free(). They also return "0" from their "new" callback, indicating as they say:
/* * return 0 which means to OpenSSL that the pNew is still * valid and was not freed by us with SSL_SESSION_free(). */ return 0;
Are we sure the session code is doing the right things?
It works... until you do session resumption. :(
Of course, the crappy OpenSSL API is really, really badly documented so it's hard to be sure...
Yeah. It reminds me of the documentation for a graphing program I used in university. 400 pages of documentation, and *every single* example in it produced "syntax error" when typed in verbatim. It takes dedication to be that incompetent. Alan DeKok.
participants (6)
-
Alan Buxey -
Alan DeKok -
Alexander Clouter -
Arran Cudbard-Bell -
Phil Mayers -
Steven Coutts