intermittent auth issue (proxy: request is no longer in proxy hash)
Chris Knipe
savage at savage.za.org
Thu Jul 3 13:04:25 CEST 2014
On Thu, Jul 3, 2014 at 12:40 PM, Adam Bishop <Adam.Bishop at ja.net> wrote:
> On 3 Jul 2014, at 11:15, Chris Knipe <savage at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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.
More information about the Freeradius-Users
mailing list