On Thu, Jul 3, 2014 at 1:46 PM, Phil Mayers <p.mayers@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@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@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@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@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@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@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@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@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@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@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.