intermittent auth issue (proxy: request is no longer in proxy hash)
Hi All, I've manage to pull the below request (-Xxx) from a debug log. Very intermittently, and randomly, my FR would receive a auth-accept from an proxy server. The accept packet received from the proxy server includes a Configuration-Token attribute, which I then interpret and do stuff with in the post_proxy section, using rlm_perl. For some reason, the response received does not make it through post_proxy. From what I can gather in the logs, FR complains: Thu Jul 3 11:55:49 2014 : Debug: (216) proxy: request is no longer in proxy hash Thu Jul 3 11:55:49 2014 : Debug: (216) Found Auth-Type = Accept Thu Jul 3 11:55:49 2014 : Debug: (216) Auth-Type = Accept, accepting the user Thu Jul 3 11:55:49 2014 : Auth: (216) Login OK: [user@proxy.realm/oozuL8poop] (from client CLIENT port 0 cli c.d.99.6) And then of course, never passes the request off through rlm_perl. Can anyone shed some light on this in terms of how to fix this? It is imperative that that proxied response passes through rlm_perl - in my specific case, I am not concerned about how long the authentication process takes, but it is critically important that it passes through rlm_perl so that various aspects of the session can be setup... Full Debug Log: Received Access-Request Id 85 from e.f.240.36:22947 to e.f.136.224:1812 length 119 Called-Station-Id = 'a.b.8.42' Calling-Station-Id = 'c.d.99.6' NAS-IP-Address = e.f.240.36 NAS-Port-Type = Virtual NAS-Port-Id = '16980' Service-Type = Authenticate-Only User-Name = 'user@proxy.realm' User-Password = 'oozuL8poop' Thu Jul 3 11:55:48 2014 : Debug: (216) # Executing section authorize from file /etc/freeradius/radiusd.conf Thu Jul 3 11:55:48 2014 : Debug: (216) authorize { Thu Jul 3 11:55:48 2014 : Debug: (216) filter_username filter_username { Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ / /) Thu Jul 3 11:55:48 2014 : Debug: Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: literal --> Thu Jul 3 11:55:48 2014 : Debug: (216) EXPAND Thu Jul 3 11:55:48 2014 : Debug: (216) --> Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ / /) -> FALSE Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /@.*@/ ) Thu Jul 3 11:55:48 2014 : Debug: @.*@ Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: literal --> @.*@ Thu Jul 3 11:55:48 2014 : Debug: (216) EXPAND @.*@ Thu Jul 3 11:55:48 2014 : Debug: (216) --> @.*@ Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /@.*@/ ) -> FALSE Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /\\.\\./ ) Thu Jul 3 11:55:48 2014 : Debug: \.\. Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: literal --> \\\. Thu Jul 3 11:55:48 2014 : Debug: (216) EXPAND \.\. Thu Jul 3 11:55:48 2014 : Debug: (216) --> \\\. Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /\\.\\./ ) -> FALSE Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /\\.$/) Thu Jul 3 11:55:48 2014 : Debug: \.$ Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: literal --> \$$ Thu Jul 3 11:55:48 2014 : Debug: (216) EXPAND \.$ Thu Jul 3 11:55:48 2014 : Debug: (216) --> \$$ Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /\\.$/) -> FALSE Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /@\\./) Thu Jul 3 11:55:48 2014 : Debug: @\. Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: literal --> @\. Thu Jul 3 11:55:48 2014 : Debug: (216) EXPAND @\. Thu Jul 3 11:55:48 2014 : Debug: (216) --> @\. Thu Jul 3 11:55:48 2014 : Debug: (216) if (User-Name =~ /@\\./) -> FALSE Thu Jul 3 11:55:48 2014 : Debug: (216) } # filter_username filter_username = notfound Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [preprocess] = ok Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling auth_log (rlm_detail) for request 216 Thu Jul 3 11:55:48 2014 : Debug: /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-auth_log Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: literal --> /var/log/freeradius/ Thu Jul 3 11:55:48 2014 : Debug: percent --> Y Thu Jul 3 11:55:48 2014 : Debug: literal --> / Thu Jul 3 11:55:48 2014 : Debug: percent --> Y Thu Jul 3 11:55:48 2014 : Debug: literal --> - Thu Jul 3 11:55:48 2014 : Debug: percent --> m Thu Jul 3 11:55:48 2014 : Debug: literal --> / Thu Jul 3 11:55:48 2014 : Debug: percent --> Y Thu Jul 3 11:55:48 2014 : Debug: literal --> - Thu Jul 3 11:55:48 2014 : Debug: percent --> m Thu Jul 3 11:55:48 2014 : Debug: literal --> - Thu Jul 3 11:55:48 2014 : Debug: percent --> d Thu Jul 3 11:55:48 2014 : Debug: literal --> -auth_log Thu Jul 3 11:55:48 2014 : Debug: (216) auth_log : EXPAND /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-auth_log Thu Jul 3 11:55:48 2014 : Debug: (216) auth_log : --> /var/log/freeradius/2014/2014-07/2014-07-03-auth_log Thu Jul 3 11:55:48 2014 : Debug: (216) auth_log : /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-auth_log expands to /var/log/freeradius/2014/2014-07/2014-07-03-auth_log Thu Jul 3 11:55:48 2014 : Debug: %t Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: percent --> t Thu Jul 3 11:55:48 2014 : Debug: (216) auth_log : EXPAND %t Thu Jul 3 11:55:48 2014 : Debug: (216) auth_log : --> Thu Jul 3 11:55:48 2014 Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from auth_log (rlm_detail) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [auth_log] = ok Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling suffix (rlm_realm) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) suffix : Looking up realm "proxy.realm" for User-Name = "user@proxy.realm" Thu Jul 3 11:55:48 2014 : Debug: (216) suffix : Found realm "proxy.realm" Thu Jul 3 11:55:48 2014 : Debug: (216) suffix : Adding Realm = "proxy.realm" Thu Jul 3 11:55:48 2014 : Debug: (216) suffix : Proxying request from user user@proxy.realm to realm proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) suffix : Preparing to proxy authentication request to realm "proxy.realm" Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from suffix (rlm_realm) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [suffix] = updated Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling files (rlm_files) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from files (rlm_files) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [files] = noop Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling perl (rlm_perl) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- Proxy-To-Realm = proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- Called-Station-Id = a.b.8.42 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- Calling-Station-Id = c.d.99.6 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- NAS-IP-Address = e.f.240.36 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- NAS-Port-Type = Virtual Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- NAS-Port-Id = 16980 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- Service-Type = Authenticate-Only Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- User-Name = user@proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- User-Password = oozuL8poop Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- Realm = proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) perl : <-- Proxy-To-Realm = proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> NAS-Port-Type = Virtual Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> Service-Type = Authenticate-Only Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> Calling-Station-Id = c.d.99.6 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> Called-Station-Id = a.b.8.42 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> User-Name = user@proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> User-Password = oozuL8poop Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> Realm = proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> NAS-IP-Address = e.f.240.36 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> NAS-Port-Id = 16980 Thu Jul 3 11:55:48 2014 : Debug: (216) perl : --> Proxy-To-Realm = proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from perl (rlm_perl) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [perl] = noop Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling logintime (rlm_logintime) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from logintime (rlm_logintime) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [logintime] = noop Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling pap (rlm_pap) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from pap (rlm_pap) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [pap] = noop Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: calling chap (rlm_chap) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[authorize]: returned from chap (rlm_chap) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [chap] = noop Thu Jul 3 11:55:48 2014 : Debug: (216) } # authorize = updated Thu Jul 3 11:55:48 2014 : Debug: (216) # Executing section pre-proxy from file /etc/freeradius/radiusd.conf Thu Jul 3 11:55:48 2014 : Debug: (216) pre-proxy { Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail) for request 216 Thu Jul 3 11:55:48 2014 : Debug: /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-pre_proxy_log Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: literal --> /var/log/freeradius/ Thu Jul 3 11:55:48 2014 : Debug: percent --> Y Thu Jul 3 11:55:48 2014 : Debug: literal --> / Thu Jul 3 11:55:48 2014 : Debug: percent --> Y Thu Jul 3 11:55:48 2014 : Debug: literal --> - Thu Jul 3 11:55:48 2014 : Debug: percent --> m Thu Jul 3 11:55:48 2014 : Debug: literal --> / Thu Jul 3 11:55:48 2014 : Debug: percent --> Y Thu Jul 3 11:55:48 2014 : Debug: literal --> - Thu Jul 3 11:55:48 2014 : Debug: percent --> m Thu Jul 3 11:55:48 2014 : Debug: literal --> - Thu Jul 3 11:55:48 2014 : Debug: percent --> d Thu Jul 3 11:55:48 2014 : Debug: literal --> -pre_proxy_log Thu Jul 3 11:55:48 2014 : Debug: (216) pre_proxy_log : EXPAND /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-pre_proxy_log Thu Jul 3 11:55:48 2014 : Debug: (216) pre_proxy_log : --> /var/log/freeradius/2014/2014-07/2014-07-03-pre_proxy_log Thu Jul 3 11:55:48 2014 : Debug: (216) pre_proxy_log : /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-pre_proxy_log expands to /var/log/freeradius/2014/2014-07/2014-07-03-pre_proxy_log Thu Jul 3 11:55:48 2014 : Debug: %t Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: percent --> t Thu Jul 3 11:55:48 2014 : Debug: (216) pre_proxy_log : EXPAND %t Thu Jul 3 11:55:48 2014 : Debug: (216) pre_proxy_log : --> Thu Jul 3 11:55:48 2014 Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [pre_proxy_log] = ok Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[pre-proxy]: calling attr_filter.pre-proxy (rlm_attr_filter) for request 216 Thu Jul 3 11:55:48 2014 : Debug: %{Realm} Thu Jul 3 11:55:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:48 2014 : Debug: attribute --> Realm Thu Jul 3 11:55:48 2014 : Debug: { Thu Jul 3 11:55:48 2014 : Debug: ref 2 Thu Jul 3 11:55:48 2014 : Debug: list 1 Thu Jul 3 11:55:48 2014 : Debug: tag -128 Thu Jul 3 11:55:48 2014 : Debug: } Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : EXPAND %{Realm} Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : --> proxy.realm Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Matched entry DEFAULT at line 1 Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : NAS-Port-Type = Virtual allowed by NAS-Port-Type == Virtual Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "NAS-Port-Type" allowed by 1 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Service-Type = Authenticate-Only allowed by Service-Type == Authenticate-Only Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "Service-Type" allowed by 1 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Calling-Station-Id = 'c.d.99.6' allowed by Calling-Station-Id =* '' Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "Calling-Station-Id" allowed by 1 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Called-Station-Id = 'a.b.8.42' allowed by Called-Station-Id == 'a.b.8.42' Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "Called-Station-Id" allowed by 1 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : User-Name = 'user@proxy.realm' allowed by User-Name =* '' Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "User-Name" allowed by 1 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : User-Password = 'oozuL8poop' allowed by User-Password =* '' Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "User-Password" allowed by 1 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "Realm" allowed by 0 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "NAS-IP-Address" allowed by 0 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "NAS-Port-Id" allowed by 0 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "Message-Authenticator" allowed by 0 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Proxy-State = 0x3835 allowed by Proxy-State =* 0x Thu Jul 3 11:55:48 2014 : Debug: (216) attr_filter.pre-proxy : Attribute "Proxy-State" allowed by 1 rules, disallowed by 0 rules Thu Jul 3 11:55:48 2014 : Debug: (216) modsingle[pre-proxy]: returned from attr_filter.pre-proxy (rlm_attr_filter) for request 216 Thu Jul 3 11:55:48 2014 : Debug: (216) [attr_filter.pre-proxy] = updated Thu Jul 3 11:55:48 2014 : Debug: (216) } # pre-proxy = updated Thu Jul 3 11:55:48 2014 : Debug: (216) proxy: Trying to allocate ID (0/2) Thu Jul 3 11:55:48 2014 : Debug: (216) proxy: request is now in proxy hash Thu Jul 3 11:55:48 2014 : Debug: (216) proxy: allocating destination 127.0.0.1 port 18130 - Id 28 Thu Jul 3 11:55:48 2014 : Debug: (216) Proxying request to home server 127.0.0.1 port 18130 Sending Access-Request Id 28 from 0.0.0.0:5245 to 127.0.0.1:18130 Acct-Authentic := RADIUS Acct-Delay-Time := 0 NAS-IP-Address := 85.12.8.44 NAS-Port-Type = Virtual Service-Type = Authenticate-Only Calling-Station-Id = 'c.d.99.6' Called-Station-Id = 'a.b.8.42' User-Name = 'user@proxy.realm' User-Password = 'oozuL8poop' Proxy-State = 0x3835 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 Thu Jul 3 11:55:49 2014 : Debug: (216) Found Auth-Type = Accept Thu Jul 3 11:55:49 2014 : Debug: (216) Auth-Type = Accept, accepting the user Thu Jul 3 11:55:49 2014 : Auth: (216) Login OK: [user@proxy.realm/oozuL8poop] (from client CLIENT port 0 cli c.d.99.6) Thu Jul 3 11:55:49 2014 : Debug: (216) # Executing section post-auth from file /etc/freeradius/radiusd.conf Thu Jul 3 11:55:49 2014 : Debug: (216) post-auth { Thu Jul 3 11:55:49 2014 : Debug: (216) modsingle[post-auth]: calling reply_log (rlm_detail) for request 216 Thu Jul 3 11:55:49 2014 : Debug: /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-reply_log Thu Jul 3 11:55:49 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:49 2014 : Debug: literal --> /var/log/freeradius/ Thu Jul 3 11:55:49 2014 : Debug: percent --> Y Thu Jul 3 11:55:49 2014 : Debug: literal --> / Thu Jul 3 11:55:49 2014 : Debug: percent --> Y Thu Jul 3 11:55:49 2014 : Debug: literal --> - Thu Jul 3 11:55:49 2014 : Debug: percent --> m Thu Jul 3 11:55:49 2014 : Debug: literal --> / Thu Jul 3 11:55:49 2014 : Debug: percent --> Y Thu Jul 3 11:55:49 2014 : Debug: literal --> - Thu Jul 3 11:55:49 2014 : Debug: percent --> m Thu Jul 3 11:55:49 2014 : Debug: literal --> - Thu Jul 3 11:55:49 2014 : Debug: percent --> d Thu Jul 3 11:55:49 2014 : Debug: literal --> -reply_log Thu Jul 3 11:55:49 2014 : Debug: (216) reply_log : EXPAND /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-reply_log Thu Jul 3 11:55:49 2014 : Debug: (216) reply_log : --> /var/log/freeradius/2014/2014-07/2014-07-03-reply_log Thu Jul 3 11:55:49 2014 : Debug: (216) reply_log : /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-reply_log expands to /var/log/freeradius/2014/2014-07/2014-07-03-reply_log Thu Jul 3 11:55:49 2014 : Debug: %t Thu Jul 3 11:55:49 2014 : Debug: Parsed xlat tree: Thu Jul 3 11:55:49 2014 : Debug: percent --> t Thu Jul 3 11:55:49 2014 : Debug: (216) reply_log : EXPAND %t Thu Jul 3 11:55:49 2014 : Debug: (216) reply_log : --> Thu Jul 3 11:55:48 2014 Thu Jul 3 11:55:49 2014 : Debug: (216) modsingle[post-auth]: returned from reply_log (rlm_detail) for request 216 Thu Jul 3 11:55:49 2014 : Debug: (216) [reply_log] = ok Thu Jul 3 11:55:49 2014 : Debug: (216) } # post-auth = ok Sending Access-Accept Id 85 from e.f.136.224:1812 to e.f.240.36:22947 -- Regards, Chris Knipe
On 3 Jul 2014, at 11:15, Chris Knipe <savage@savage.za.org> wrote:
Thu Jul 3 11:55:49 2014 : Debug: (216) Found Auth-Type = Accept Thu Jul 3 11:55:49 2014 : Debug: (216) Auth-Type = Accept, accepting the user
This is more likely to be your issue - I believe the previous message is just informational. Could you post your pre/post proxy blocks please? Regards, Adam Bishop gpg: 0x6609D460 Janet, the UK's research and education network. Janet(UK) is a trading name of Jisc Collections and Janet Limited, a not-for-profit company which is registered in England under No. 2881024 and whose Registered Office is at Lumen House, Library Avenue, Harwell Oxford, Didcot, Oxfordshire. OX11 0SG. VAT No. 614944238
On Thu, Jul 3, 2014 at 12:40 PM, Adam Bishop <Adam.Bishop@ja.net> wrote:
On 3 Jul 2014, at 11:15, Chris Knipe <savage@savage.za.org> wrote:
Thu Jul 3 11:55:49 2014 : Debug: (216) Found Auth-Type = Accept Thu Jul 3 11:55:49 2014 : Debug: (216) Auth-Type = Accept, accepting the user
This is more likely to be your issue - I believe the previous message is just informational.
Could you post your pre/post proxy blocks please?
I don't do anything pre-proxy. # Pre-Proxy pre-proxy { pre_proxy_log attr_filter.pre-proxy # perl } # Post-Proxy post-proxy { post_proxy_log attr_filter.post-proxy perl } Post-Proxy, auth-type accept makes sense. The response from the proxy server would surely state that authentication was successful or not. Given the debug log I posted, FR does not execute post_proxy at all. Here's a -Xxx of a request from the SAME proxy server, where it DOES pass through post_proxy. Thu Jul 3 12:59:48 2014 : Debug: (0) Proxying request to home server 127.0.0.1 port 18130 Sending Access-Request Id 211 from 0.0.0.0:38667 to 127.0.0.1:18130 Acct-Authentic := RADIUS Acct-Delay-Time := 0 NAS-IP-Address := a.b.8.44 NAS-Port-Type = Virtual Service-Type = Authenticate-Only Calling-Station-Id = 'c.d.49.113' Called-Station-Id = 'a.b.8.42' User-Name = 'user@proxy.realm' User-Password = 'Ohs3dee2ei' NAS-Port-Id = '1959' Proxy-State = 0x313638 Thu Jul 3 12:59:48 2014 : Debug: Waking up in 0.2 seconds. Received Access-Accept Id 211 from 127.0.0.1:18130 to 127.0.0.1:38667 length 107 Configuration-Token = 'OK:100:15:V:26843545600' Reply-Message = 'Welcome to the ...' Service-Type = Authenticate-Only Proxy-State = 0x313638 Default-TTL = 19 Thu Jul 3 12:59:48 2014 : Debug: (0) proxy: request is no longer in proxy hash Thu Jul 3 12:59:48 2014 : Debug: (0) # Executing section post-proxy from file /etc/freeradius/radiusd.conf Thu Jul 3 12:59:48 2014 : Debug: (0) post-proxy { Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-proxy]: calling post_proxy_log (rlm_detail) for request 0 Thu Jul 3 12:59:48 2014 : Debug: /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-post_proxy_log Thu Jul 3 12:59:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 12:59:48 2014 : Debug: literal --> /var/log/freeradius/ Thu Jul 3 12:59:48 2014 : Debug: percent --> Y Thu Jul 3 12:59:48 2014 : Debug: literal --> / Thu Jul 3 12:59:48 2014 : Debug: percent --> Y Thu Jul 3 12:59:48 2014 : Debug: literal --> - Thu Jul 3 12:59:48 2014 : Debug: percent --> m Thu Jul 3 12:59:48 2014 : Debug: literal --> / Thu Jul 3 12:59:48 2014 : Debug: percent --> Y Thu Jul 3 12:59:48 2014 : Debug: literal --> - Thu Jul 3 12:59:48 2014 : Debug: percent --> m Thu Jul 3 12:59:48 2014 : Debug: literal --> - Thu Jul 3 12:59:48 2014 : Debug: percent --> d Thu Jul 3 12:59:48 2014 : Debug: literal --> -post_proxy_log Thu Jul 3 12:59:48 2014 : Debug: (0) post_proxy_log : EXPAND /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-post_proxy_log Thu Jul 3 12:59:48 2014 : Debug: (0) post_proxy_log : --> /var/log/freeradius/2014/2014-07/2014-07-03-post_proxy_log Thu Jul 3 12:59:48 2014 : Debug: (0) post_proxy_log : /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-post_proxy_log expands to /var/log/freeradius/2014/2014-07/2014-07-03-post_proxy_log Thu Jul 3 12:59:48 2014 : Debug: %t Thu Jul 3 12:59:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 12:59:48 2014 : Debug: percent --> t Thu Jul 3 12:59:48 2014 : Debug: (0) post_proxy_log : EXPAND %t Thu Jul 3 12:59:48 2014 : Debug: (0) post_proxy_log : --> Thu Jul 3 12:59:48 2014 Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-proxy]: returned from post_proxy_log (rlm_detail) for request 0 Thu Jul 3 12:59:48 2014 : Debug: (0) [post_proxy_log] = ok Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-proxy]: calling attr_filter.post-proxy (rlm_attr_filter) for request 0 Thu Jul 3 12:59:48 2014 : Debug: %{Realm} Thu Jul 3 12:59:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 12:59:48 2014 : Debug: attribute --> Realm Thu Jul 3 12:59:48 2014 : Debug: { Thu Jul 3 12:59:48 2014 : Debug: ref 2 Thu Jul 3 12:59:48 2014 : Debug: list 1 Thu Jul 3 12:59:48 2014 : Debug: tag -128 Thu Jul 3 12:59:48 2014 : Debug: } Thu Jul 3 12:59:48 2014 : Debug: (0) attr_filter.post-proxy : EXPAND %{Realm} Thu Jul 3 12:59:48 2014 : Debug: (0) attr_filter.post-proxy : --> news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-proxy]: returned from attr_filter.post-proxy (rlm_attr_filter) for request 0 Thu Jul 3 12:59:48 2014 : Debug: (0) [attr_filter.post-proxy] = noop Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-proxy]: calling perl (rlm_perl) for request 0 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Proxy-To-Realm = news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- NAS-Port-Type = Virtual Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Service-Type = Authenticate-Only Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Calling-Station-Id = c.d.49.113 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Called-Station-Id = a.b.8.42 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- User-Name = user@proxy.realm Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- User-Password = Ohs3dee2ei Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Realm = news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Realm = news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- NAS-IP-Address = 88.198.114.8 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- NAS-Port-Id = 1959 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Proxy-To-Realm = news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Acct-Authentic = RADIUS Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Acct-Delay-Time = 0 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- NAS-IP-Address = a.b.8.44 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- NAS-Port-Type = Virtual Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Service-Type = Authenticate-Only Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Calling-Station-Id = c.d.49.113 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Called-Station-Id = a.b.8.42 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- User-Name = user@proxy.realm Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- User-Password = Ohs3dee2ei Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- NAS-Port-Id = 1959 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Proxy-State = 0x313638 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Configuration-Token = OK:100:15:V:26843545600 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Reply-Message = Welcome to the CrystalWeb news server Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Service-Type = Authenticate-Only Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Proxy-State = 0x313638 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : <-- Default-TTL = 19 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> NAS-Port-Type = Virtual Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Service-Type = Authenticate-Only Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Called-Station-Id = a.b.8.42 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Calling-Station-Id = c.d.49.113 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> User-Name = user@proxy.realm Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> User-Password = Ohs3dee2ei Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Realm = news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Realm = news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> NAS-IP-Address = 88.198.114.8 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> NAS-Port-Id = 1959 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Proxy-To-Realm = news.crystalweb.com Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> NAS-Port-Type = Virtual Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Proxy-State = 0x313638 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Service-Type = Authenticate-Only Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Called-Station-Id = a.b.8.42 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Calling-Station-Id = c.d.49.113 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> User-Name = user@proxy.realm Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> User-Password = Ohs3dee2ei Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Acct-Authentic = RADIUS Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> NAS-IP-Address = a.b.8.44 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> NAS-Port-Id = 1959 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Acct-Delay-Time = 0 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Reply-Message = Welcome to the CrystalWeb news server Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Configuration-Token = OK:27F5709C-7588-369E-A215-7FFF12EA86A9:user@proxy.realm:V:26843545600:15:Welcome to the ... Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Default-TTL = 19 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Proxy-State = 0x313638 Thu Jul 3 12:59:48 2014 : Debug: (0) perl : --> Service-Type = Authenticate-Only Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-proxy]: returned from perl (rlm_perl) for request 0 Thu Jul 3 12:59:48 2014 : Debug: (0) [perl] = updated Thu Jul 3 12:59:48 2014 : Debug: (0) } # post-proxy = updated Thu Jul 3 12:59:48 2014 : Debug: (0) Found Auth-Type = Accept Thu Jul 3 12:59:48 2014 : Debug: (0) Auth-Type = Accept, accepting the user Thu Jul 3 12:59:48 2014 : Auth: (0) Login OK: [user@proxy.realm/Ohs3dee2ei] (from client NNTPCACHE02 port 0 cli c.d.49.113) Thu Jul 3 12:59:48 2014 : Debug: (0) # Executing section post-auth from file /etc/freeradius/radiusd.conf Thu Jul 3 12:59:48 2014 : Debug: (0) post-auth { Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-auth]: calling reply_log (rlm_detail) for request 0 Thu Jul 3 12:59:48 2014 : Debug: /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-reply_log Thu Jul 3 12:59:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 12:59:48 2014 : Debug: literal --> /var/log/freeradius/ Thu Jul 3 12:59:48 2014 : Debug: percent --> Y Thu Jul 3 12:59:48 2014 : Debug: literal --> / Thu Jul 3 12:59:48 2014 : Debug: percent --> Y Thu Jul 3 12:59:48 2014 : Debug: literal --> - Thu Jul 3 12:59:48 2014 : Debug: percent --> m Thu Jul 3 12:59:48 2014 : Debug: literal --> / Thu Jul 3 12:59:48 2014 : Debug: percent --> Y Thu Jul 3 12:59:48 2014 : Debug: literal --> - Thu Jul 3 12:59:48 2014 : Debug: percent --> m Thu Jul 3 12:59:48 2014 : Debug: literal --> - Thu Jul 3 12:59:48 2014 : Debug: percent --> d Thu Jul 3 12:59:48 2014 : Debug: literal --> -reply_log Thu Jul 3 12:59:48 2014 : Debug: (0) reply_log : EXPAND /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-reply_log Thu Jul 3 12:59:48 2014 : Debug: (0) reply_log : --> /var/log/freeradius/2014/2014-07/2014-07-03-reply_log Thu Jul 3 12:59:48 2014 : Debug: (0) reply_log : /var/log/freeradius/%Y/%Y-%m/%Y-%m-%d-reply_log expands to /var/log/freeradius/2014/2014-07/2014-07-03-reply_log Thu Jul 3 12:59:48 2014 : Debug: %t Thu Jul 3 12:59:48 2014 : Debug: Parsed xlat tree: Thu Jul 3 12:59:48 2014 : Debug: percent --> t Thu Jul 3 12:59:48 2014 : Debug: (0) reply_log : EXPAND %t Thu Jul 3 12:59:48 2014 : Debug: (0) reply_log : --> Thu Jul 3 12:59:48 2014 Thu Jul 3 12:59:48 2014 : Debug: (0) modsingle[post-auth]: returned from reply_log (rlm_detail) for request 0 Thu Jul 3 12:59:48 2014 : Debug: (0) [reply_log] = ok Thu Jul 3 12:59:48 2014 : Debug: (0) } # post-auth = ok Sending Access-Accept Id 168 from c.d.136.224:1812 to c.d.114.8:56059 Reply-Message = 'Welcome to the ...' Configuration-Token = 'OK:27F5709C-7588-369E-A215-7FFF12EA86A9:user@proxy.realm:V:26843545600:15:Welcome to the ...' Default-TTL = 19 Service-Type = Authenticate-Only Thu Jul 3 12:59:48 2014 : Debug: (0) Finished request The issue here is that the response received from the proxy server, is always the same. However on some instances, FR does process post_proxy, and on other cases (very intermittently), FR does not execute post_proxy... -- Chris.
On Thu, Jul 3, 2014 at 12:40 PM, Adam Bishop <Adam.Bishop@ja.net> wrote:
On 3 Jul 2014, at 11:15, Chris Knipe <savage@savage.za.org> wrote:
Thu Jul 3 11:55:49 2014 : Debug: (216) Found Auth-Type = Accept Thu Jul 3 11:55:49 2014 : Debug: (216) Auth-Type = Accept, accepting the user
This is more likely to be your issue - I believe the previous message is just informational.
Just to clarify, this is how 99.999% of the responses are handled from proxied requests: Received Access-Accept Id 211 from 127.0.0.1:18130 to 127.0.0.1:38667 length 107 Configuration-Token = 'OK:100:15:V:26843545600' Reply-Message = 'Welcome to the ...' Service-Type = Authenticate-Only Proxy-State = 0x313638 Default-TTL = 19 Thu Jul 3 12:59:48 2014 : Debug: (0) proxy: request is no longer in proxy hash Thu Jul 3 12:59:48 2014 : Debug: (0) # Executing section post-proxy It does receive an access accept from the proxy server, but it enters executes post_proxy. 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 Thu Jul 3 11:55:49 2014 : Debug: (216) Found Auth-Type = Accept Thu Jul 3 11:55:49 2014 : Debug: (216) Auth-Type = Accept, accepting the user Thu Jul 3 11:55:49 2014 : Auth: (216) Login OK: [user@proxy.realm/oozuL8poop] (from client CLIENT port 0 cli c.d.99.6) Thu Jul 3 11:55:49 2014 : Debug: (216) # Executing section post-auth The access accept received is the same (identical attributes, different values). Yet it doesn't execute post_proxy. Regards, Chris Knipe
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?
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.
On 03/07/14 13:38, Chris Knipe wrote:
It's definitely looking to be like something in FR, but I can't
I don't think there's any evidence for that yet. Maybe it is, maybe it isn't. You haven't explained the problem very well, at least not well enough for *me* to understand it.
read/understand C, so I have no idea where to even begin looking :-(
Well, I wouldn't start with the source code. I'd start with describing the problem, in terms of what you see on the wire.
I also tried to retransmit the packet in the event where this does
"You" tried to retransmit it? What does that mean? Are you proxying to another piece of software that you wrote?
This is example what radsecproxy returns on 7 unique access-requests, in quick succession (in quick succession I am basically saying that
Ok, but why would you post the radsecproxy log for that? Why not post the FreeRADIUS debug, which is something we actually know how to read on this mailing list?
On 03/07/14 14:10, Phil Mayers wrote:
On 03/07/14 13:38, Chris Knipe wrote:
It's definitely looking to be like something in FR, but I can't
The other thing you might do is try upgrading to 3.0.x HEAD.
Chris Knipe wrote:
For some reason, the response received does not make it through post_proxy. From what I can gather in the logs, FR complains:
Thu Jul 3 11:55:49 2014 : Debug: (216) proxy: request is no longer in proxy hash
That's the issue. The original request has timed out, and has been removed from the list of outstanding proxied packets. RADIUS isn't perfect. If a request takes too long, the client can give up on it. When the home server finally responds, the proxy discovers that there is no place for the response to go.
And then of course, never passes the request off through rlm_perl.
Because there's no reason to do that. In fact, the only thing that the proxy can do is to discard the response.
Can anyone shed some light on this in terms of how to fix this?
Make sure that the home server (and the proxy) process packets in a timely manner. Alan DeKok.
On Thu, Jul 3, 2014 at 2:11 PM, Alan DeKok <aland@deployingradius.com> wrote:
Chris Knipe wrote:
For some reason, the response received does not make it through post_proxy. From what I can gather in the logs, FR complains:
Thu Jul 3 11:55:49 2014 : Debug: (216) proxy: request is no longer in proxy hash
That's the issue. The original request has timed out, and has been removed from the list of outstanding proxied packets.
Ok. So what is the value of the timeout? Is it configurable, and if not, can we get a option to configure the timeout value? I don't see anything in proxy.conf, so my apologies if I missed this. All the requests also generally come back to me at the same time (as posted previously in the logs). Why is post_proxy then executed for one request, but not the other? They arrive back at FR at the same time, baring a few us... If you read the two responses posted to the packets, you will also see that both responses gave the proxy hash error, yet the one is still passed through post_proxy, and the other is not.. Unfortunately, again, the speed of light is a constant. I *cannot* process a proxied packet faster than what it takes to transmit the packet half way around the world - I get my responses generally sub 250ms. With all due respect Alan, and I say this with the UTMOST respect, Freeradius is being anal about timeouts, IF, this is indeed a timeout issue. The fact that the first response is sent through post_proxy, and the other responses received virtually at the same time is not... Well, yes. -- Regards, Chris Knipe
Chris Knipe wrote:
Ok. So what is the value of the timeout? Is it configurable, and if not, can we get a option to configure the timeout value? I don't see anything in proxy.conf, so my apologies if I missed this.
Then you deleted it. The configuration items are in the default proxy.conf file, with documentation. Also, the client may time out. You can't control that.
All the requests also generally come back to me at the same time (as posted previously in the logs). Why is post_proxy then executed for one request, but not the other? They arrive back at FR at the same time, baring a few us...
That's what the debug log is for.
If you read the two responses posted to the packets, you will also see that both responses gave the proxy hash error, yet the one is still passed through post_proxy, and the other is not..
That shouldn't happen. Please try the v3.0.x branch from git.
Unfortunately, again, the speed of light is a constant. I *cannot* process a proxied packet faster than what it takes to transmit the packet half way around the world - I get my responses generally sub 250ms.
That should be fine.
With all due respect Alan, and I say this with the UTMOST respect, Freeradius is being anal about timeouts, IF, this is indeed a timeout issue. The fact that the first response is sent through post_proxy, and the other responses received virtually at the same time is not...
It may be a bug. And yes, the server is SUPPOSED to be anal about timeouts. That's what timeouts are for. The alternative is to lie to people. "This timeout is for situation X, but if something happens after the timeout, that's OK, too" There is no reason in heaven or earth for FR to ignore documented timeouts. Alan DeKok.
On Thu, Jul 3, 2014 at 6:30 PM, Alan DeKok <aland@deployingradius.com> wrote:
Chris Knipe wrote:
Ok. So what is the value of the timeout? Is it configurable, and if not, can we get a option to configure the timeout value? I don't see anything in proxy.conf, so my apologies if I missed this.
Then you deleted it. The configuration items are in the default proxy.conf file, with documentation.
Also, the client may time out. You can't control that.
I looked at the -default- proxy.conf, that comes with FR3.0.3 which is what I am using. There isn't anything there in terms of request timeouts, just timeouts which controls when the proxy goes into a dead and/or zombie state - which is not what we are discussing here (again sorry if I missed it - a reference may thus be a good option). The proxy is never marked as dead, nor as a zombie, otherwise the natural thing for me WOULD HAVE been to look at and consider timeouts - that's why zombie / dead server configurations are there, isn't it? The client that sends the request, the FR server that does the proxing, as well as the FR server that receives the proxied request is under my control and neither one of them are timing out. Request: My Application -> FR Proxy -> FR Client, works fine FR Client -> FR Proxy -> My Application, and the FR Proxy then gets this weird behaviour when it decides on it's own when to, and when not to execute post_proxy.
All the requests also generally come back to me at the same time (as posted previously in the logs). Why is post_proxy then executed for one request, but not the other? They arrive back at FR at the same time, baring a few us...
That's what the debug log is for.
Please try and be helpful. I would appreciate it. I *DID* post the debug logs, both of a request that works, as well as a request that does not work. It is clear that for SOME reason, FR executes post_proxy in one request, and not in another. The attributes received in both packets are the same. This is NOT a configuration issue, nor a timeout issue IMHO. If I knew why FR is behaving like this, I would have fixed it. I am here however, to seek assistance to try and find out WHY this is happening.
If you read the two responses posted to the packets, you will also see that both responses gave the proxy hash error, yet the one is still passed through post_proxy, and the other is not..
That shouldn't happen. Please try the v3.0.x branch from git.
But it *IS* happening - that's the whole point of why I am here asking 'experts' as to WHY it is happening. I will however try the latest code and see whether the issue persist. I have since modified my rlm_perl application to use the authorize section to proxy requests to the parent radius server myself. In other words, I am no longer using FR's proxy implementation, but rather do it myself using perl. It's been running like that now for close to 12 hours, and I have not had *one* single Authentication error. There is *something* in FR's proxy code causing this issue, and it's related to high amounts of "concurrent" requests for the same username. I am sending the exact same packet via authorize, instead of the FR proxy modules, and it's working. It is thus NOT a timeout issue, it is NOT related to attributes received / not received, but rather, related to SOMETHING that the proxy modules does / does not do when a response is received. Again, as Phil said, it's more than likely too soon to call a bug, but it sure is leaning towards that and looking like it. Phil in terms of your questions, if I may rather just reply to everything in one email... Let's first get some background. The authentication and accounting is used for user authentication pertaining to NNTP server software - it is NOT NAS orientated. The NNTP Server is written by ourselves, and for local non proxied realms, authentication works without any problem whatsoever. Now, when a user connects, the user is entitled to x amount of concurrent threads to the NNTP server (typically 30). Generally, the client applications used by the customer connects all threads at the same time to the server. Hence, in a VERY short period of time (sub 10uS) 30 odd identical authentication requests are sent off to FR. The only attribute that is different in the authentication request, is the NAS-Port-Id, which we assign the value of the pid of the thread that the client has started on the NNTP servers. A typical authentication request will look like this: Fri Jul 4 00:30:25 2014 Packet-Type = Access-Request Called-Station-Id = 'a.b.8.42' Calling-Station-Id = 'c.d.96.24' NAS-IP-Address = a.b.240.36 NAS-Port-Type = Virtual NAS-Port-Id = '37713' Service-Type = Authenticate-Only User-Name = 'user@local.realm' User-Password = 'password' FR then accepts the packet, and almost exclusively relies on rlm_perl to authenticate the user. rlm_perl also configures various items such as rate limits and does session verification on a custom hardware load balancer. Typically, rlm_perl returns Auth-Type Accept (with reason), and a Configuration-Token attribute that gets sent back to the NNTP server. rlm_perl handles authentication generally under 0.010 seconds (measured from where FR passes the request to rlm_perl, until when rlm_perl executes the return back to FR). A typical response to an access-request looks like this (this is transmitted back to the NNTP software stack): Fri Jul 4 00:34:54 2014 Packet-Type = Access-Accept Configuration-Token = 'OK:37F46FA8-E538-497D-8B05-8D48FF2EC745:user@local.realm:T:1406584800:30:Welcome, user@local.realm (1/30)' This entire authentication process on local non-proxied realms works absolutely flawlessly. There is nothing wrong with this at all, it's fast, the custom code is highly optimized and we're extremely happy with this. When we now get to proxied requests, we have resellers that use our NNTP servers as well. Our NNTP servers sends the same authentication request to our FR server, the FR server sees that the realm needs to go to a proxy server, and then does the following: The packet passes through attr.filter, where we re-write a few attributes, as well as remove various unneeded attributes: my attr_filter.pre-proxy contains: DEFAULT Called-Station-Id == a.b.8.42, Calling-Station-Id =* ANY, NAS-IP-Address := a.b.8.44, NAS-Port-Id =* ANY, NAS-Port-Type == Virtual, Service-Type == Authenticate-Only, User-Name =* ANY, User-Password =* ANY, Proxy-State =* ANY FR then sends the proxy request off directly to the remote FR server (let's leave radsecproxy out of this for now. It was added as I thought the issue may have been caused by packet loss but the issue remains the same, whether the proxied request goes direct to the remote FR server or when it goes via radsecproxy). The auth request proxied generally looks like this: Thu Jul 3 00:02:31 2014 Packet-Type = Access-Request NAS-Port-Type = Virtual Service-Type = Authenticate-Only Calling-Station-Id = 'c.d.8.74' Called-Station-Id = 'a.b.8.42' User-Name = 'user@remote.realm' User-Password = 'aquiaP1eec' Realm = 'remote.realm' NAS-IP-Address = a.b.240.36 Message-Authenticator := 0x00 Proxy-State = 0x3438 All the authentication requests transmitted, DOES make it to the remote FR server, and the remote FR server is a STOCK STANDARD 2.1.12 install that comes with Ubuntu. All usernames & passwords in the users file. There's NOTHING changed, and NOTHING special. A stock standard install with just the parent FR server sending it requests configured in clients.conf. The server obviously responds virtually instantly with an access accept, as such: Thu Jul 3 02:16:50 2014 Packet-Type = Access-Accept Configuration-Token = 'OK:100:15:V:26843545600' Reply-Message = 'Welcome' Service-Type = Authenticate-Only Proxy-State = 0x3339 Now, THIS is where I think the issue is coming in. The accept packet from the remote server, will *always* be identical. The Configuration-Token returned will change over time, but for all initial 30 or 40 "simultaneous" authentication requests, the same Configuration-Token is returned. The main FR server thus sees 30 identical packets, to 30 different requests. What happens now, is that FR will take the 1st response it receives, and will push that through post_proxy. The remaining responses for some reason goes directly to post_auth, instead of what should be, post_proxy. The problem ONLY presents itself in requests sent to proxied servers, and it ONLY presents itself when there is a high amount of "concurrent" requests... Say, more than 10 within a very short period of time. This is essentially what I tried to show by posting the radsecproxy log, together with the log from my perl module. The Configuration-Token returned by the proxied server, and the Configuration-Token expected by our NNTP servers has different formats. The idea thus, is that the FR server *must* execute post_proxy for each and every response it receives from a proxied request, so that the sessions can be configured / confirmed on the load balancers, before the Configuration-Token is then re-written before being transmitted back to the application. Again, for intermediate requests, this works absolutely fine, and FR executes post_proxy as we all expect. This behaviour is *only* seen on a large amount of concurrent requests, and I suspect, is triggered when identical auth accepts are returned from the proxy server. This is somewhat irrelevant though, as my post_proxy rlm_perl module is useless seeing that post_proxy section is not executed in it's *entirety* when FR does this, not even post_proxy_log is called... -- Chris. -- Regards, Chris Knipe
Chris Knipe wrote:
I looked at the -default- proxy.conf, that comes with FR3.0.3 which is what I am using. There isn't anything there in terms of request timeouts, just timeouts which controls when the proxy goes into a dead and/or zombie state - which is not what we are discussing here (again sorry if I missed it - a reference may thus be a good option). The proxy is never marked as dead, nor as a zombie, otherwise the natural thing for me WOULD HAVE been to look at and consider timeouts - that's why zombie / dead server configurations are there, isn't it?
The proxy.conf file has a "response_window" configuration item. It controls how long a proxied request is marked "outstanding" before the proxy marks it as failed.
The client that sends the request, the FR server that does the proxing, as well as the FR server that receives the proxied request is under my control and neither one of them are timing out.
The "not in proxy list" message indicates that (a) it's timing out, or (b) there's a bug.
Please try and be helpful. I would appreciate it.
I can unsubscribe you from the list if you don't like my help.
I *DID* post the debug logs, both of a request that works, as well as a request that does not work.
You posted PART of the debug log. If you've been on the list for any length of time, you will see this behavior as a REPEATED problem. People post 3-4 lines, and expect some kind of magical solution. They then get cranky when they're told they need to read (or post) the FULL debug output. i.e. what's happening now.
It is clear that for SOME reason, FR executes post_proxy in one request, and not in another.
Saying that repeatedly is annoying. That's another one of my pet peeves. People who ask questions, and say the same thing over and over and over and over. We get it. There's a problem. Now stop complaining about the problem, and work towards a solution.
The attributes received in both packets are the same. This is NOT a configuration issue, nor a timeout issue IMHO. If I knew why FR is behaving like this, I would have fixed it. I am here however, to seek assistance to try and find out WHY this is happening.
You really don't get it. We are TRYING to help you. Your response is to wave your hands and say THINGS ARE GOING WRONG. Well... yes. We're aware of that.
That shouldn't happen. Please try the v3.0.x branch from git.
But it *IS* happening - that's the whole point of why I am here asking 'experts' as to WHY it is happening.
<sigh> We're not miracle workers. When you post ~10 lines of the debug output and a description of what's going wrong, I can't magically say "Oh yes, it's a bug in file X line Y". Sometimes I can do that. But in this case I can't. Now stop demanding a magical solution, and *cooperate*.
I will however try the latest code and see whether the issue persist.
That's really the point here.
I have since modified my rlm_perl application to use the authorize section to proxy requests to the parent radius server myself. In other words, I am no longer using FR's proxy implementation, but rather do it myself using perl. It's been running like that now for close to 12 hours, and I have not had *one* single Authentication error. There is *something* in FR's proxy code causing this issue, and it's related to high amounts of "concurrent" requests for the same username.
So... try the code from v3.0.x branch in git.
I am sending the exact same packet via authorize, instead of the FR proxy modules, and it's working. It is thus NOT a timeout issue, it is NOT related to attributes received / not received, but rather, related to SOMETHING that the proxy modules does / does not do when a response is received.
No. You are guessing as to how the server works. Don't do that.
Again, as Phil said, it's more than likely too soon to call a bug, but it sure is leaning towards that and looking like it.
I may be an idiot, but the server is *supposed* to proxy requests properly. If it doesn't that sure sounds like a bug.
Let's first get some background.
Most of that doesn't matter. i.e. your long description is looking at entirely the wrong thing. The packet contents don't matter. Whether the client is an NNTP server, NAS, PAM client, or magic pixies doesn't matter. What the home is running doesn't matter. What the home server is doing doesn't matter.
Now, THIS is where I think the issue is coming in. The accept packet from the remote server, will *always* be identical.
No. That is NOT how RADIUS works.
The Configuration-Token returned will change over time, but for all initial 30 or 40 "simultaneous" authentication requests, the same Configuration-Token is returned. The main FR server thus sees 30 identical packets, to 30 different requests.
No. That is NOT how RADIUS works.
What happens now, is that FR will take the 1st response it receives, and will push that through post_proxy. The remaining responses for some reason goes directly to post_auth, instead of what should be, post_proxy. The problem ONLY presents itself in requests sent to proxied servers, and it ONLY presents itself when there is a high amount of "concurrent" requests... Say, more than 10 within a very short period of time. This is essentially what I tried to show by posting the radsecproxy log, together with the log from my perl module.
No. That is NOT how RADIUS works. Much of your time is spent on completely useless things. Like going down the wrong path, repeating the same things over and over, and arguing with me. Stop it. If you want to get the problem fixed, you need to work with others. It may be a bug in v3.0.3. But I don't see that when I do my tests. If you try the v3.0.x branch from git, all known bugs are fixed. But if the v3.0.x branch has the same behavior, you need to provide the FULL debug output. And work from the assumption that we have a little bit of a clue about how FreeRADIUS works. Alan DeKok.
Hi,
The packet contents don't matter. Whether the client is an NNTP server, NAS, PAM client, or magic pixies doesn't matter. What the home is running doesn't matter. What the home server is doing doesn't matter.
<SNIP> has that been fixed in HEAD then? Last I checked my magic pixies were unable to work with FR ;-) alan
participants (5)
-
A.L.M.Buxey＠lboro.ac.uk -
Adam Bishop -
Alan DeKok -
Chris Knipe -
Phil Mayers