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@tct9       187923@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@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@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