Robust proxy accounting
Chris Howley
C.P.Howley at leeds.ac.uk
Fri Jun 12 13:08:36 CEST 2009
Ivan,
I doubled the value of cleanup delay in radiusd.conf. This change didn't fix the problem (see below).
Thanks for your help,
Chris
++[exec] returns noop
Sending Access-Accept of id 88 to 10.12.80.109 port 32769
User-Name = "isschug"
MS-MPPE-Recv-Key = 0x529e91a0004dce6a6ba2d81c79eeeb98aa3bc7c08880c37d95236064ef786280
MS-MPPE-Send-Key = 0x59005da107574a481d3a7d580821be64872d65153f9767789e79a51f84880994
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.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 1.0 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 1.0 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=137, 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = "4a323344/00:13:02:8d:f3:1f/49",User-Name = "isschug"'
[acct_unique] Acct-Unique-Session-ID = "829905a4bf02a129".
++[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-11: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-11:00
[detail] expand: %{Packet-Src-IP-Address} - %t -> 10.12.80.109 - Fri Jun 12 11:51:48 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 167 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = 0x313337
Proxying request 10 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 167 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = 0x313337
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 0.7 seconds.
Waking up in 0.2 seconds.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Waking up in 0.9 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=137, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 137 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 0.3 seconds.
Cleaning up request 0 ID 79 with timestamp +1750
Cleaning up request 1 ID 80 with timestamp +1750
Cleaning up request 2 ID 81 with timestamp +1750
Cleaning up request 3 ID 82 with timestamp +1750
Cleaning up request 4 ID 83 with timestamp +1750
Cleaning up request 5 ID 84 with timestamp +1750
Cleaning up request 6 ID 85 with timestamp +1750
Waking up in 0.2 seconds.
Cleaning up request 7 ID 86 with timestamp +1750
Cleaning up request 8 ID 87 with timestamp +1751
Cleaning up request 9 ID 88 with timestamp +1751
Waking up in 0.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.8 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=137, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 137 due to unfinished request 10
Waking up in 0.7 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.4 seconds.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=137, length=156
Discarding duplicate request from client wism07-1 port 32769 - ID: 137 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-20090612:11
[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:11
[detail.example.com] expand: %t -> Fri Jun 12 11:51:48 2009
[detail.example.com] Freeradius-Proxied-To = 129.11.162.17
++[detail.example.com] returns ok
}
Sending Accounting-Response of id 137 to 10.12.80.109 port 32769
Finished request 10.
Cleaning up request 10 ID 137 with timestamp +1758
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 86 to 129.11.162.17 port 1813
Message-Authenticator := 0x00000000000000000000000000000000
NAS-Identifier := "Status Check. Are you alive?"
Waking up in 0.7 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:11 -> /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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = "829905a4bf02a129"
Realm = "acct_realm.example.com"
FreeRADIUS-Proxied-To = 129.11.162.17
Packet-Original-Timestamp = "Jun 12 2009 11:51:48 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 179 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = 0x3339353133
Proxying request 12 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 179 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = 0x3339353133
Going to the next request
Waking up in 0.8 seconds.
Waking up in 0.1 seconds.
Waking up in 0.6 seconds.
Waking up in 1.0 seconds.
Waking up in 0.5 seconds.
Waking up in 0.6 seconds.
Waking up in 0.8 seconds.
Waking up in 0.9 seconds.
Waking up in 0.3 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
Finished request 12.
Cleaning up request 12 ID 39513 with timestamp +1765
Going to the next request
Waking up in 0.7 seconds.
Waking up in 26.6 seconds.
Sending Status-Server of id 141 to 129.11.162.17 port 1813
Message-Authenticator := 0x00000000000000000000000000000000
NAS-Identifier := "Status Check. Are you alive?"
Waking up in 3.3 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = "829905a4bf02a129"
Realm = "acct_realm.example.com"
FreeRADIUS-Proxied-To = 129.11.162.17
Packet-Original-Timestamp = "Jun 12 2009 11:51:48 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 210 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = 0x3232383630
Proxying request 14 to home server 129.11.162.17 port 1813
Sending Accounting-Request of id 210 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = 0x3232383630
Going to the next request
Waking up in 0.6 seconds.
Waking up in 0.3 seconds.
Waking up in 1.1 seconds.
Waking up in 1.0 seconds.
Waking up in 0.8 seconds.
Waking up in 0.7 seconds.
Waking up in 1.1 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
Finished request 14.
Cleaning up request 14 ID 22860 with timestamp +1801
Going to the next request
Waking up in 25.5 seconds.
Sending Status-Server of id 186 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 0.4 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 = "4a323344/00:13:02:8d:f3:1f/49"
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 = "829905a4bf02a129"
Realm = "acct_realm.example.com"
FreeRADIUS-Proxied-To = 129.11.162.17
Packet-Original-Timestamp = "Jun 12 2009 11:51:48 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 from internal virtual server.
server home.example.com {
}
server home.example.com {
} # server home.example.com
Finished request 16.
Cleaning up request 16 ID 56874 with timestamp +1837
Going to the next request
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-*:*
More information about the Freeradius-Users
mailing list