Robust proxy accounting

15 Jun 2009

      Alan,

This is the debug output using the latest release of 2.1.7 from http://git.freeradius.org/pre.

Thanks for your help in advance.

Chris

-----Original Message-----
From: Chris Howley [mailto:ecl6ch@netserv3.leeds.ac.uk]
Sent: 15 June 2009 12:07
To: Chris Howley
Subject: radius.debug4

ending Access-Accept of id 138 to 10.12.80.109 port 32769
        User-Name = "isschug"
        MS-MPPE-Recv-Key = 0x7c4e32b6485bed39ef623ae3c45738d54144c1492d00df705cb1902ed60d5578
        MS-MPPE-Send-Key = 0x707c6949db85e4ebb023aaa8016fb3027bfaaf613fb82b92568ba62965235648
        EAP-Message = 0x030b0004
        Message-Authenticator = 0x00000000000000000000000000000000
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3021,"
        Reply-Message = "Welcome isschug - student"
Finished request 9.
Going to the next request
Waking up in 0.2 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 1.2 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.8 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 1.1 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.8 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.7 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.9 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.7 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 1.0 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 1.0 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=146, length=156
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 29,Client-IP-Address = 10.12.80.109,NAS-IP-Address = 10.12.80.109,Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53",User-Name = "isschug"'
[acct_unique] Acct-Unique-Session-ID = "04fae10ff02490f4".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "isschug", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[files] returns noop
+- entering group accounting {...}
[detail]        expand: /usr/local/var/log/radius/radacct/%Y-%m-%d/accounting-detail-%H:00 -> /usr/local/var/log/radius/radacct/2009-06-15/accounting-detail-12:00
[detail] /usr/local/var/log/radius/radacct/%Y-%m-%d/accounting-detail-%H:00 expands to /usr/local/var/log/radius/radacct/2009-06-15/accounting-detail-12:00
[detail]        expand: %{Packet-Src-IP-Address} - %t -> 10.12.80.109 - Mon Jun 15 12:00:24 2009
++[detail] returns ok
++? if ("%{Client-IP-Address}" != "129.11.162.17")
        expand: %{Client-IP-Address} -> 10.12.80.109
? Evaluating ("%{Client-IP-Address}" != "129.11.162.17") -> TRUE
++? if ("%{Client-IP-Address}" != "129.11.162.17") -> TRUE
++- entering if ("%{Client-IP-Address}" != "129.11.162.17") {...}
+++[control] returns ok
++- if ("%{Client-IP-Address}" != "129.11.162.17") returns ok
++[unix] returns ok
[radutmp]       expand: /usr/local/var/log/radius/radutmp -> /usr/local/var/log/radius/radutmp
[radutmp]       expand: %{User-Name} -> isschug
++[radutmp] returns ok
[attr_filter.accounting_response]       expand: %{User-Name} -> isschug
 attr_filter: Matched entry DEFAULT at line 1
++[attr_filter.accounting_response] returns updated
 server home.example.com {
 }
Sending Accounting-Request of id 159 to 129.11.162.17 port 1813
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        Proxy-State = 0x313436
Proxying request 10 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 159 to 129.11.162.17 port 1813
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        Proxy-State = 0x313436
Going to the next request
Waking up in 0.3 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.3 seconds.
Cleaning up request 0 ID 129 with timestamp +6
Cleaning up request 1 ID 130 with timestamp +6
Cleaning up request 2 ID 131 with timestamp +6
Cleaning up request 3 ID 132 with timestamp +6
Cleaning up request 4 ID 133 with timestamp +6
Waking up in 0.1 seconds.
Cleaning up request 5 ID 134 with timestamp +6
Cleaning up request 6 ID 135 with timestamp +6
Waking up in 0.2 seconds.
Cleaning up request 7 ID 136 with timestamp +6
Cleaning up request 8 ID 137 with timestamp +7
Waking up in 0.1 seconds.
Cleaning up request 9 ID 138 with timestamp +7
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.7 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=146, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 146 due to unfinished request 10
Waking up in 0.2 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 1.1 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.8 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=146, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 146 due to unfinished request 10
Waking up in 0.2 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 1.0 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.6 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=146, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 146 due to unfinished request 10
Rejecting request 10 due to lack of any response from home server 129.11.162.17 port 1813
  Found Post-Proxy-Type
 server home.example.com {
+- entering group Fail {...}
[detail.example.com]    expand: /usr/local/var/log/radius/radacct/detail.example.com/detail-%Y%m%d:%H -> /usr/local/var/log/radius/radacct/detail.example.com/detail-20090615:12
[detail.example.com] /usr/local/var/log/radius/radacct/detail.example.com/detail-%Y%m%d:%H expands to /usr/local/var/log/radius/radacct/detail.example.com/detail-20090615:12
[detail.example.com]    expand: %t -> Mon Jun 15 12:00:24 2009
[detail.example.com] Freeradius-Proxied-To = 129.11.162.17
++[detail.example.com] returns ok
 }
Sending Accounting-Response of id 146 to 10.12.80.109 port 32769
Finished request 10.
Cleaning up request 10 ID 146 with timestamp +16
Going to the next request
PROXY: Marking home server 129.11.162.17 port 1813 as zombie (it looks like it is dead).
Sending Status-Server of id 121 to 129.11.162.17 port 1813
        Message-Authenticator := 0x00000000000000000000000000000000
        NAS-Identifier := "Status Check. Are you alive?"
Waking up in 0.1 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
detail_recv: Renaming /usr/local/var/log/radius/radacct/detail.example.com/detail-20090615:12 -> /usr/local/var/log/radius/radacct/detail.example.com/detail.work
detail_recv: Read packet from /usr/local/var/log/radius/radacct/detail.example.com/detail.work
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        Acct-Unique-Session-Id = "04fae10ff02490f4"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Packet-Original-Timestamp = "Jun 15 2009 12:00:24 BST"
        Acct-Delay-Time = 6
server home.example.com {
+- entering group accounting {...}
++[control] returns noop
} # server home.example.com
 server home.example.com {
 }
Sending Accounting-Request of id 21 to 129.11.162.17 port 1813
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Acct-Delay-Time = 6
        Proxy-State = 0x3333303539
Proxying request 12 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 21 to 129.11.162.17 port 1813
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Acct-Delay-Time = 6
        Proxy-State = 0x3333303539
Going to the next request
Waking up in 0.8 seconds.
Waking up in 0.1 seconds.
Waking up in 0.5 seconds.
Waking up in 1.1 seconds.
Waking up in 0.9 seconds.
Waking up in 0.1 seconds.
Waking up in 1.0 seconds.
Waking up in 1.1 seconds.
Rejecting request 12 due to lack of any response from home server 129.11.162.17 port 1813
  Found Post-Proxy-Type
 server home.example.com {
+- entering group Fail {...}
[detail.example.com] Suppressing writes to detail file as the request was just read from a detail file.
++[detail.example.com] returns noop
 }
server home.example.com {
} # server home.example.com
No response configured for request 12.  Will retry in 30 seconds
Finished request 12.
Cleaning up request 12 ID 33059 with timestamp +22
Going to the next request
Waking up in 24.4 seconds.
Sending Status-Server of id 6 to 129.11.162.17 port 1813
        Message-Authenticator := 0x00000000000000000000000000000000
        NAS-Identifier := "Status Check. Are you alive?"
Waking up in 3.9 seconds.
Waking up in 1.5 seconds.
detail_recv: Read packet from /usr/local/var/log/radius/radacct/detail.example.com/detail.work
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        Acct-Unique-Session-Id = "04fae10ff02490f4"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Packet-Original-Timestamp = "Jun 15 2009 12:00:24 BST"
        Acct-Delay-Time = 42
server home.example.com {
+- entering group accounting {...}
++[control] returns noop
} # server home.example.com
 server home.example.com {
 }
Sending Accounting-Request of id 57 to 129.11.162.17 port 1813
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Acct-Delay-Time = 42
        Proxy-State = 0x3437323335
Proxying request 14 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 57 to 129.11.162.17 port 1813
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Acct-Delay-Time = 42
        Proxy-State = 0x3437323335
Going to the next request
Waking up in 0.9 seconds.
Waking up in 0.1 seconds.
Waking up in 0.9 seconds.
Waking up in 1.1 seconds.
Waking up in 1.2 seconds.
Waking up in 0.8 seconds.
Waking up in 0.6 seconds.
Rejecting request 14 due to lack of any response from home server 129.11.162.17 port 1813
PROXY: Marking home server 129.11.162.17 port 1813 as dead.
  Found Post-Proxy-Type
 server home.example.com {
+- entering group Fail {...}
[detail.example.com] Suppressing writes to detail file as the request was just read from a detail file.
++[detail.example.com] returns noop
 }
server home.example.com {
} # server home.example.com
No response configured for request 14.  Will retry in 30 seconds
Finished request 14.
Cleaning up request 14 ID 47235 with timestamp +58
Going to the next request
Waking up in 0.2 seconds.
Waking up in 22.2 seconds.
Sending Status-Server of id 244 to 129.11.162.17 port 1813
        Message-Authenticator := 0x00000000000000000000000000000000
        NAS-Identifier := "Status Check. Are you alive?"
Waking up in 3.9 seconds.
Waking up in 3.7 seconds.
detail_recv: Read packet from /usr/local/var/log/radius/radacct/detail.example.com/detail.work
        User-Name = "isschug"
        NAS-Port = 29
        NAS-IP-Address = 10.12.80.109
        Framed-IP-Address = 129.11.1.138
        NAS-Identifier = "WM07-1"
        Airespace-Wlan-Id = 1
        Acct-Session-Id = "4a3629c8/00:13:02:8d:f3:1f/53"
        Acct-Authentic = RADIUS
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "3022"
        Acct-Status-Type = Start
        Calling-Station-Id = "129.11.1.138"
        Called-Station-Id = "10.12.80.109"
        Acct-Unique-Session-Id = "04fae10ff02490f4"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Packet-Original-Timestamp = "Jun 15 2009 12:00:24 BST"
        Acct-Delay-Time = 78
server home.example.com {
+- entering group accounting {...}
++[control] returns noop
} # server home.example.com
 server home.example.com {
 }
...
...
...
Sending proxied request internally to virtual server.
server acct_detail.example.com {
+- entering group accounting {...}
[detail.example.com] Suppressing writes to detail file as the request was just read from a detail file.
++[detail.example.com] returns noop
} # server acct_detail.example.com
Going to the next request
<<< Received proxied response code 0 from internal virtual server.
  Found Post-Proxy-Type
 server home.example.com {
+- entering group Fail {...}
[detail.example.com] Suppressing writes to detail file as the request was just read from a detail file.
++[detail.example.com] returns noop
 }
server home.example.com {
} # server home.example.com
Finished request 16.
Cleaning up request 16 ID 36027 with timestamp +94
Going to the next request
Waking up in 1.0 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.8 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*