Hanging Problem in 2.1.10

Thu Aug 26 19:47:22 CEST 2010

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 at ucar.edu)       Network Engineer IV  |
| Tel: (303) 497-1845                      National Center for  |
| FAX: (303) 497-1818                      Atmospheric Research |
-----------------------------------------------------------------
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: gdb-radiusd.log.3
URL: <http://lists.freeradius.org/pipermail/freeradius-devel/attachments/20100826/02d61b59/attachment.ksh>