RE: Log when the proxy home_server has no response
Thanks alan for help. But I haven't got it done now..still cannot let it get into post-proxy-fail section.please take a look on my config and another debug log! Thanks! Below is my proxy.conf.home_server test_1 { type=auth+acct ipaddr=172.30.179.22 port=1812 secret = test123 require_message_authenticator=no response_window = 5 zombie_period = 5 revive_interval = 5 status_check = none check_interval = 30 num_answers_to_alive = 3}home_server_pool test_pool { type = fail-over home_server = test_1}realm test { pool = test_pool nostrip} Because the scenario what I simulate is that external AAA might not be freeradius, so I set status_check to "none". Also, as alan mentioned, I set response_window and zombie_period to 5. About my ./site-available/default config, I only show the part of post-proxy. You can find that in Post-Proxy-Type Fail section, I want to update a Tmp-String value. Then I can know it is proxy timeout so that I will write down a log in perl.post-proxy { # If you want to have a log of replies from a home server, # un-comment the following line, and the 'detail post_proxy_log' # section, above.# post_proxy_log # attr_rewrite # Uncomment the following line if you want to filter replies from # remote proxies based on the rules defined in the 'attrs' file.# attr_filter.post-proxy Post-Proxy-Type Fail { update control { Tmp-String-0 := "PJ-TO" } perl-log-module-here }} last is my debug log: rad_recv: Access-Request packet from host 172.30.179.21 port 55342, id=27, length=79 User-Name = "test@test" User-Password = "123" NAS-IP-Address = 127.0.0.1 NAS-Port = 0 Message-Authenticator = 0x3d63469358ade53b4181dc50a857762b# Executing section authorize from file /opt/freeRADIUS/etc/raddb/sites-enabled/default+- entering group authorize {...} expand: %{client:Gateway-Type} -> ALU++[control] returns notfoundrlm_perl: RAD_CONFIG: Tmp-String-8 = ALUrlm_perl: Added pair User-Name = test@testrlm_perl: Added pair User-Password = 123rlm_perl: Added pair NAS-Port = 0rlm_perl: Added pair NAS-IP-Address = 127.0.0.1rlm_perl: Added pair Message-Authenticator = 0x3d63469358ade53b4181dc50a857762brlm_perl: Added pair Tmp-String-8 = ALU++[test_client_config] returns noop++[preprocess] returns ok[auth_log] expand: %{Packet-Src-IP-Address} -> 172.30.179.21[auth_log] expand: /opt/freeRADIUS/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d -> /opt/freeRADIUS/var/log/radius/radacct/172.30.179.21/auth-detail-20140214[auth_log] /opt/freeRADIUS/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /opt/freeRADIUS/var/log/radius/radacct/172.30.179.21/auth-detail-20140214[auth_log] expand: %t -> Fri Feb 14 09:36:15 2014++[auth_log] returns ok++[chap] returns noop++[mschap] returns noop++[digest] returns noop[suffix] Looking up realm "test" for User-Name = "test@test"[suffix] Found realm "test"[suffix] Adding Realm = "test"[suffix] Proxying request from user test to realm test[suffix] Preparing to proxy authentication request to realm "test" ++[suffix] returns updated[eap] No EAP-Message, not doing EAP++[eap] returns noop++[files] returns noop++[expiration] returns noop++[logintime] returns noop++[pap] returns noop# Executing section pre-proxy from file /opt/freeRADIUS/etc/raddb/sites-enabled/default+- entering group pre-proxy {...}[attr_filter.pre-proxy] expand: %{Realm} -> testattr_filter: Matched entry DEFAULT at line 50++[attr_filter.pre-proxy] returns updatedSending Access-Request of id 219 to 172.30.179.22 port 1812 User-Name = "test@test" User-Password = "123" NAS-IP-Address = 127.0.0.1 Message-Authenticator = 0x00000000000000000000000000000000 Proxy-State = 0x3237Proxying request 0 to home server 172.30.179.22 port 1812Sending Access-Request of id 219 to 172.30.179.22 port 1812 User-Name = "test@test" User-Password = "123" NAS-IP-Address = 127.0.0.1 Message-Authenticator = 0x00000000000000000000000000000000 Proxy-State = 0x3237Going to the next requestWaking up in 0.9 seconds.Waking up in 4.0 seconds.Cleaning up request 0 ID 27 with timestamp +7Marking home server 172.30.179.22 port 1812 as zombie (it looks like it is dead).rad_recv: Access-Request packet from host 172.30.179.21 port 55342, id=27, length=79 User-Name = "test@test" User-Password = "123" NAS-IP-Address = 127.0.0.1 NAS-Port = 0 Message-Authenticator = 0x3d63469358ade53b4181dc50a857762b# Executing section authorize from file /opt/freeRADIUS/etc/raddb/sites-enabled/default+- entering group authorize {...} expand: %{client:Gateway-Type} -> ALU++[control] returns notfoundrlm_perl: RAD_CONFIG: Tmp-String-8 = ALUrlm_perl: Added pair User-Name = test@testrlm_perl: Added pair User-Password = 123rlm_perl: Added pair NAS-Port = 0rlm_perl: Added pair NAS-IP-Address = 127.0.0.1rlm_perl: Added pair Message-Authenticator = 0x3d63469358ade53b4181dc50a857762brlm_perl: Added pair Tmp-String-8 = ALU++[test_client_config] returns noop++[preprocess] returns ok[auth_log] expand: %{Packet-Src-IP-Address} -> 172.30.179.21[auth_log] expand: /opt/freeRADIUS/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d -> /opt/freeRADIUS/var/log/radius/radacct/172.30.179.21/auth-detail-20140214[auth_log] /opt/freeRADIUS/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /opt/freeRADIUS/var/log/radius/radacct/172.30.179.21/auth-detail-20140214[auth_log] expand: %t -> Fri Feb 14 09:36:20 2014++[auth_log] returns ok++[chap] returns noop++[mschap] returns noop++[digest] returns noop[suffix] Looking up realm "test" for User-Name = "test@test"[suffix] Found realm "test"[suffix] Adding Realm = "test"[suffix] Proxying request from user test to realm test[suffix] Preparing to proxy authentication request to realm "test" ++[suffix] returns updated[eap] No EAP-Message, not doing EAP++[eap] returns noop++[files] returns noop++[expiration] returns noop++[logintime] returns noop++[pap] returns noop# Executing section pre-proxy from file /opt/freeRADIUS/etc/raddb/sites-enabled/default+- entering group pre-proxy {...}[attr_filter.pre-proxy] expand: %{Realm} -> testattr_filter: Matched entry DEFAULT at line 50++[attr_filter.pre-proxy] returns updatedSending Access-Request of id 69 to 172.30.179.22 port 1812 User-Name = "test@test" User-Password = "123" NAS-IP-Address = 127.0.0.1 Message-Authenticator = 0x00000000000000000000000000000000 Proxy-State = 0x3237Proxying request 1 to home server 172.30.179.22 port 1812Sending Access-Request of id 69 to 172.30.179.22 port 1812 User-Name = "test@test" User-Password = "123" NAS-IP-Address = 127.0.0.1 Message-Authenticator = 0x00000000000000000000000000000000 Proxy-State = 0x3237Going to the next requestWaking up in 0.9 seconds.Waking up in 4.0 seconds.Marking home server 172.30.179.22 port 1812 as dead.Cleaning up request 1 ID 27 with timestamp +12rad_recv: Access-Request packet from host 172.30.179.21 port 55342, id=27, length=79 User-Name = "test@test" User-Password = "123" NAS-IP-Address = 127.0.0.1 NAS-Port = 0 Message-Authenticator = 0x3d63469358ade53b4181dc50a857762b# Executing section authorize from file /opt/freeRADIUS/etc/raddb/sites-enabled/default+- entering group authorize {...} expand: %{client:Gateway-Type} -> ALU++[control] returns notfoundrlm_perl: RAD_CONFIG: Tmp-String-8 = ALUrlm_perl: Added pair User-Name = test@testrlm_perl: Added pair User-Password = 123rlm_perl: Added pair NAS-Port = 0rlm_perl: Added pair NAS-IP-Address = 127.0.0.1rlm_perl: Added pair Message-Authenticator = 0x3d63469358ade53b4181dc50a857762brlm_perl: Added pair Tmp-String-8 = ALU++[test_client_config] returns noop++[preprocess] returns ok[auth_log] expand: %{Packet-Src-IP-Address} -> 172.30.179.21[auth_log] expand: /opt/freeRADIUS/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d -> /opt/freeRADIUS/var/log/radius/radacct/172.30.179.21/auth-detail-20140214[auth_log] /opt/freeRADIUS/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /opt/freeRADIUS/var/log/radius/radacct/172.30.179.21/auth-detail-20140214[auth_log] expand: %t -> Fri Feb 14 09:36:25 2014++[auth_log] returns ok++[chap] returns noop++[mschap] returns noop++[digest] returns noop[suffix] Looking up realm "test" for User-Name = "test@test"[suffix] Found realm "test"[suffix] Adding Realm = "test"[suffix] Proxying request from user test to realm test[suffix] Preparing to proxy authentication request to realm "test" ++[suffix] returns updated[eap] No EAP-Message, not doing EAP++[eap] returns noop++[files] returns noop++[expiration] returns noop++[logintime] returns noop++[pap] returns noopERROR: Failed to find live home server for realm testThere was no response configured: rejecting request 2Using Post-Auth-Type REJECT# Executing group from file /opt/freeRADIUS/etc/raddb/sites-enabled/default+- entering group REJECT {...}[attr_filter.access_reject] expand: %{User-Name} -> test@testattr_filter: Matched entry DEFAULT at line 11++[attr_filter.access_reject] returns updatedDelaying reject of request 2 for 1 secondsGoing to the next requestWaking up in 0.9 seconds.Sending delayed reject for request 2Sending Access-Reject of id 27 to 172.30.179.21 port 55342Waking up in 4.9 seconds.Cleaning up request 2 ID 27 with timestamp +17Waking up in 53.9 seconds.Marking home server 172.30.179.22 port 1812 alive again... we have no idea if it really is alive or not.Ready to process requests. Is there anything I still need to get it down? Thanks for all your patience! Okis
Chuang Okis wrote:
Thanks alan for help. But I haven't got it done now..still cannot let it get into post-proxy-fail section. please take a look on my config and another debug log! Thanks!
Which version are you using?
Is there anything I still need to get it down? Thanks for all your patience!
You seem to have broken the server: rad_recv: Access-Request packet from host 172.30.179.21 port 55342, id=27, length=79 Which then gets proxied: Proxying request 0 to home server 172.30.179.22 port 1812 And then: Waking up in 4.0 seconds. Cleaning up request 0 ID 27 with timestamp +7 Huh? Why does that happen? The default is for the max_request_time to be 30 seconds. This allows for the request to stay "live" while the NAS retransmits. It looks like you set "max_request_time = 5". Don't do that. It's wrong. It's breaking the server. Alan DeKok.
No, I don't change the default max_request_time to 5, it is still 30 now. Sorry...actually I am a bit not get it about what you mean..but I am guessing could it be possible that I intentionally set policy *Do-Not-Response* on home server 172.30.179.22? Sorry about not illustrate clear enough, I try to describe again. I need to know the event type - proxy timeout while proxy access-request to external AAA and they don't response. So I set up a test environment which has three components: radiusclient, radius proxy, radius AAA. Then I used radiusclient to send request three times, all of them won't be replied to radius client. I also set this home_server with quite low value of zombie_period and response_window (both are 5).I thought that would be more easy to make my radius proxy to decide timeout? Just curious about one dumb question, does freeradius get into Post-Proxy-Type Fail section every time when home_server did not response or only when this home_server is marked as dead? Okis
Chuang Okis wrote:
No, I don't change the default max_request_time to 5, it is still 30 now.
Hmm... then something is wrong. The server is deleting the request before the client re-transmits.
I need to know the event type - proxy timeout while proxy access-request to external AAA and they don't response. So I set up a test environment which has three components: radiusclient, radius proxy, radius AAA.
Then I used radiusclient to send request three times, all of them won't be replied to radius client.
I also set this home_server with quite low value of zombie_period and response_window (both are 5). I thought that would be more easy to make my radius proxy to decide timeout?
The client has to keep retransmitting. The server doesn't wake up and decide that the home server hasn't responded. It is all driven by the client.
Just curious about one dumb question, does freeradius get into Post-Proxy-Type Fail section every time when home_server did not response or only when this home_server is marked as dead?
When there's no response to the request from the home server. But the server shouldn't be deleting the request, either. Alan DeKok.
participants (2)
-
Alan DeKok -
Chuang Okis