Segmentation fault on conflicting packet

[Milan Holub]

Hi Alan,

I'm using cvs build based on cvs head on May 29 2007.
I'm running it under conditions close to production(40 auth
requests/hour, 700 accounting requests/hour).

Most of the time it's doing well but I've observed already multiple
times following behaviour:

2007-05-31 06:18:14.884403500 Thread 1 handling request 11920, (2384 handled so far)
2007-05-31 06:18:14.884406500   Processing the preacct section of radiusd.conf
2007-05-31 06:18:14.884408500 +- entering group preacct
2007-05-31 06:18:14.884410500 ++[preprocess] returns ok
2007-05-31 06:18:14.884412500 radius_xlat:  '<CLIENT_IP>'
2007-05-31 06:18:14.884414500 rlm_attr_rewrite: Added attribute Client-IP-Address with value '<CLIENT_IP>'
2007-05-31 06:18:14.884417500 ++[add_clientip] returns ok
2007-05-31 06:18:14.884534500 rlm_acct_unique: Hashing 'NAS-Port = 5292,Client-IP-Address = <CLIENT_IP>,NAS-IP-Address = <NAS_IP>,Acct-Session-Id = "192458",User-Name = "<USERNAME>"'
2007-05-31 06:18:14.884540500 rlm_acct_unique: Acct-Unique-Session-ID = "4c66e6ddb85d6ed4".
2007-05-31 06:18:14.884543500 ++[acct_unique] returns ok
2007-05-31 06:18:14.884544500     rlm_realm: No '/' in User-Name = "<USERNAME>", looking up realm NULL
2007-05-31 06:18:14.884547500     rlm_realm: No such realm "NULL"
2007-05-31 06:18:14.884562500 ++[IPASS] returns noop
2007-05-31 06:18:14.884564500     rlm_realm: No '@' in User-Name = "<USERNAME>", looking up realm NULL
2007-05-31 06:18:14.884567500     rlm_realm: No such realm "NULL"
2007-05-31 06:18:14.884568500 ++[suffix] returns noop
2007-05-31 06:18:14.884570500 radius_xlat:  '<CLIENT_IP>'
2007-05-31 06:18:14.884572500     acct_users: Matched entry DEFAULT at line 39
2007-05-31 06:18:14.884574500 ++[files] returns ok
2007-05-31 06:18:14.884575500 Using perl at 0x81691e0
2007-05-31 06:18:14.884590500 rlm_perl: rlm_perl: preacct
2007-05-31 06:18:14.884592500 rlm_perl: Request attributes:
2007-05-31 06:18:14.884594500 rlm_perl: RAD_REQUEST: WISPr-Location-Name = 21001:BE-HO Bern Holingen KVA
2007-05-31 06:18:14.884619500 rlm_perl: RAD_REQUEST: Calling-Station-Id = 0000000000000000
2007-05-31 06:18:14.884622500 rlm_perl: RAD_REQUEST: NAS-Port = 5292
2007-05-31 06:18:14.884624500 rlm_perl: RAD_REQUEST: Acct-Delay-Time = 0
2007-05-31 06:18:14.884626500 rlm_perl: RAD_REQUEST: WISPr-Location-ID = 68
2007-05-31 06:18:14.884628500 rlm_perl: RAD_REQUEST: Acct-Session-Id = 192458
2007-05-31 06:18:14.884630500 rlm_perl: RAD_REQUEST: NAS-Identifier = <NAS_IP>:5292
2007-05-31 06:18:14.884645500 rlm_perl: RAD_REQUEST: Class = TN_S1M
2007-05-31 06:18:14.884647500 rlm_perl: RAD_REQUEST: Acct-Unique-Session-Id = 4c66e6ddb85d6ed4
2007-05-31 06:18:14.884650500 rlm_perl: RAD_REQUEST: Called-Station-Id = 00:19:D2:3D:5A:EA
2007-05-31 06:18:14.884652500 rlm_perl: RAD_REQUEST: Acct-Authentic = RADIUS
2007-05-31 06:18:14.884654500 rlm_perl: RAD_REQUEST: Framed-IP-Address = 10.2.159.24
2007-05-31 06:18:14.884657500 rlm_perl: RAD_REQUEST: NAS-Port-Type = Wireless-802.11
2007-05-31 06:18:14.884672500 rlm_perl: RAD_REQUEST: User-Name = <USERNAME>
2007-05-31 06:18:14.884674500 rlm_perl: RAD_REQUEST: Client-IP-Address = <CLIENT_IP>
2007-05-31 06:18:14.884676500 rlm_perl: RAD_REQUEST: NAS-IP-Address = <NAS_IP>
2007-05-31 06:18:14.884678500 rlm_perl: RAD_REQUEST: Acct-Status-Type = Start
2007-05-31 06:18:14.884680500 rlm_perl: Reply attributes:
2007-05-31 06:18:14.884682500 rlm_perl: Check attributes:
2007-05-31 06:18:14.884684500 rlm_perl: RAD_CHECK Proxy-To-Realm = LOCAL
2007-05-31 06:18:14.884699500 rlm_perl: Added pair WISPr-Location-Name = 21001:BE-HO Bern Holingen KVA
2007-05-31 06:18:14.884720500 rlm_perl: Added pair Calling-Station-Id = 0000000000000000
2007-05-31 06:18:14.884723500 rlm_perl: Added pair NAS-Port = 5292
2007-05-31 06:18:14.884725500 rlm_perl: Added pair Acct-Delay-Time = 0
2007-05-31 06:18:14.884727500 rlm_perl: Added pair WISPr-Location-ID = 68
2007-05-31 06:18:14.884729500 rlm_perl: Added pair Acct-Session-Id = 192458
2007-05-31 06:18:14.884731500 rlm_perl: Added pair NAS-Identifier = <NAS_IP>:5292
2007-05-31 06:18:14.884746500 rlm_perl: Added pair Class = TN_S1M
2007-05-31 06:18:14.884748500 rlm_perl: Added pair Acct-Unique-Session-Id = 4c66e6ddb85d6ed4
2007-05-31 06:18:14.884750500 rlm_perl: Added pair Called-Station-Id = 00:19:D2:3D:5A:EA
2007-05-31 06:18:14.884753500 rlm_perl: Added pair Acct-Authentic = RADIUS
2007-05-31 06:18:14.884755500 rlm_perl: Added pair Framed-IP-Address = 10.2.159.24
2007-05-31 06:18:14.884757500 rlm_perl: Added pair NAS-Port-Type = Wireless-802.11
2007-05-31 06:18:14.884772500 rlm_perl: Added pair User-Name = <USERNAME>
2007-05-31 06:18:14.884774500 rlm_perl: Added pair Client-IP-Address = <CLIENT_IP>
2007-05-31 06:18:14.884776500 rlm_perl: Added pair NAS-IP-Address = <NAS_IP>
2007-05-31 06:18:14.884778500 rlm_perl: Added pair Acct-Status-Type = Start
2007-05-31 06:18:14.884780500 rlm_perl: Added pair Proxy-To-Realm = LOCAL
2007-05-31 06:18:14.884782500 ++[perl] returns ok
2007-05-31 06:18:14.884784500 +- group preacct returns ok
2007-05-31 06:18:14.884835500   Processing the accounting section of radiusd.conf
2007-05-31 06:18:14.884837500 +- entering group accounting
2007-05-31 06:18:14.884839500 radius_xlat:  '/var/log/freeradius/radacct/<CLIENT_IP>/detail-20070531'
2007-05-31 06:18:14.884860500 rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradi
us/radacct/<CLIENT_IP>/detail-20070531
2007-05-31 06:18:14.884865500 radius_xlat:  'Thu May 31 06:18:14 2007'
2007-05-31 06:18:14.884935500 Threads: total/active/spare threads = 5/1/4
2007-05-31 06:18:14.885099500 Received conflicting packet from client <SHORTNAME> port 33499 - ID: 0 due to unfinished request 11920.Giving up on old request.
2007-05-31 06:18:14.885168500 Failed to insert request 11921 in the list of live requests: discarding
2007-05-31 06:18:14.913060500 ++[detail] returns ok
2007-05-31 06:18:14.913068500 rad_accounting: Cancelling proxy to realm LOCAL, as it is a LOCAL realm.
2007-05-31 06:18:14.913071500 Request 11920 was cancelled.
2007-05-31 06:18:14.913073500 Going to the next request
2007-05-31 06:18:14.913074500 Thread 1 waiting to be assigned a request
>>SEQMENTATION FAULT...


If you check the timeline we've received conclicting packet after
0.000696 sec. Which I think was a duplicate packet due to some network
problem. Packet 11920 was in the middle of processing(finished writing
into detail file, but not yet written to database). Segmentation fault
occured when another request was received.

I was not able to simulate by sending duplicate packets via radclient. I
think the sensitive part is receiving duplicate packet during the
processing of original packet.

Any ideas?


Milan Holub
holub (at) thenet (dot) ch

--------------------------------------
 TheNet-Internet Services AG,
 im Bernertechnopark, Morgenstr. 129
 CH-3018, Bern, Switzerland
 031 998 4333, Fax 031 998 4330
 http://www.thenet.ch
 http://wlan.thenet.ch
--------------------------------------