robust-proxy-accounting issue

[Paul Sherratt]

I've just installed latest fr2.1.10 stable, and testing the stock
robust-proxy-accounting.

It looks as if when all home servers are down, the detail file is
continuously replayed over itself, causing new attributes to be
appended on each poll and rapidly increasing the size of the detail
log, and other obscurities like Packet-Transmit-Counter being re-set
as it thinks each re-play is a new proxied packet.

In rlm_detail.c:479

        if (request->listener->type == RAD_LISTEN_DETAIL &&
            strcmp(((struct detail_instance *)instance)->detailfile,
                   ((listen_detail_t
*)request->listener->data)->filename) == 0) {
                RDEBUG("Suppressing writes to detail file as the
request was just read from a detail file.");
                return RLM_MODULE_NOOP;
        }

It looks like in the example config, detail-%Y%m%d:%H is used on the
detail writer, and detail-*:* is used on the detail listener, which
wont match above?  So short-term workaround is to just use a single
detail file.


Rgds

Paul


--8<----------------

Going to the next request
Detail listener
/var/log/freeradius/radacct/detail.example.com/detail-*:* state
replied signalled 0 waiting 0.005643 sec
Detail - unlinking /var/log/freeradius/radacct/detail.example.com/detail.work
Detail listener
/var/log/freeradius/radacct/detail.example.com/detail-*:* state
unopened signalled 0 waiting 1.035186 sec
Waking up in 1.0 seconds.
Polling for detail file
/var/log/freeradius/radacct/detail.example.com/detail-*:*
Detail - Renaming
/var/log/freeradius/radacct/detail.example.com/detail-20101203:15 ->
/var/log/freeradius/radacct/detail.example.com/detail.work
detail_recv: Read packet from
/var/log/freeradius/radacct/detail.example.com/detail.work
        Acct-Status-Type = Interim-Update
        NAS-IP-Address = 192.0.2.1
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 192.0.2.20
        Packet-Original-Timestamp = "Dec  3 2010 15:14:32 GMT"
        Acct-Delay-Time = 21
        Packet-Transmit-Counter = 1
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 192.0.2.10
        Packet-Original-Timestamp = "Dec  3 2010 15:14:39 GMT"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 192.0.2.10
        Packet-Original-Timestamp = "Dec  3 2010 15:14:46 GMT"
server home.example.com {
  WARNING: Empty preacct section.  Using default return values.
# Executing section accounting from file /etc/freeradius/sites-enabled/test
+- entering group accounting {...}
++[control] returns noop
} # server home.example.com
 server home.example.com {
  WARNING: Empty pre-proxy section.  Using default return values.
 }
>>> Sending proxied request internally to virtual server.

server acct_detail.example.com {
  WARNING: Empty preacct section.  Using default return values.
# Executing section accounting from file /etc/freeradius/sites-enabled/test
+- entering group accounting {...}
[detail.example.com]    expand:
/var/log/freeradius/radacct/detail.example.com/detail-%Y%m%d:%H ->
/var/log/freeradius/radacct/detail.example.com/detail-20101203:15
[detail.example.com]
/var/log/freeradius/radacct/detail.example.com/detail-%Y%m%d:%H
expands to /var/log/freeradius/radacct/detail.example.com/detail-20101203:15
[detail.example.com]    expand: %t -> Fri Dec  3 15:14:56 2010
++[detail.example.com] returns ok
} # server acct_detail.example.com
Going to the next request
<<< Received proxied response code 5 from internal virtual server.
 server home.example.com {
  WARNING: Empty post-proxy section.  Using default return values.
# Executing section post-proxy from file /etc/freeradius/sites-enabled/test
 }
server home.example.com {
} # server home.example.com
Finished request 5.
...
Cleaning up request 7 ID 25567 with timestamp +37
Going to the next request
Detail listener
/var/log/freeradius/radacct/detail.example.com/detail-*:* state
replied signalled 0 waiting 0.002655 sec
Detail - unlinking /var/log/freeradius/radacct/detail.example.com/detail.work
Detail listener
/var/log/freeradius/radacct/detail.example.com/detail-*:* state
unopened signalled 0 waiting 1.146660 sec
Waking up in 1.1 seconds.
Polling for detail file
/var/log/freeradius/radacct/detail.example.com/detail-*:*
Detail - Renaming
/var/log/freeradius/radacct/detail.example.com/detail-20101203:15 ->
/var/log/freeradius/radacct/detail.example.com/detail.work
detail_recv: Read packet from
/var/log/freeradius/radacct/detail.example.com/detail.work
        Acct-Status-Type = Interim-Update
        NAS-IP-Address = 192.0.2.1
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 192.0.2.20
        Packet-Original-Timestamp = "Dec  3 2010 15:14:32 GMT"
        Acct-Delay-Time = 25
        Packet-Transmit-Counter = 1
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 192.0.2.10
        Packet-Original-Timestamp = "Dec  3 2010 15:14:39 GMT"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 192.0.2.10
        Packet-Original-Timestamp = "Dec  3 2010 15:14:46 GMT"
        Proxy-State = 0x3239373330
        Packet-Original-Timestamp = "Dec  3 2010 15:14:53 GMT"
        Proxy-State = 0x3237313737
        Packet-Original-Timestamp = "Dec  3 2010 15:14:55 GMT"
        Proxy-State = 0x3235353637
        Packet-Original-Timestamp = "Dec  3 2010 15:14:56 GMT"