Ivan, When both RADIUS servers are operational robust proxying works. When one of the servers is unreachable the other server (that's attempting to proxy an accounting request) will delete the detail.work file from the listener's sub-directory after failing to get a response from the other server. Thanks for you help. Chris ++[exec] returns noop Sending Access-Accept of id 67 to 10.12.80.109 port 32769 User-Name = "isschrpg" MS-MPPE-Recv-Key = 0x240dd3ada2d5904bf049fc2bd7afdfc8b1a2b589b4eb3974235cf04143f138d1 MS-MPPE-Send-Key = 0x638979dd5d59705051793c16de1509508e39fd9722d56198d52da2286bb69879 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 isschrpg - student" Finished request 9. 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.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.9 seconds. 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=123, length=157 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44",User-Name = "isschrpg"' [acct_unique] Acct-Unique-Session-ID = "aeb3d50af9d33fb8". ++[acct_unique] returns ok [suffix] No '@' in User-Name = "isschrpg", 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-11/accounting-detail-08: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-11/accounting-detail-08:00 [detail] expand: %{Packet-Src-IP-Address} - %t -> 10.12.80.109 - Thu Jun 11 08:39:20 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} -> isschrpg ++[radutmp] returns ok [sql] expand: %{Stripped-User-Name} -> [sql] expand: %{User-Name} -> isschrpg [sql] expand: %{%{User-Name}:-DEFAULT} -> isschrpg [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> isschrpg [sql] sql_set_user escaped user --> 'isschrpg' [sql] expand: %{Acct-Delay-Time} -> [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasidentifier, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, tunneltype, tunnelmedium, tunnelgroupid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-Identifier}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0000-00-00 00:00:00', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', ! '%{Calling-Station-Id} [sql] expand: /usr/local/var/log/radius/sqltrace.sql -> /usr/local/var/log/radius/sqltrace.sql rlm_sql (sql): Reserving sql socket id: 3 rlm_sql_mysql: query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasidentifier, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, tunneltype, tunnelmedium, tunnelgroupid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('4a30b4a8/00:13:02:8d:f3:1f/44', 'aeb3d50af9d33fb8', 'isschrpg', '', 'WM07-1', '10.12.80.109', '29', '', '2009-06-11 08:39:20', '0000-00-00 00:00:00', '0', 'RADIUS', '', '', '0', '0', '10.12.80.109', '129.11.1.138', 'VLAN', 'IEEE-802', '3022', '', '', '', '1! 29.11.1.138', '0', '0') rlm_sql (sql): Released sql socket id: 3 ++[sql] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> isschrpg attr_filter: Matched entry DEFAULT at line 1 ++[attr_filter.accounting_response] returns updated server home.example.com { } Sending Accounting-Request of id 66 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x313233 Proxying request 10 to home server 129.11.162.17 port 1813 Sending Accounting-Request of id 66 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x313233 Going to the next request Waking up in 0.1 seconds. Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:* Waking up in 0.4 seconds. Cleaning up request 0 ID 58 with timestamp +4 Cleaning up request 1 ID 59 with timestamp +4 Cleaning up request 2 ID 60 with timestamp +4 Cleaning up request 3 ID 61 with timestamp +4 Cleaning up request 4 ID 62 with timestamp +4 Cleaning up request 5 ID 63 with timestamp +4 Cleaning up request 6 ID 64 with timestamp +4 Waking up in 0.2 seconds. Cleaning up request 7 ID 65 with timestamp +4 Cleaning up request 8 ID 66 with timestamp +5 Cleaning up request 9 ID 67 with timestamp +5 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=123, length=157 Discarding duplicate request from client wism07-1 port 32769 - ID: 123 due to unfinished request 10 Waking up in 0.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.1 seconds. rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=123, length=157 Discarding duplicate request from client wism07-1 port 32769 - ID: 123 due to unfinished request 10 Waking up in 0.3 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.6 seconds. 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-20090611:08 [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-20090611:08 [detail.example.com] expand: %t -> Thu Jun 11 08:39:20 2009 [detail.example.com] Freeradius-Proxied-To = 129.11.162.17 ++[detail.example.com] returns ok } Sending Accounting-Response of id 123 to 10.12.80.109 port 32769 Finished request 10. Cleaning up request 10 ID 123 with timestamp +9 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 19 to 129.11.162.17 port 1813 Message-Authenticator := 0x00000000000000000000000000000000 NAS-Identifier := "Status Check. Are you alive?" Waking up in 0.3 seconds. rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=123, length=157 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44",User-Name = "isschrpg"' [acct_unique] Acct-Unique-Session-ID = "aeb3d50af9d33fb8". ++[acct_unique] returns ok [suffix] No '@' in User-Name = "isschrpg", 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-11/accounting-detail-08: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-11/accounting-detail-08:00 [detail] expand: %{Packet-Src-IP-Address} - %t -> 10.12.80.109 - Thu Jun 11 08:39:26 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} -> isschrpg ++[radutmp] returns ok [sql] expand: %{Stripped-User-Name} -> [sql] expand: %{User-Name} -> isschrpg [sql] expand: %{%{User-Name}:-DEFAULT} -> isschrpg [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> isschrpg [sql] sql_set_user escaped user --> 'isschrpg' [sql] expand: %{Acct-Delay-Time} -> [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasidentifier, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, tunneltype, tunnelmedium, tunnelgroupid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-Identifier}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0000-00-00 00:00:00', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', ! '%{Calling-Station-Id} [sql] expand: /usr/local/var/log/radius/sqltrace.sql -> /usr/local/var/log/radius/sqltrace.sql rlm_sql (sql): Reserving sql socket id: 2 rlm_sql_mysql: query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasidentifier, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, tunneltype, tunnelmedium, tunnelgroupid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('4a30b4a8/00:13:02:8d:f3:1f/44', 'aeb3d50af9d33fb8', 'isschrpg', '', 'WM07-1', '10.12.80.109', '29', '', '2009-06-11 08:39:26', '0000-00-00 00:00:00', '0', 'RADIUS', '', '', '0', '0', '10.12.80.109', '129.11.1.138', 'VLAN', 'IEEE-802', '3022', '', '', '', '1! 29.11.1.138', '0', '0') rlm_sql (sql): Released sql socket id: 2 ++[sql] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> isschrpg attr_filter: Matched entry DEFAULT at line 1 ++[attr_filter.accounting_response] returns updated server home.example.com { } Sending Accounting-Request of id 23 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x313233 Proxying request 12 to home server 129.11.162.17 port 1813 Sending Accounting-Request of id 23 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x313233 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-*:* detail_recv: Renaming /usr/local/var/log/radius/radacct/detail.example.com/detail-20090611:08 -> /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 = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = "aeb3d50af9d33fb8" SQL-User-Name = "isschrpg" Realm = "acct_realm.example.com" FreeRADIUS-Proxied-To = 129.11.162.17 Packet-Original-Timestamp = "Jun 11 2009 08:39:20 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 243 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x3231313537 Proxying request 13 to home server 129.11.162.17 port 1813 Sending Accounting-Request of id 243 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x3231313537 Going to the next request Waking up in 0.5 seconds. Waking up in 0.4 seconds. Waking up in 0.1 seconds. Waking up in 1.0 seconds. Waking up in 1.1 seconds. Waking up in 0.2 seconds. Waking up in 1.0 seconds. Waking up in 0.9 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] 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-20090611:08 [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-20090611:08 [detail.example.com] expand: %t -> Thu Jun 11 08:39:26 2009 [detail.example.com] Freeradius-Proxied-To = 129.11.162.17 ++[detail.example.com] returns ok } Sending Accounting-Response of id 123 to 10.12.80.109 port 32769 Finished request 12. Cleaning up request 12 ID 123 with timestamp +15 Going to the next request Waking up in 0.2 seconds. Waking up in 0.1 seconds. Rejecting request 13 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 13. Cleaning up request 13 ID 21157 with timestamp +15 Going to the next request Waking up in 0.9 seconds. Waking up in 23.9 seconds. Sending Status-Server of id 131 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 2.0 seconds. detail_recv: Read packet from /usr/local/var/log/radius/radacct/detail.example.com/detail.work User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = "aeb3d50af9d33fb8" SQL-User-Name = "isschrpg" Realm = "acct_realm.example.com" FreeRADIUS-Proxied-To = 129.11.162.17 Packet-Original-Timestamp = "Jun 11 2009 08:39:20 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 247 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x3431353031 Proxying request 15 to home server 129.11.162.17 port 1813 Sending Accounting-Request of id 247 to 129.11.162.17 port 1813 User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = 0x3431353031 Going to the next request Waking up in 0.8 seconds. Waking up in 0.1 seconds. Waking up in 0.8 seconds. Waking up in 0.7 seconds. Waking up in 0.7 seconds. Waking up in 1.1 seconds. Waking up in 1.0 seconds. Waking up in 0.4 seconds. Rejecting request 15 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 15. Cleaning up request 15 ID 41501 with timestamp +51 Going to the next request Waking up in 0.6 seconds. Waking up in 15.9 seconds. Sending Status-Server of id 34 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 10.0 seconds. detail_recv: Read packet from /usr/local/var/log/radius/radacct/detail.example.com/detail.work User-Name = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = "aeb3d50af9d33fb8" SQL-User-Name = "isschrpg" Realm = "acct_realm.example.com" FreeRADIUS-Proxied-To = 129.11.162.17 Packet-Original-Timestamp = "Jun 11 2009 08:39:20 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 from internal virtual server. server home.example.com { } server home.example.com { } # server home.example.com Finished request 17. Cleaning up request 17 ID 9120 with timestamp +87 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-*:* detail_recv: Renaming /usr/local/var/log/radius/radacct/detail.example.com/detail-20090611:08 -> /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 = "isschrpg" 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 = "4a30b4a8/00:13:02:8d:f3:1f/44" 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 = "aeb3d50af9d33fb8" SQL-User-Name = "isschrpg" Realm = "acct_realm.example.com" FreeRADIUS-Proxied-To = 129.11.162.17 Packet-Original-Timestamp = "Jun 11 2009 08:39:26 BST" Acct-Delay-Time = 73 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 18. Cleaning up request 18 ID 39494 with timestamp +88 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 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-*:*
When both RADIUS servers are operational robust proxying works. When one of the servers is unreachable the other server (that's attempting to proxy an accounting request) will delete the detail.work file from the listener's sub-directory after failing to get a response from the other server.
Let us see.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=123, length=157 ... [detail] expand: /usr/local/var/log/radius/radacct/%Y-%m-%d/accounting-detail-%H:00 -> /usr/local/var/log/radius/radacct/2009-06-11/accounting-detail-08: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-11/accounting-detail-08:00 [detail] expand: %{Packet-Src-IP-Address} - %t -> 10.12.80.109 - Thu Jun 11 08:39:20 2009 ++[detail] returns ok
... writes to accounting detail file ...
[attr_filter.accounting_response] expand: %{User-Name} -> isschrpg attr_filter: Matched entry DEFAULT at line 1 ++[attr_filter.accounting_response] returns updated server home.example.com { } Sending Accounting-Request of id 66 to 129.11.162.17 port 1813 ... Proxying request 10 to home server 129.11.162.17 port 1813 Sending Accounting-Request of id 66 to 129.11.162.17 port 1813
... and sends proxy.
Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:* Waking up in 0.4 seconds. Polling for detail file /usr/local/var/log/radius/radacct/detail.example.com/detail-*:*
Looks in backup detail file a few times.
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=123, length=157 Discarding duplicate request from client wism07-1 port 32769 - ID: 123 due to unfinished request 10 Waking up in 0.1 seconds.
This is NAS repeating request. But we are still waiting for home server to respond.
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. rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=123, length=157 Discarding duplicate request from client wism07-1 port 32769 - ID: 123 due to unfinished request 10 Waking up in 0.3 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.6 seconds. Rejecting request 10 due to lack of any response from home server 129.11.162.17 port 1813
Waited enough. Go to failover.
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-20090611:08 [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-20090611:08 [detail.example.com] expand: %t -> Thu Jun 11 08:39:20 2009 [detail.example.com] Freeradius-Proxied-To = 129.11.162.17 ++[detail.example.com] returns ok }
Writing packet to failover detail ...
Sending Accounting-Response of id 123 to 10.12.80.109 port 32769
... and sending response to the NAS ...
Finished request 10. Cleaning up request 10 ID 123 with timestamp +9
... removing request from the list (that might be a problem) ...
Going to the next request PROXY: Marking home server 129.11.162.17 port 1813 as zombie (it looks like it is dead).
... marking home server as dead ...
Sending Status-Server of id 19 to 129.11.162.17 port 1813 Message-Authenticator := 0x00000000000000000000000000000000 NAS-Identifier := "Status Check. Are you alive?"
... and checking if it works.
Waking up in 0.3 seconds.
Done, but ...
rad_recv: Accounting-Request packet from host 10.12.80.109 port 32769, id=123, length=157
... your NAS didn't get the response. Since packet (id 123) was removed from the list server doesn't know it is the same one. So off we go again:
[detail] expand: /usr/local/var/log/radius/radacct/%Y-%m-%d/accounting-detail-%H:00 -> /usr/local/var/log/radius/radacct/2009-06-11/accounting-detail-08: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-11/accounting-detail-08:00 [detail] expand: %{Packet-Src-IP-Address} - %t -> 10.12.80.109 - Thu Jun 11 08:39:26 2009 ++[detail] returns ok
Write to accounting detail ...
Sending Accounting-Request of id 23 to 129.11.162.17 port 1813 ... Proxying request 12 to home server 129.11.162.17 port 1813 Sending Accounting-Request of id 23 to 129.11.162.17 port 1813
... try to proxy (I am not sure why did this happen - server is suposed to be marked dead; but it is still treated as alive) ...
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-20090611:08 -> /usr/local/var/log/radius/radacct/detail.example.com/detail.work
... and run into trouble. This is not suposed to be polled again until status of home server is changed to active.
detail_recv: Read packet from /usr/local/var/log/radius/radacct/detail.example.com/detail.work ... server home.example.com { +- entering group accounting {...} ++[control] returns noop } # server home.example.com server home.example.com { } Sending Accounting-Request of id 243 to 129.11.162.17 port 1813 ... Proxying request 13 to home server 129.11.162.17 port 1813 Sending Accounting-Request of id 243 to 129.11.162.17 port 1813
Failover now tries to proxy (home server is still not treated as dead)...
Going to the next request Waking up in 0.5 seconds. Waking up in 0.4 seconds. Waking up in 0.1 seconds. Waking up in 1.0 seconds. Waking up in 1.1 seconds. Waking up in 0.2 seconds. Waking up in 1.0 seconds. Waking up in 0.9 seconds. Rejecting request 12 due to lack of any response from home server 129.11.162.17 port 1813
... and decides to reject ...
Found Post-Proxy-Type server home.example.com { +- entering group Fail {...}
... and gets into the loop. After a few loops home server is treated as dead, packet has nowhere to go and is lost. Try increasing cleanup delay in radiusd.conf. See if that fixes the issue. If the request is kept longer on the list NAS request recieved after accounting response was sent should be caught and ignored. Ivan Kalik Kalik Informatika ISP
participants (2)
-
Chris Howley -
Ivan Kalik