Robust proxy accounting

Chris Howley C.P.Howley at leeds.ac.uk
Fri Jun 12 18:18:03 CEST 2009


Alan,

Here's the output from FR2.1.7.

Thanks for you help in advance,

Chris


++[exec] returns noop
Sending Access-Accept of id 128 to 10.12.80.109 port 32769
        User-Name = "isschug"
        MS-MPPE-Recv-Key = 0x3019b4c8f9f76bb2fc4d69edbc20e98377351a661c0b412c760cd773e3b4c5f5
        MS-MPPE-Send-Key = 0x5c7923cd941d8d7bd673b823632371b01435f0590105a5c38211b89b04fdea1b
        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 20.
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.9 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.9 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 1.2 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.9 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-*:*
Cleaning up request 11 ID 119 with timestamp +601
Cleaning up request 12 ID 120 with timestamp +601
Cleaning up request 13 ID 121 with timestamp +601
Cleaning up request 14 ID 122 with timestamp +601
Cleaning up request 15 ID 123 with timestamp +601
Cleaning up request 16 ID 124 with timestamp +601
Cleaning up request 17 ID 125 with timestamp +601
Cleaning up request 18 ID 126 with timestamp +601
Cleaning up request 19 ID 127 with timestamp +601
Cleaning up request 20 ID 128 with timestamp +601
Waking up in 0.5 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=144, 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = "4a327dde/00:13:02:8d:f3:1f/52",User-Name = "isschug"'
[acct_unique] Acct-Unique-Session-ID = "5b58953f85bf5074".
++[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-12/accounting-detail-17: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-12/accounting-detail-17:00
[detail]        expand: %{Packet-Src-IP-Address} - %t -> 10.12.80.109 - Fri Jun 12 17:10:06 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 253 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = 0x313434
Proxying request 21 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 253 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = 0x313434
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.6 seconds.
Waking up in 0.1 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 1.1 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=144, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 144 due to unfinished request 21
Waking up in 0.3 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=144, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 144 due to unfinished request 21
Waking up in 0.4 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.4 seconds.
Rejecting request 21 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-20090612:17
[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-20090612:17
[detail.example.com]    expand: %t -> Fri Jun 12 17:10:06 2009
[detail.example.com] Freeradius-Proxied-To = 129.11.162.17
++[detail.example.com] returns ok
 }
Sending Accounting-Response of id 144 to 10.12.80.109 port 32769
Finished request 21.
Cleaning up request 21 ID 144 with timestamp +611
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 225 to 129.11.162.17 port 1813
        Message-Authenticator := 0x00000000000000000000000000000000
        NAS-Identifier := "Status Check. Are you alive?"
Waking up in 0.5 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-20090612:17 -> /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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = "5b58953f85bf5074"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Packet-Original-Timestamp = "Jun 12 2009 17:10:06 BST"
        Acct-Delay-Time = 7
server home.example.com {
+- entering group accounting {...}
++[control] returns noop
} # server home.example.com
 server home.example.com {
 }
Sending Accounting-Request of id 42 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = 7
        Proxy-State = 0x3133363235
Proxying request 23 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 42 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = 7
        Proxy-State = 0x3133363235
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 0.7 seconds.
Waking up in 0.5 seconds.
Waking up in 0.4 seconds.
Waking up in 1.0 seconds.
Waking up in 1.0 seconds.
Rejecting request 23 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 23.  Will retry in 30 seconds
Finished request 23.
Cleaning up request 23 ID 13625 with timestamp +618
Going to the next request
Waking up in 24.4 seconds.
Sending Status-Server of id 66 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = "5b58953f85bf5074"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Packet-Original-Timestamp = "Jun 12 2009 17:10:06 BST"
        Acct-Delay-Time = 43
server home.example.com {
+- entering group accounting {...}
++[control] returns noop
} # server home.example.com
 server home.example.com {
 }
Sending Accounting-Request of id 13 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = 43
        Proxy-State = 0x3534373934
Proxying request 25 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 13 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = 43
        Proxy-State = 0x3534373934
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.0 seconds.
Waking up in 1.1 seconds.
Waking up in 0.4 seconds.
Rejecting request 25 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 25.  Will retry in 30 seconds
Finished request 25.
Cleaning up request 25 ID 54794 with timestamp +654
Going to the next request
Waking up in 0.7 seconds.
Waking up in 20.7 seconds.
Sending Status-Server of id 81 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 5.2 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 = "4a327dde/00:13:02:8d:f3:1f/52"
        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 = "5b58953f85bf5074"
        Realm = "acct_realm.example.com"
        FreeRADIUS-Proxied-To = 129.11.162.17
        Packet-Original-Timestamp = "Jun 12 2009 17:10:06 BST"
        Acct-Delay-Time = 79
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.
 server home.example.com {
 }
server home.example.com {
} # server home.example.com
Finished request 27.
Cleaning up request 27 ID 8957 with timestamp +690
Going to the next request
Waking up in 0.9 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.8 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.8 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 1.1 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.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 1.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.7 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.7 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.1 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.9 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.8 seconds.
Sending Status-Server of id 3 to 129.11.162.17 port 1813
        Message-Authenticator := 0x00000000000000000000000000000000
        NAS-Identifier := "Status Check. Are you alive?"
Waking up in 0.3 seconds.





More information about the Freeradius-Users mailing list