Proxy response_window issue

[JS SV]

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!