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.