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

3 Jul 2014

      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