intermittent auth issue (proxy: request is no longer in proxy hash)

[Chris Knipe]

On Thu, Jul 3, 2014 at 1:46 PM, Phil Mayers <p.mayers at imperial.ac.uk> wrote:
> On 03/07/14 12:12, Chris Knipe wrote:
>
>> Very intermittently this happens (and it's a very small amount of the
>> overall amount of requests too):
>> Received Access-Accept Id 28 from 127.0.0.1:18130 to 127.0.0.1:5245 length
>> 106
>>          Configuration-Token = 'OK:100:15:V:26843545600'
>>          Reply-Message = 'Welcome to the ...'
>>          Service-Type = Authenticate-Only
>>          Proxy-State = 0x3835
>>          Default-TTL = 19
>> Thu Jul  3 11:55:49 2014 : Debug: (216) proxy: request is no longer in
>> proxy hash
>
>
> Which version is this?
>

root at sql02:/etc/freeradius# radiusd -v
radiusd: FreeRADIUS Version 3.0.3, for host x86_64-unknown-linux-gnu,
built on Jun 23 2014 at 17:54:45
Copyright (C) 1999-2014 The FreeRADIUS server project and contributors
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License
For more information about these matters, see the file named COPYRIGHT

It's definitely looking to be like something in FR, but I can't
read/understand C, so I have no idea where to even begin looking :-(

I also tried to retransmit the packet in the event where this does
happen, but FR just does the same thing - it's almost like it caches
the proxy result, and returns the cached response WITHOUT the rest of
the attributes (i.e. only returns the access-accept packet without
including the rest of the attributes).  What's interesting to me, is
that I can see from my own personal logs that the proxy returns (up
to) 15 access-accepts for different (unique) requests.  Yet, FR will
only execute post-proxy for one or two of the responses.

This is example what radsecproxy returns on 7 unique access-requests,
in quick succession (in quick succession I am basically saying that
there's less than a 10us difference in timestamp between the
requests)...
Jul  3 14:25:38 sql02 radsecproxy[5364]: Access-Accept for user
user at proxy.realm stationid a.b.28.173 from AUTH-CRY001 (Welcome to the
...) to 127.0.0.1 (127.0.0.1)
Jul  3 14:25:38 sql02 radsecproxy[5364]: Access-Accept for user
user at proxy.realm stationid a.b.28.173 from AUTH-CRY001 (Welcome to the
...) to 127.0.0.1 (127.0.0.1)
Jul  3 14:25:38 sql02 radsecproxy[5364]: Access-Accept for user
user at proxy.realm stationid a.b.28.173 from AUTH-CRY001 (Welcome to the
...) to 127.0.0.1 (127.0.0.1)
Jul  3 14:25:38 sql02 radsecproxy[5364]: Access-Accept for user
user at proxy.realm stationid a.b.28.173 from AUTH-CRY001 (Welcome to the
...) to 127.0.0.1 (127.0.0.1)
Jul  3 14:25:38 sql02 radsecproxy[5364]: Access-Accept for user
user at proxy.realm stationid a.b.28.173 from AUTH-CRY001 (Welcome to the
...) to 127.0.0.1 (127.0.0.1)
Jul  3 14:25:38 sql02 radsecproxy[5364]: Access-Accept for user
user at proxy.realm stationid a.b.28.173 from AUTH-CRY001 (Welcome to the
...) to 127.0.0.1 (127.0.0.1)
Jul  3 14:25:39 sql02 radsecproxy[5364]: Access-Accept for user
user at proxy.realm stationid a.b.28.173 from AUTH-CRY001 (Welcome to the
...) to 127.0.0.1 (127.0.0.1)
Jul  3 14:25:39 sql02 radiusd[24200]: DEBUG: Configuration-Token:
OK:305D98AD-820B-3065-8F96-6C8AB8572E07:user at proxy.realm:V:26843545600:15:Welcome
to the ...
Jul  3 14:25:39 sql02 radiusd[24200]: post_proxy(): 0.006 Seconds,
Authentication successful for user at proxy.realm, cli a.b.28.173,
sessions 2/15

In other words, radsecproxy returned 7 access-accepts for 7 unique
requests (and I know they are unique, as the NAS-Port-Id for each
individual request would be different) received from FR.  However,
from the 7 responses to the proxied requests, FR only executed
post_proxy for 1 of them.  The first proxied request passes through
post_proxy, and the remaining 6 ("cached") then goes directly to
post_auth not returning any attributes, but only the access-accept.

It would be my understanding, that all 7 responses would need to
execute post_proxy.

--
Chris.