David Mitchell wrote:

Alan,

I had a hang pretty quickly this time. As last time, the last output was that it the 'entering group authenticate' section. I got the bt output. I'm not sure if it's helpful or not. I just re-read doc/bugs and will try it again with gdb logging enabled. I'm not sure if that will help or not.

I'm attaching a full gdb log. I suspect that whatever is going wrong is a little before the actual hang. I'm seeing that whenever the server hangs, there was the warning about an EAP session not finishing a few transactions earlier. I'm 99% certain that my server certs are good, so I think the warning is misleading. I have XP client which are connecting without issue, and the clients I'm getting the warnings about are sometimes OSX or Linux. rad_recv: Access-Request packet from host 10.201.3.12 port 1645, id=161, length=123 User-Name = "russell" Framed-MTU = 1400 Called-Station-Id = "0015.639a.a412" Calling-Station-Id = "3415.9e45.6f8e" Service-Type = Login-User Message-Authenticator = 0xe9a6adfa5ebfd53662afe0ea64b7413d EAP-Message = 0x0201000c0172757373656c6c NAS-Port-Type = Wireless-802.11 NAS-Port = 674 NAS-IP-Address = 10.201.3.12 Thu Aug 26 11:21:41 2010 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Thu Aug 26 11:21:41 2010 : Info: +- entering group authorize {...} Thu Aug 26 11:21:41 2010 : Info: ++[preprocess] returns ok Thu Aug 26 11:21:41 2010 : Info: [suffix] No '@' in User-Name = "russell", looking up realm NULL Thu Aug 26 11:21:41 2010 : Info: [suffix] Found realm "~.+$" Thu Aug 26 11:21:41 2010 : Info: [suffix] Adding Stripped-User-Name = "russell" Thu Aug 26 11:21:41 2010 : Info: [suffix] Adding Realm = "(null)" Thu Aug 26 11:21:41 2010 : Info: [suffix] Authentication realm is LOCAL. Thu Aug 26 11:21:41 2010 : Info: ++[suffix] returns ok Thu Aug 26 11:21:41 2010 : Info: [eap] EAP packet type response id 1 length 12 Thu Aug 26 11:21:41 2010 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Thu Aug 26 11:21:41 2010 : Info: ++[eap] returns updated Thu Aug 26 11:21:41 2010 : Info: ++[files] returns noop Thu Aug 26 11:21:41 2010 : Info: Found Auth-Type = EAP Thu Aug 26 11:21:41 2010 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Thu Aug 26 11:21:41 2010 : Info: +- entering group authenticate {...} Thu Aug 26 11:21:41 2010 : Info: [eap] EAP Identity Thu Aug 26 11:21:41 2010 : Info: [eap] processing type tls Thu Aug 26 11:21:41 2010 : Info: [tls] Requiring client certificate Thu Aug 26 11:21:41 2010 : Info: [tls] Initiate Thu Aug 26 11:21:41 2010 : Info: [tls] Start returned 1 Thu Aug 26 11:21:41 2010 : Info: ++[eap] returns handled Sending Access-Challenge of id 161 to 10.201.3.12 port 1645 EAP-Message = 0x010200060d20 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x100c0b19100e062216c18f3934aa8859 Thu Aug 26 11:21:41 2010 : Info: Finished request 128. Thu Aug 26 11:21:41 2010 : Debug: Going to the next request Thu Aug 26 11:21:41 2010 : Debug: Waking up in 4.9 seconds. Thu Aug 26 11:21:47 2010 : Info: Cleaning up request 128 ID 161 with timestamp +1843 Thu Aug 26 11:21:47 2010 : Debug: WARNING: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Thu Aug 26 11:21:47 2010 : Debug: WARNING: !! EAP session for state 0x100c0b19100e0622 did not finish! Thu Aug 26 11:21:47 2010 : Debug: WARNING: !! Please read http://wiki.freeradius.org/Certificate_Compatibility Thu Aug 26 11:21:47 2010 : Debug: WARNING: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Thu Aug 26 11:21:47 2010 : Info: Ready to process requests.

Thu Aug 26 08:33:10 2010 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Thu Aug 26 08:33:10 2010 : Info: +- entering group authorize {...} Thu Aug 26 08:33:10 2010 : Info: ++[preprocess] returns ok Thu Aug 26 08:33:10 2010 : Info: [suffix] No '@' in User-Name = "mark", looking up realm NULL Thu Aug 26 08:33:10 2010 : Info: [suffix] Found realm "~.+$" Thu Aug 26 08:33:10 2010 : Info: [suffix] Adding Stripped-User-Name = "mark" Thu Aug 26 08:33:10 2010 : Info: [suffix] Adding Realm = "(null)" Thu Aug 26 08:33:10 2010 : Info: [suffix] Authentication realm is LOCAL. Thu Aug 26 08:33:10 2010 : Info: ++[suffix] returns ok Thu Aug 26 08:33:10 2010 : Info: [eap] EAP packet type response id 2 length 136 Thu Aug 26 08:33:10 2010 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Thu Aug 26 08:33:10 2010 : Info: ++[eap] returns updated Thu Aug 26 08:33:10 2010 : Info: ++[files] returns noop Thu Aug 26 08:33:10 2010 : Info: Found Auth-Type = EAP Thu Aug 26 08:33:10 2010 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Thu Aug 26 08:33:10 2010 : Info: +- entering group authenticate {...} ^C Program received signal SIGINT, Interrupt. [Switching to Thread 0xb75af8c0 (LWP 14706)] 0xb77b7424 in __kernel_vsyscall () (gdb) bt #0 0xb77b7424 in __kernel_vsyscall () #1 0xb7752c99 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0 #2 0xb774e0c4 in _L_lock_89 () from /lib/i686/cmov/libpthread.so.0 #3 0xb774d9f2 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0 #4 0xb75ac26f in eap_handler_free (inst=0x827fd98, handler=0x82af1a8) at mem.c:137 #5 0xb75ac3d5 in eaplist_expire (inst=0x827fd98, timestamp=1282833190) at mem.c:315 #6 0xb75ac856 in eaplist_find (inst=0x827fd98, request=0x82cee78, eap_packet=0x82ccc40) at mem.c:502 #7 0xb75aa76f in eap_handler (inst=0x827fd98, eap_packet_p=0xbfffd118, request=0x82cee78) at eap.c:974 #8 0xb75a9d80 in eap_authenticate (instance=0x827fd98, request=0x82cee78) at rlm_eap.c:298 #9 0x08089bbc in modcall (component=0, c=0x8293f88, request=0x82cee78) at modcall.c:297 #10 0x0808651b in indexed_modcall (comp=0, idx=6, request=0x82cee78) at modules.c:728 #11 0x0808692c in module_authenticate (auth_type=6, request=0x82cee78) at modules.c:1502 #12 0x080753c4 in rad_authenticate (request=0x82cee78) at auth.c:371 #13 0x08095854 in radius_handle_request (request=0x82cee78, fun=0x8074a10 <rad_authenticate>) at event.c:3767 #14 0x0808c9bf in thread_pool_addrequest (request=0x82cee78, fun=0x8074a10 <rad_authenticate>) at threads.c:874 #15 0x08091f7a in event_socket_handler (xel=0x82980a8, fd=7, ctx=0x829bb40) at event.c:3412 #16 0xb77a808c in fr_event_loop (el=0x82980a8) at event.c:411 #17 0x08092df6 in radius_event_process () at event.c:3753 #18 0x0808a782 in main (argc=2, argv=0xbfffe5a4) at radiusd.c:406 (gdb)

-- ----------------------------------------------------------------- | David Mitchell (mitchell@ucar.edu) Network Engineer IV | | Tel: (303) 497-1845 National Center for | | FAX: (303) 497-1818 Atmospheric Research | ----------------------------------------------------------------- Starting program: /usr/local/sbin/radiusd -xX [Thread debugging using libthread_db enabled] [New Thread 0xb74f58c0 (LWP 30771)] Program received signal SIGINT, Interrupt. [Switching to Thread 0xb74f58c0 (LWP 30771)] 0xb76fd424 in __kernel_vsyscall () * 1 Thread 0xb74f58c0 (LWP 30771) 0xb76fd424 in __kernel_vsyscall () Thread 1 (Thread 0xb74f58c0 (LWP 30771)): #0 0xb76fd424 in __kernel_vsyscall () No symbol table info available. #1 0xb75cea7d in select () from /lib/i686/cmov/libc.so.6 No symbol table info available. #2 0xb76edfcd in fr_event_loop (el=0x82982b8) at event.c:389 i = <value optimized out> rcode = <value optimized out> maxfd = 11 when = {tv_sec = 0, tv_usec = 0} wake = (struct timeval *) 0x0 read_fds = {fds_bits = {3904, 0 <repeats 31 times>}} master_fds = {fds_bits = {3904, 0 <repeats 31 times>}} #3 0x08092df6 in radius_event_process () at event.c:3753 No locals. #4 0x0808a782 in main (argc=2, argv=0xbfffd134) at radiusd.c:406 rcode = 134785712 argval = <value optimized out> spawn_flag = 0 dont_fork = 1 flag = 0 act = {__sigaction_handler = {sa_handler = 0x808aab0 <sig_fatal>, sa_sigaction = 0x808aab0 <sig_fatal>}, sa_mask = {__val = { 0 <repeats 32 times>}}, sa_flags = 0, sa_restorer = 0} The program being debugged has been started already. Start it from the beginning? (y or n) Starting program: /usr/local/sbin/radiusd -xX [Thread debugging using libthread_db enabled] [New Thread 0xb75d58c0 (LWP 30779)] Program received signal SIGINT, Interrupt. [Switching to Thread 0xb75d58c0 (LWP 30779)] 0xb77dd424 in __kernel_vsyscall () * 1 Thread 0xb75d58c0 (LWP 30779) 0xb77dd424 in __kernel_vsyscall () Thread 1 (Thread 0xb75d58c0 (LWP 30779)): #0 0xb77dd424 in __kernel_vsyscall () No symbol table info available. #1 0xb7778c99 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0 No symbol table info available. #2 0xb77740c4 in _L_lock_89 () from /lib/i686/cmov/libpthread.so.0 No symbol table info available. #3 0xb77739f2 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0 No symbol table info available. #4 0xb75d226f in eap_handler_free (inst=0x827ff50, handler=0x82c79b8) at mem.c:137 No locals. #5 0xb75d23d5 in eaplist_expire (inst=0x827ff50, timestamp=1282843521) at mem.c:315 node = (rbnode_t *) 0x82c0708 i = 0 handler = (EAP_HANDLER *) 0x82c79b8 #6 0xb75d2856 in eaplist_find (inst=0x827ff50, request=0x82d9890, eap_packet=0x82d8b80) at mem.c:502 state = <value optimized out> handler = <value optimized out> myHandler = {prev = 0x82cf160, next = 0x8261620, state = "\207š\203Õ\207ª\216ŠÛ\236\223Ùz\000åq", src_ipaddr = {af = 2, ipaddr = {ip4addr = {s_addr = 67356938}, ip6addr = {in6_u = {u6_addr8 = "\nÉ\003\004", '\0' <repeats 11 times>, u6_addr16 = {51466, 1027, 0, 0, 0, 0, 0, 0}, u6_addr32 = {67356938, 0, 0, 0}}}}, scope = 0}, eap_id = 2, eap_type = 2, timestamp = 137205904, request = 0xb75d34ec, identity = 0xb75d395b "response", prev_eapds = 0x2, eap_ds = 0xb772cff4, opaque = 0x88, free_opaque = 0x88, status = -1073755576, stage = -1218148779, trips = -1217207968, tls = 136, finished = -1217207968, certs = 0xa} #7 0xb75d076f in eap_handler (inst=0x827ff50, eap_packet_p=0xbfffcab8, request=0x82d9890) at eap.c:974 handler = <value optimized out> eap_packet = (eap_packet_t *) 0x82d8b80 vp = <value optimized out> #8 0xb75cfd80 in eap_authenticate (instance=0x827ff50, request=0x82d9890) at rlm_eap.c:298 handler = <value optimized out> eap_packet = (eap_packet_t *) 0x82d8b80 rcode = <value optimized out> #9 0x08089bbc in modcall (component=0, c=0x82941b0, request=0x82d9890) at modcall.c:297 myresult = 1 stack = {pointer = -1217212428, priority = {0, 0, -1073754112, -1218219508, -1073754284, -1217321383, -1073754056, -1073753940, 0, -72515583, -1073753940, -1073753940, -1073753940, -1073753940, -1073753930, -1, -1073753940, -1, 0, 0, 0, 0, 0, -1218357653, 0, -1073754176, -1224736768, 0, -1, 0, -1073752736, -1073753888}, result = {0, 0, -1073754016, -1, -72515583, -1073753860, -1073753860, -1073753860, -1073753860, -1073753856, -1073752837, -1073753860, -1073752837, 0, -1217213664, 0, 0, -1217212428, -1073753940, 137323688, -1073754088, -1218317173, -1073753940, -1217321383, -1073753860, 137323688, -1073753912, -1217635481, -1073753860, -1073753940, 10, 201}, children = {0x82941b0, 0x8294148, 0xbfffd058, 0xb77bb071, 0xbfffd0b8, 0x4, 0x1114749e, 0x636f6c20, 0xb77d3524, 0xb772c940, 0x0, 0xb77be268, 0xbfffd0b4, 0x8198da0, 0xffffffff, 0xbfffd0b4, 0x8195968, 0xac4, 0x8195984, 0xb77d3524, 0xbfffd0b4, 0x82e0d18, 0xbfffd098, 0xb77be361, 0x82ddb39, 0x1, 0xbfffd0c8, 0xb77ba614, 0xb772cff4, 0xbfffd0fc, 0x82e0d18, 0x322e3031}, start = {0x0, 0x8294148, 0xb77bf811, 0xb77d3524, 0xbfffd0fc, 0x82f64a8, 0xbfffd548, 0xb77c1839, 0xbfffd621, 0xbfffd0fc, 0x3ef, 0x400, 0x7561632d, 0x652d6573, 0x4e3d7478, 0x6552206f, 0x6e6f7361, 0x8157693, 0xbfffd4f0, 0x322e3031, 0x332e3130, 0x3700342e, 0x65386161, 0x62643661, 0x33396539, 0x61373964, 0x35653030, 0x30003137, 0x35373030, 0x31303330, 0x36376334, 0x39363361}} parent = (modcallable *) 0x82941b0 child = (modcallable *) 0x8294148 if_taken = 0 was_if = 0 #10 0x0808651b in indexed_modcall (comp=0, idx=6, request=0x82d9890) at modules.c:728 rcode = <value optimized out> list = (modcallable *) 0x82941b0 server = (virtual_server_t *) 0x8083b30 #11 0x0808692c in module_authenticate (auth_type=6, request=0x82d9890) at modules.c:1502 No locals. #12 0x080753c4 in rad_authenticate (request=0x82d9890) at auth.c:371 namepair = (VALUE_PAIR *) 0x82c9df8 check_item = <value optimized out> auth_item = (VALUE_PAIR *) 0x0 module_msg = <value optimized out> tmp = <value optimized out> result = <value optimized out> autz_retry = <value optimized out> autz_type = <value optimized out> #13 0x08095854 in radius_handle_request (request=0x82d9890, fun=0x8074a10 <rad_authenticate>) at event.c:3767 No locals. #14 0x0808c9bf in thread_pool_addrequest (request=0x82d9890, fun=0x8074a10 <rad_authenticate>) at threads.c:874 No locals. #15 0x08091f7a in event_socket_handler (xel=0x8298208, fd=9, ctx=0x829bd38) at event.c:3412 fun = (RAD_REQUEST_FUNP) 0x8074a10 <rad_authenticate> request = (REQUEST *) 0x82d9890 #16 0xb77ce08c in fr_event_loop (el=0x8298208) at event.c:411 i = 1 rcode = <value optimized out> maxfd = 12 when = {tv_sec = 1282843526, tv_usec = 134163} wake = (struct timeval *) 0xbfffdd94 read_fds = {fds_bits = {512, 0 <repeats 31 times>}} master_fds = {fds_bits = {7808, 0 <repeats 31 times>}} #17 0x08092df6 in radius_event_process () at event.c:3753 No locals. #18 0x0808a782 in main (argc=2, argv=0xbfffdf44) at radiusd.c:406 rcode = 134785712 argval = <value optimized out> spawn_flag = 0 dont_fork = 1 flag = 0 act = {__sigaction_handler = {sa_handler = 0x808aab0 <sig_fatal>, sa_sigaction = 0x808aab0 <sig_fatal>}, sa_mask = {__val = { 0 <repeats 32 times>}}, sa_flags = 0, sa_restorer = 0} The program is running. Exit anyway? (y or n)