Robust proxy accounting
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-*:*
Alan,
This is the debug output using the latest release of 2.1.7 from http://git.freeradius.org/pre.
Hm, for some reason failure doesn'r result in retry in last pass: ...
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. ...
That looks good but after internal proxy: ...
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.
Line:
No response configured for request 16. Will retry in 30 seconds
is missing in the debug. Ivan Kalik Kalik Informatika ISP
Chris Howley wrote:
This is the debug output using the latest release of 2.1.7 from http://git.freeradius.org/pre.
Arg. There was an idiotic typo in the code. I can't help but feel at least partially responsible. OK... I've put the updated version on the same web site. You don't have to re-configure && re-build. Just copy src/main/event.c from the newer "tar" file to where-ever you had built the previous snapshot of 2.1.7. $ mdkir foo $ cd foo $ wget http://git.freeradius.org/freeradius-server-2.1.7.tar.gz $ tar -zxf freeradius-server-2.1.7.tar.gz $ cd freeradius-server-2.1.7/src/main/ $ cp event.c ~/previous-version/src/main/event.c $ cd ~/previous-version/src/main $ make $ make install And that *should* fix it. Alan DeKok.
participants (3)
-
Alan DeKok -
Chris Howley -
Ivan Kalik