FreeRADIUS Strange action (unfinished request/dropping conflict packet)

[Ali Majdzadeh]

Hi



I’m running freeradius 1.1.8 with rlm_exec. External program on ACCTOUNTING
packets runs and my external program returns OK! And printout the following
in its logfile:



(PID  5036) 2011-09-15 18:24:28          Packet: updt             UserName:
hhsde0100413 at tct9       187923 at 172.31.3.7   10320 Sec 3993228/61717432 Bytes



FreeRADIUS Debugging shows log as the following and shows everything goes
fine for that request.



Thu Sep 15 18:24:28 2011 : Debug: Thread 1 handling request 175, (31 handled
so far)

        User-Name = "hhsde0100413 at tct9"

        NAS-Port = 136339956

        NAS-IP-Address = 172.31.3.7

        Framed-IP-Address = 2.179.17.211

        Filter-Id = "tct9"

        Class =
0x68687364653031303034313340746374397c387c3137322e33312e332e377c316361666637623036653264

        rad_recv: Accounting-Request packet from host 172.31.3.7:1813,
id=92, length=530

NAS-Identifier = "KJ-RJ-ME60X16-01"

        Acct-Status-Type = Interim-Update

        Acct-Delay-Time = 0

        Acct-Input-Octets = 3993228

        Acct-Output-Octets = 61717432

        Acct-Session-Id = "KJ-RJ-M08206050000000890a6e187923"

        Acct-Authentic = RADIUS

        Acct-Session-Time = 10320

        Acct-Input-Packets = 45602

        Acct-Output-Packets = 50322

        Acct-Input-Gigawords = 0

        Acct-Output-Gigawords = 0

Thu Sep 15 18:24:28 2011 : Debug: Thread 1 handling request 175, (31 handled
so far)

Thu Sep 15 18:24:28 2011 : Debug: modcall: entering group preacct for
request 175

Thu Sep 15 18:24:28 2011 : Debug:   modsingle[preacct]: calling preprocess
(rlm_preprocess) for request 175

        Acct-Session-Time = 10320Thu Sep 15 18:24:28 2011 : Debug:
modsingle[preacct]: returned from preprocess (rlm_preprocess) for request
175

        Thu Sep 15 18:24:28 2011 : Debug:   modcall[preacct]: module
"preprocess" returns noop for request 175

Thu Sep 15 18:24:28 2011 : Debug:   modsingle[preacct]: calling acct_unique
(rlm_acct_unique) for request 175

        Thu Sep 15 18:24:28 2011 : Debug:   modsingle[preacct]: returned
from acct_unique (rlm_acct_unique) for request 175

        Thu Sep 15 18:24:28 2011 : Debug:   modcall[preacct]: module
"acct_unique" returns ok for request 175

        Thu Sep 15 18:24:28 2011 : Debug: modcall: leaving group preacct
(returns ok) for request 175

        Thu Sep 15 18:24:28 2011 : Debug: modcall: entering group accounting
for request 175

        Thu Sep 15 18:24:28 2011 : Debug:   modsingle[accounting]: calling
detail (rlm_detail) for request 175

Thu Sep 15 18:24:28 2011 : Debug:   modsingle[accounting]: returned from
detail (rlm_detail) for request 175

Thu Sep 15 18:24:28 2011 : Debug:   modcall[accounting]: module "detail"
returns ok for request 175

Thu Sep 15 18:24:28 2011 : Debug:   modsingle[accounting]: calling
netbill_acct (rlm_exec) for request 175



Tcpdump shows the accounting packet issued and returned back to the RAS:





IP 172.31.3.7.radius-acct > 172.26.60.3.radius-acct: RADIUS, Accounting
Request (4), id: 0xx length: 527

IP 172.26.60.3.radius-acct > 172.31.3.7.radius-acct: RADIUS, Accounting
Response (5), id: 0xxx length: 20



But after about 30 secound, I got the following error in freeRADIUS’s
log!!!!



Thu Sep 15 18:24:59 2011 : Error: WARNING: Unresponsive child (id
3086457744) for request 175 (in component accounting module rlm_exec)
hhsde0100413 at tct9        Thu Sep 15 18:24:59 2011 : Debug: Server rejecting
request 175.



And then shows:



Thu Sep 15 18:43:54 2011 : Error: Dropping conflicting packet from client
172.31.3.7:1646 - ID: 151 due to unfinished request 175


My external program returns 0 (means OK) and freeRADIUS getting it and
returns back to the BRAS, so why freeradius gives such error?!


Kind Regards,
Ali Majdzadeh Kohbanani
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20110915/5bc0ce6e/attachment.html>