Hi, I'm having a behavior that I don't fully understand when using proxy timers. I am using radclient to do the tests and I find that if radclient sends, for example, 3 retransmissions (timeout) the timers do not add up. I have the following configuration for home_server: response_window = 20 zombie_period = 40 check_interval = 30 num_answers_to_alive = 3 fail no response no response ------>|-------------------------------->|---------------------------------->|-------------------- req. response_window zombie_period (dead) 20s 40s The part that doesn't work for me is the response_window, if only one request is sent with radclient it goes well, the problem comes if more are sent, I add the debug: (0) Mon Jun 13 13:02:59 2022: Debug: Received Access-Request Id 205 from 127.0.0.1:60690 to 127.0.0.1:1812 length 236 (0) Mon Jun 13 13:02:59 2022: Debug: User-Name = "000a0b0c0d0f" ... (0) Mon Jun 13 13:02:59 2022: Debug: NAS-IP-Address = 10.10.36.50 (0) Mon Jun 13 13:02:59 2022: Debug: # Executing section authorize from file /etc/raddb/sites-enabled/default (0) Mon Jun 13 13:02:59 2022: Debug: authorize { ... (0) Mon Jun 13 13:02:59 2022: Debug: } # authorize = updated (0) Mon Jun 13 13:02:59 2022: Debug: Starting proxy to home server 10.10.39.211 port 1812 (0) Mon Jun 13 13:02:59 2022: Debug: server default { (0) Mon Jun 13 13:02:59 2022: Debug: } (0) Mon Jun 13 13:02:59 2022: Debug: Sent Access-Request Id 145 from 0.0.0.0:42987 to 10.10.39.211:1812 length 237 (0) Mon Jun 13 13:02:59 2022: Debug: User-Name = "000a0b0c0d0f" ... (0) Mon Jun 13 13:02:59 2022: Debug: Proxy-State = 0x323035 (0) Mon Jun 13 13:02:59 2022: Debug: Expecting proxy response no later than 19.673084 seconds from now (0) Mon Jun 13 13:03:04 2022: Debug: Sending duplicate proxied request to home server 10.10.39.211 port 1812 - ID: 145 (0) Mon Jun 13 13:03:04 2022: Debug: Sent Access-Request Id 145 from 0.0.0.0:42987 to 10.10.39.211:1812 length 237 (0) Mon Jun 13 13:03:04 2022: Debug: User-Name = "000a0b0c0d0f" ... (0) Mon Jun 13 13:03:04 2022: Debug: Event-Timestamp = "Jun 13 2022 13:02:59 CEST" (0) Mon Jun 13 13:03:04 2022: Debug: Proxy-State = 0x323035 (0) Mon Jun 13 13:03:09 2022: Debug: Sending duplicate proxied request to home server 10.10.39.211 port 1812 - ID: 145 (0) Mon Jun 13 13:03:09 2022: Debug: Sent Access-Request Id 145 from 0.0.0.0:42987 to 10.10.39.211:1812 length 237 (0) Mon Jun 13 13:03:09 2022: Debug: User-Name = "000a0b0c0d0f" ... (0) Mon Jun 13 13:03:09 2022: Debug: Event-Timestamp = "Jun 13 2022 13:02:59 CEST" (0) Mon Jun 13 13:03:09 2022: Debug: Proxy-State = 0x323035 (0) Mon Jun 13 13:03:19 2022: Debug: Expecting proxy response no later than 9.993284 seconds from now (0) Mon Jun 13 13:03:29 2022: Debug: No proxy response, giving up on request and marking it done (0) Mon Jun 13 13:03:29 2022: ERROR: Failing proxied request for user "000a0b0c0d0f", due to lack of any response from home server 10.10.39.211 port 1812 (0) Mon Jun 13 13:03:29 2022: Debug: Clearing existing &reply: attributes (0) Mon Jun 13 13:03:29 2022: Debug: Found Post-Proxy-Type Fail-Authentication (0) Mon Jun 13 13:03:29 2022: Debug: server default { (0) Mon Jun 13 13:03:29 2022: Debug: # Executing group from file /etc/raddb/sites-enabled/default (0) Mon Jun 13 13:03:29 2022: Debug: Post-Proxy-Type Fail-Authentication { (0) Mon Jun 13 13:03:29 2022: Debug: policy accept { (0) Mon Jun 13 13:03:29 2022: Debug: update control { (0) Mon Jun 13 13:03:29 2022: Debug: } # update control = noop (0) Mon Jun 13 13:03:29 2022: Debug: [handled] = handled (0) Mon Jun 13 13:03:29 2022: Debug: } # policy accept = handled (0) Mon Jun 13 13:03:29 2022: Debug: } # Post-Proxy-Type Fail-Authentication = handled (0) Mon Jun 13 13:03:29 2022: Debug: } (0) Mon Jun 13 13:03:29 2022: Debug: # Executing section post-auth from file /etc/raddb/sites-enabled/default (0) Mon Jun 13 13:03:29 2022: Debug: Sent Access-Accept Id 205 from 127.0.0.1:1812 to 127.0.0.1:60690 length 0 (0) Mon Jun 13 13:03:29 2022: Debug: Finished request (0) Mon Jun 13 13:03:34 2022: Debug: Cleaning up request packet ID 205 with timestamp +7 I can see in the first request that the timer starts at 20s (13:02:59) but when I receive the third request, the timer has 10s left (13:03:19) when it should have finished, right? What are these extra 10s due to? Thanks!
On Jun 13, 2022, at 7:20 AM, JS SV <jssv51997@gmail.com> wrote:
Hi, I'm having a behavior that I don't fully understand when using proxy timers. I am using radclient to do the tests and I find that if radclient sends, for example, 3 retransmissions (timeout) the timers do not add up.
The timers operate as documented. The usual confusion is that people think all of the timers are global. They're not. The response_window is per-packet. It requires the client to keep resending packets for the timers to run. There is no global timer which tracks responses across all packets. As a result, if the client sends one packet and stops, the server never notices that "response_window" has been hit. The server has to receive multiple retransmissions from the client. So "response_window" doesn't work as most people think it does. But it does work as documented. There's no global response_window timer because it's difficult (and slow) to keep such a timer across multiple threads. Alan DeKok.
I think what you say makes sense to me. but I am not sure about it. If I send three Access-Requests, each of them will have its response_window, right? so, when the first packet arrives, the home_server have 20s before the server is marked zombie?(this is the part that I may not fully understand). and the two subsequent packages will have their own response_window timers? I do not finish seeing clearly because if I define 20s as response_window it is taking me 30s to mark as zombie thanks El lun, 13 jun 2022 a las 16:43, Alan DeKok (<aland@deployingradius.com>) escribió:
On Jun 13, 2022, at 7:20 AM, JS SV <jssv51997@gmail.com> wrote:
Hi, I'm having a behavior that I don't fully understand when using proxy timers. I am using radclient to do the tests and I find that if radclient sends, for example, 3 retransmissions (timeout) the timers do not add up.
The timers operate as documented. The usual confusion is that people think all of the timers are global. They're not.
The response_window is per-packet. It requires the client to keep resending packets for the timers to run. There is no global timer which tracks responses across all packets.
As a result, if the client sends one packet and stops, the server never notices that "response_window" has been hit. The server has to receive multiple retransmissions from the client.
So "response_window" doesn't work as most people think it does. But it does work as documented.
There's no global response_window timer because it's difficult (and slow) to keep such a timer across multiple threads.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Jun 13, 2022, at 3:51 PM, JS SV <jssv51997@gmail.com> wrote:
I think what you say makes sense to me. but I am not sure about it. If I send three Access-Requests, each of them will have its response_window, right?
Yes.
so, when the first packet arrives, the home_server have 20s before the server is marked zombie?(this is the part that I may not fully understand). and the two subsequent packages will have their own response_window timers?
I do not finish seeing clearly because if I define 20s as response_window it is taking me 30s to mark as zombie
The timers are drive by packets from the clients. There is no timer started when the first packet is proxied. i.e if the client sends packets at 0 seconds, 8, 16, and 24 seconds, the server will see at 24 seconds that the home server is not responsive. The server won't fire a timer at 20 seconds exactly. Alan DeKok.
Ok, thank you very much for your explanation. I only leave here last log (0) Mon Jun 13 23:27:44 2022: Debug: Received Access-Request Id 139 from 127.0.0.1:47353 to 127.0.0.1:1812 length 236 ... (0) Mon Jun 13 23:27:44 2022: Debug: Sent Access-Request Id 118 from 0.0.0.0:42706 to 10.20.39.211:1812 length 237 (0) Mon Jun 13 23:27:44 2022: Debug: Expecting proxy response no later than 19.673733 seconds from now ... (0) Mon Jun 13 23:27:49 2022: Debug: Sending duplicate proxied request to home server 10.20.39.211 port 1812 - ID: 118 (0) Mon Jun 13 23:27:49 2022: Debug: Sent Access-Request Id 118 from 0.0.0.0:42706 to 10.20.39.211:1812 length 237 ... (0) Mon Jun 13 23:27:54 2022: Debug: Sending duplicate proxied request to home server 10.20.39.211 port 1812 - ID: 118 (0) Mon Jun 13 23:27:54 2022: Debug: Sent Access-Request Id 118 from 0.0.0.0:42706 to 10.20.39.211:1812 length 237 ... (0) Mon Jun 13 23:28:04 2022: Debug: Expecting proxy response no later than 9.992814 seconds from now (0) Mon Jun 13 23:28:14 2022: Debug: No proxy response, giving up on request and marking it done (0) Mon Jun 13 23:28:14 2022: ERROR: Failing proxied request for user "000a0b0c0d0f", due to lack of any response from home server 10.20.39.211 port 1812 At 23:27:44 I understand that the response_window is started (we are waiting for a response). then we receive the other two requests that we mentioned (the client has a timeout in the first one so it sends another and another) After that, at 23:28:04 (20s after receiving the first req so that "theoretically" the response_window has passed) it tells us that it waits 10s more and after those 10s the home_server is set to zombie. so the total of 30s said. Thanks Alan! El lun, 13 jun 2022 a las 22:12, Alan DeKok (<aland@deployingradius.com>) escribió:
On Jun 13, 2022, at 3:51 PM, JS SV <jssv51997@gmail.com> wrote:
I think what you say makes sense to me. but I am not sure about it. If I send three Access-Requests, each of them will have its response_window, right?
Yes.
so, when the first packet arrives, the home_server have 20s before the server is marked zombie?(this is the part that I may not fully understand). and the two subsequent packages will have their own response_window timers?
I do not finish seeing clearly because if I define 20s as response_window it is taking me 30s to mark as zombie
The timers are drive by packets from the clients. There is no timer started when the first packet is proxied.
i.e if the client sends packets at 0 seconds, 8, 16, and 24 seconds, the server will see at 24 seconds that the home server is not responsive. The server won't fire a timer at 20 seconds exactly.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Jun 13, 2022, at 4:45 PM, JS SV <jssv51997@gmail.com> wrote:
At 23:27:44 I understand that the response_window is started
Again, it's the request_window for the first packet. There is no global request_window.
(we are waiting for a response). then we receive the other two requests that we mentioned (the client has a timeout in the first one so it sends another and another)
Each of those two packets have their own response_window timers
After that, at 23:28:04 (20s after receiving the first req so that "theoretically" the response_window has passed) it tells us that it waits 10s more and after those 10s the home_server is set to zombie.
so the total of 30s said.
Yes, that's how it works. Alan DeKok.
participants (2)
-
Alan DeKok -
JS SV