RE: attrs.filter differences between FR 2.2.0 and FR 3

12 Nov 2013

      Hi Alan,
...
...
Also on a completely different note, I've noticed that sometimes (only so far when auth'ing against our test @eduroam.ac.uk account, not locally) I get about thousands & thousands of these, until eventually it cleans up...
...
....well thats 'interesting'. I would suggest that you run in full debug mode when performing an authentication with that test account to see what is going on at a deeper level - because If you get back an Access-Accept packet then theres no more to receive....your server should not need to be waiting for more responses...
but if this is part of the 'lets get your RADIUS cert' conversation then it looks like v3 is either doing some extra things...or is just being more verbose than 2.x (and thousands of such things being logged would be annoying)...
I've just tried to use raddebug to capture the debug, but I might have unearthed another problem.
Once raddebug times out after 60 second it kills radiusd.

Below is the debug output, auth fails, and looks like there might be a duplicate proxies request to the NRPS.

Thanks,
Jezz.

rad_recv: Access-Request packet from host 123.44.55.66 port 37026, id=0, length=162
User-Name = 'swansea.ac.uk@eduroam.ac.uk'
Calling-Station-Id = '02-00-00-00-00-01'
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Connect-Info = 'CONNECT 11Mbps 802.11b'
NAS-IP-Address = 137.44.0.2
EAP-Message = 0x02000020017377616e7365612e61632e756b40656475726f616d2e61632e756b
Message-Authenticator = 0x999c405516f2b7db33a613f6c1a41074
Tue Nov 12 13:13:06 2013 : Debug: (160) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (160)   authorize {
Tue Nov 12 13:13:06 2013 : Debug: (160)   filter_username filter_username {
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (User-Name =~ /@.*@/ ) 
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (User-Name =~ /@.*@/ )  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))  
Tue Nov 12 13:13:06 2013 : Debug: (160) %{0}: Inserting new value "@"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{1}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{2}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{3}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{0}: Inserting new value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{1}: Inserting new value "eduroam.ac"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{2}: Inserting new value "uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{3}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (User-Name =~ /\\.$/)  
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (User-Name =~ /\\.$/)   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (User-Name =~ /@\\./)  
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (User-Name =~ /@\\./)   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)   } # filter_username filter_username = notfound
Tue Nov 12 13:13:06 2013 : Debug: (160)   ? if ("%{reply:Reply-Message}" !~ /MAC-AUTH/) 
Tue Nov 12 13:13:06 2013 : Debug: %{reply:Reply-Message}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Reply-Message
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 2
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{reply:Reply-Message}" -> ''
Tue Nov 12 13:13:06 2013 : Debug: (160)   ? if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (160)   if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  {
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/) 
Tue Nov 12 13:13:06 2013 : Debug: %{User-Name}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: User-Name
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{User-Name}" -> 'swansea.ac.uk@eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (160) %{0}: Inserting new value "swansea.ac.uk@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{1}: Inserting new value "swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{2}: Inserting new value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{3}: Inserting new value "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (160)    if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  {
Tue Nov 12 13:13:06 2013 : Debug: (160)     ? if ("%{3}") 
Tue Nov 12 13:13:06 2013 : Debug: %{3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: regex-var: 3
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{3}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (160)     ? if ("%{3}")  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (160)     if ("%{3}")  {
Tue Nov 12 13:13:06 2013 : Debug: (160)      ? if ((User-Name =~ /([a-z0-9_\.\-]+)@(swan|colegcymraeg|swansea|abertawe|test\.colegcymraeg|test\.swansea|test\.abertawe)\.ac\.uk/i) || (User-Name =~ /@(swan|colegcymraeg|swansea|abertawe)\.ac\.uk/i)) 
Tue Nov 12 13:13:06 2013 : Debug: (160)      ? if ((User-Name =~ /([a-z0-9_\.\-]+)@(swan|colegcymraeg|swansea|abertawe|test\.colegcymraeg|test\.swansea|test\.abertawe)\.ac\.uk/i) || (User-Name =~ /@(swan|colegcymraeg|swansea|abertawe)\.ac\.uk/i))  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)      else else {
Tue Nov 12 13:13:06 2013 : Debug: (160)       ? if ((User-Name =~ /3gppnetwork\.org/i) || (User-Name =~ /\.acuk$/i) || (User-Name =~ /\.aaac\.uk\/$/i)) 
Tue Nov 12 13:13:06 2013 : Debug: (160)       ? if ((User-Name =~ /3gppnetwork\.org/i) || (User-Name =~ /\.acuk$/i) || (User-Name =~ /\.aaac\.uk\/$/i))  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)       else else {
Tue Nov 12 13:13:06 2013 : Debug: (160)        update request {
Tue Nov 12 13:13:06 2013 : Debug: %{3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: regex-var: 3
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{3}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (160) Stripped-User-Domain = "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: FROM 1 TO 8 MAX 9
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: Examining Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: APPENDING Stripped-User-Domain FROM 0 TO 8
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: TO in 8 out 9
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[7] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[8] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (160)        } # update request = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)       } # else else = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)      } # else else = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)     } # if ("%{3}")  = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)      ... skipping else for request 160: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (160)    } # if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)     ... skipping else for request 160: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./)) 
Tue Nov 12 13:13:06 2013 : Debug: %{NAS-IP-Address}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{NAS-IP-Address}" -> '137.44.0.2'
Tue Nov 12 13:13:06 2013 : Debug: (160) %{0}: Inserting new value "137.44."
Tue Nov 12 13:13:06 2013 : Debug: (160) %{1}: Clearing old value "swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{2}: Clearing old value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{3}: Clearing old value "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (160)    if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  {
Tue Nov 12 13:13:06 2013 : Debug: (160)     switch %{Stripped-User-Domain} {
Tue Nov 12 13:13:06 2013 : Debug: %{Stripped-User-Domain}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{Stripped-User-Domain}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (160)     switch %{Stripped-User-Domain} {
Tue Nov 12 13:13:06 2013 : Debug: (160)      case (null) {
Tue Nov 12 13:13:06 2013 : Debug: (160)       update control {
Tue Nov 12 13:13:06 2013 : Debug: (160) Proxy-To-Realm := 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: FROM 1 TO 0 MAX 1
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: Examining Proxy-To-Realm
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: APPENDING Proxy-To-Realm FROM 0 TO 0
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: TO in 0 out 1
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[0] = Proxy-To-Realm
Tue Nov 12 13:13:06 2013 : Debug: (160)       } # update control = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)       update request {
Tue Nov 12 13:13:06 2013 : Debug: (160) Realm := 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: FROM 1 TO 9 MAX 10
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: Examining Realm
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: APPENDING Realm FROM 0 TO 9
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: TO in 9 out 10
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[7] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[8] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[9] = Realm
Tue Nov 12 13:13:06 2013 : Debug: (160) Operator-Name := "1swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: FROM 1 TO 10 MAX 11
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: Examining Operator-Name
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: APPENDING Operator-Name FROM 0 TO 10
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: TO in 10 out 11
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[7] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[8] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[9] = Realm
Tue Nov 12 13:13:06 2013 : Debug: (160) ::: to[10] = Operator-Name
Tue Nov 12 13:13:06 2013 : Debug: (160)       } # update request = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)      } # case  = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)     } # switch %{Stripped-User-Domain} = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)    } # if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)     ... skipping else for request 160: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if ("%{Realm}" != "jrs") 
Tue Nov 12 13:13:06 2013 : Debug: jrs
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "jrs" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: %{Realm}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Realm
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{Realm}" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (160)    ? if ("%{Realm}" != "jrs")  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)   } # if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [preprocess] = ok
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling auth_log (rlm_detail) for request 160
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/auth-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (160) auth_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/auth-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (160) auth_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/auth-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (160) auth_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from auth_log (rlm_detail) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [auth_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling chap (rlm_chap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from chap (rlm_chap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [chap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling mschap (rlm_mschap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from mschap (rlm_mschap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [mschap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling suffix (rlm_realm) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160) suffix : Request already has destination realm set.  Ignoring.
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from suffix (rlm_realm) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [suffix] = ok
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling ntdomain (rlm_realm) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160) ntdomain : Request already has destination realm set.  Ignoring.
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from ntdomain (rlm_realm) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [ntdomain] = ok
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling eap (rlm_eap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160) eap : Request is supposed to be proxied to Realm jrs. Not doing EAP.
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from eap (rlm_eap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [eap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)   ? if (("%{NAS-IP-Address}" =~ /137.44.47.2[0-9]+[0-9]+/) && ("%{control:Tmp-String-2}" =~ /local|virus|banned|accomban/i))  
Tue Nov 12 13:13:06 2013 : Debug: %{NAS-IP-Address}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{NAS-IP-Address}" -> '137.44.0.2'
Tue Nov 12 13:13:06 2013 : Debug: (160)   ? if (("%{NAS-IP-Address}" =~ /137.44.47.2[0-9]+[0-9]+/) && ("%{control:Tmp-String-2}" =~ /local|virus|banned|accomban/i))   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)   ? if ("%{control:Tmp-String-3}" == "guest") 
Tue Nov 12 13:13:06 2013 : Debug: guest
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: 'guest'
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "guest" -> 'guest'
Tue Nov 12 13:13:06 2013 : Debug: %{control:Tmp-String-3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Tmp-String-3
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 3
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) expand: "%{control:Tmp-String-3}" -> ''
Tue Nov 12 13:13:06 2013 : Debug: (160)   ? if ("%{control:Tmp-String-3}" == "guest")  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling logintime (rlm_logintime) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from logintime (rlm_logintime) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [logintime] = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: calling pap (rlm_pap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[authorize]: returned from pap (rlm_pap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [pap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)  } #  authorize = ok
Tue Nov 12 13:13:06 2013 : Debug: (160) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (160)   pre-proxy {
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[pre-proxy]: calling attr_filter.pre-proxy (rlm_attr_filter) for request 160
Tue Nov 12 13:13:06 2013 : Debug: %{Realm}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Realm
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (160) attr_filter.pre-proxy : expand: "%{Realm}" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (160) attr_filter.pre-proxy : Matched entry DEFAULT at line 50
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[pre-proxy]: returned from attr_filter.pre-proxy (rlm_attr_filter) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [attr_filter.pre-proxy] = updated
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail) for request 160
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/pre-proxy-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (160) pre_proxy_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/pre-proxy-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (160) pre_proxy_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/pre-proxy-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (160) pre_proxy_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [pre_proxy_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (160)  } #  pre-proxy = updated
Tue Nov 12 13:13:06 2013 : Debug: (160) proxy: Trying to allocate ID (0/2)
Tue Nov 12 13:13:06 2013 : Debug: (160) proxy: request is now in proxy hash
Tue Nov 12 13:13:06 2013 : Debug: (160)  proxy: allocating destination 194.83.56.233 port 1812 - Id 40
Tue Nov 12 13:13:06 2013 : Debug: (160) Proxying request to home server 194.83.56.233 port 1812
Sending Access-Request of id 40 from 0.0.0.0 port 1814 to 194.83.56.233 port 1812
User-Name = 'swansea.ac.uk@eduroam.ac.uk'
NAS-IP-Address = 137.44.0.2
EAP-Message = 0x02000020017377616e7365612e61632e756b40656475726f616d2e61632e756b
Message-Authenticator = 0x999c405516f2b7db33a613f6c1a41074
Proxy-State = 0x30
rad_recv: Access-Challenge packet from host 194.83.56.233 port 1812, id=40, length=67
EAP-Message = 0x010100061920
Message-Authenticator = 0x19f9109f3a86b45877b9fcad0eab74d5
State = 0x6ee887f26ee99ed95ce9a084cc329b80
Proxy-State = 0x30
Tue Nov 12 13:13:06 2013 : Debug: (160) proxy: request is no longer in proxy hash
Tue Nov 12 13:13:06 2013 : Debug: (160) # Executing section post-proxy from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (160)   post-proxy {
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[post-proxy]: calling post_proxy_log (rlm_detail) for request 160
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/post-proxy-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (160) post_proxy_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/post-proxy-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (160) post_proxy_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/post-proxy-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (160) post_proxy_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[post-proxy]: returned from post_proxy_log (rlm_detail) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [post_proxy_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[post-proxy]: calling eap (rlm_eap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160) eap : No pre-existing handler found
Tue Nov 12 13:13:06 2013 : Debug: (160)   modsingle[post-proxy]: returned from eap (rlm_eap) for request 160
Tue Nov 12 13:13:06 2013 : Debug: (160)   [eap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (160)  } #  post-proxy = ok
Sending Access-Challenge of id 0 from 137.44.1.53 port 1812 to 123.44.55.66 port 37026
EAP-Message = 0x010100061920
Message-Authenticator = 0x19f9109f3a86b45877b9fcad0eab74d5
State = 0x6ee887f26ee99ed95ce9a084cc329b80
Tue Nov 12 13:13:06 2013 : Debug: (160) Finished request 160.
rad_recv: Access-Request packet from host 123.44.55.66 port 37026, id=1, length=270
User-Name = 'swansea.ac.uk@eduroam.ac.uk'
Calling-Station-Id = '02-00-00-00-00-01'
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Connect-Info = 'CONNECT 11Mbps 802.11b'
NAS-IP-Address = 137.44.0.2
EAP-Message = 0x0201007a198000000070160301006b01000067030152822962e4231c9e771215d6a36955588c3bc27a2c7d5bbc6a550a4f89ae664300003a00390038008800870035008400160013000a00330032009a009900450044002f00960041000500040015001200090014001100080006000300ff0100000400230000
State = 0x6ee887f26ee99ed95ce9a084cc329b80
Message-Authenticator = 0x3e189ee0ed4f4d44ecc15b259e54245c
Tue Nov 12 13:13:06 2013 : Debug: (161) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (161)   authorize {
Tue Nov 12 13:13:06 2013 : Debug: (161)   filter_username filter_username {
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (User-Name =~ /@.*@/ ) 
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (User-Name =~ /@.*@/ )  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))  
Tue Nov 12 13:13:06 2013 : Debug: (161) %{0}: Inserting new value "@"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{1}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{2}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{3}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{0}: Inserting new value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{1}: Inserting new value "eduroam.ac"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{2}: Inserting new value "uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{3}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (User-Name =~ /\\.$/)  
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (User-Name =~ /\\.$/)   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (User-Name =~ /@\\./)  
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (User-Name =~ /@\\./)   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)   } # filter_username filter_username = notfound
Tue Nov 12 13:13:06 2013 : Debug: (161)   ? if ("%{reply:Reply-Message}" !~ /MAC-AUTH/) 
Tue Nov 12 13:13:06 2013 : Debug: %{reply:Reply-Message}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Reply-Message
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 2
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{reply:Reply-Message}" -> ''
Tue Nov 12 13:13:06 2013 : Debug: (161)   ? if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (161)   if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  {
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/) 
Tue Nov 12 13:13:06 2013 : Debug: %{User-Name}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: User-Name
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{User-Name}" -> 'swansea.ac.uk@eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (161) %{0}: Inserting new value "swansea.ac.uk@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{1}: Inserting new value "swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{2}: Inserting new value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{3}: Inserting new value "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (161)    if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  {
Tue Nov 12 13:13:06 2013 : Debug: (161)     ? if ("%{3}") 
Tue Nov 12 13:13:06 2013 : Debug: %{3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: regex-var: 3
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{3}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (161)     ? if ("%{3}")  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (161)     if ("%{3}")  {
Tue Nov 12 13:13:06 2013 : Debug: (161)      ? if ((User-Name =~ /([a-z0-9_\.\-]+)@(swan|colegcymraeg|swansea|abertawe|test\.colegcymraeg|test\.swansea|test\.abertawe)\.ac\.uk/i) || (User-Name =~ /@(swan|colegcymraeg|swansea|abertawe)\.ac\.uk/i)) 
Tue Nov 12 13:13:06 2013 : Debug: (161)      ? if ((User-Name =~ /([a-z0-9_\.\-]+)@(swan|colegcymraeg|swansea|abertawe|test\.colegcymraeg|test\.swansea|test\.abertawe)\.ac\.uk/i) || (User-Name =~ /@(swan|colegcymraeg|swansea|abertawe)\.ac\.uk/i))  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)      else else {
Tue Nov 12 13:13:06 2013 : Debug: (161)       ? if ((User-Name =~ /3gppnetwork\.org/i) || (User-Name =~ /\.acuk$/i) || (User-Name =~ /\.aaac\.uk\/$/i)) 
Tue Nov 12 13:13:06 2013 : Debug: (161)       ? if ((User-Name =~ /3gppnetwork\.org/i) || (User-Name =~ /\.acuk$/i) || (User-Name =~ /\.aaac\.uk\/$/i))  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)       else else {
Tue Nov 12 13:13:06 2013 : Debug: (161)        update request {
Tue Nov 12 13:13:06 2013 : Debug: %{3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: regex-var: 3
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{3}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (161) Stripped-User-Domain = "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: FROM 1 TO 9 MAX 10
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: Examining Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: APPENDING Stripped-User-Domain FROM 0 TO 9
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: TO in 9 out 10
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[7] = State
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[8] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[9] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (161)        } # update request = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)       } # else else = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)      } # else else = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)     } # if ("%{3}")  = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)      ... skipping else for request 161: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (161)    } # if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)     ... skipping else for request 161: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./)) 
Tue Nov 12 13:13:06 2013 : Debug: %{NAS-IP-Address}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{NAS-IP-Address}" -> '137.44.0.2'
Tue Nov 12 13:13:06 2013 : Debug: (161) %{0}: Inserting new value "137.44."
Tue Nov 12 13:13:06 2013 : Debug: (161) %{1}: Clearing old value "swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{2}: Clearing old value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{3}: Clearing old value "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (161)    if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  {
Tue Nov 12 13:13:06 2013 : Debug: (161)     switch %{Stripped-User-Domain} {
Tue Nov 12 13:13:06 2013 : Debug: %{Stripped-User-Domain}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{Stripped-User-Domain}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (161)     switch %{Stripped-User-Domain} {
Tue Nov 12 13:13:06 2013 : Debug: (161)      case (null) {
Tue Nov 12 13:13:06 2013 : Debug: (161)       update control {
Tue Nov 12 13:13:06 2013 : Debug: (161) Proxy-To-Realm := 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: FROM 1 TO 0 MAX 1
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: Examining Proxy-To-Realm
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: APPENDING Proxy-To-Realm FROM 0 TO 0
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: TO in 0 out 1
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[0] = Proxy-To-Realm
Tue Nov 12 13:13:06 2013 : Debug: (161)       } # update control = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)       update request {
Tue Nov 12 13:13:06 2013 : Debug: (161) Realm := 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: FROM 1 TO 10 MAX 11
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: Examining Realm
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: APPENDING Realm FROM 0 TO 10
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: TO in 10 out 11
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[7] = State
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[8] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[9] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[10] = Realm
Tue Nov 12 13:13:06 2013 : Debug: (161) Operator-Name := "1swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: FROM 1 TO 11 MAX 12
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: Examining Operator-Name
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: APPENDING Operator-Name FROM 0 TO 11
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: TO in 11 out 12
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[7] = State
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[8] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[9] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[10] = Realm
Tue Nov 12 13:13:06 2013 : Debug: (161) ::: to[11] = Operator-Name
Tue Nov 12 13:13:06 2013 : Debug: (161)       } # update request = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)      } # case  = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)     } # switch %{Stripped-User-Domain} = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)    } # if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)     ... skipping else for request 161: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if ("%{Realm}" != "jrs") 
Tue Nov 12 13:13:06 2013 : Debug: jrs
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "jrs" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: %{Realm}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Realm
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{Realm}" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (161)    ? if ("%{Realm}" != "jrs")  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)   } # if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [preprocess] = ok
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling auth_log (rlm_detail) for request 161
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/auth-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (161) auth_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/auth-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (161) auth_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/auth-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (161) auth_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from auth_log (rlm_detail) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [auth_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling chap (rlm_chap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from chap (rlm_chap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [chap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling mschap (rlm_mschap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from mschap (rlm_mschap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [mschap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling suffix (rlm_realm) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161) suffix : Request already has destination realm set.  Ignoring.
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from suffix (rlm_realm) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [suffix] = ok
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling ntdomain (rlm_realm) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161) ntdomain : Request already has destination realm set.  Ignoring.
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from ntdomain (rlm_realm) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [ntdomain] = ok
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling eap (rlm_eap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161) eap : Request is supposed to be proxied to Realm jrs. Not doing EAP.
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from eap (rlm_eap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [eap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)   ? if (("%{NAS-IP-Address}" =~ /137.44.47.2[0-9]+[0-9]+/) && ("%{control:Tmp-String-2}" =~ /local|virus|banned|accomban/i))  
Tue Nov 12 13:13:06 2013 : Debug: %{NAS-IP-Address}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{NAS-IP-Address}" -> '137.44.0.2'
Tue Nov 12 13:13:06 2013 : Debug: (161)   ? if (("%{NAS-IP-Address}" =~ /137.44.47.2[0-9]+[0-9]+/) && ("%{control:Tmp-String-2}" =~ /local|virus|banned|accomban/i))   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)   ? if ("%{control:Tmp-String-3}" == "guest") 
Tue Nov 12 13:13:06 2013 : Debug: guest
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: 'guest'
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "guest" -> 'guest'
Tue Nov 12 13:13:06 2013 : Debug: %{control:Tmp-String-3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Tmp-String-3
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 3
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) expand: "%{control:Tmp-String-3}" -> ''
Tue Nov 12 13:13:06 2013 : Debug: (161)   ? if ("%{control:Tmp-String-3}" == "guest")  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling logintime (rlm_logintime) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from logintime (rlm_logintime) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [logintime] = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: calling pap (rlm_pap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[authorize]: returned from pap (rlm_pap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [pap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)  } #  authorize = ok
Tue Nov 12 13:13:06 2013 : Debug: (161) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (161)   pre-proxy {
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[pre-proxy]: calling attr_filter.pre-proxy (rlm_attr_filter) for request 161
Tue Nov 12 13:13:06 2013 : Debug: %{Realm}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Realm
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (161) attr_filter.pre-proxy : expand: "%{Realm}" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (161) attr_filter.pre-proxy : Matched entry DEFAULT at line 50
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[pre-proxy]: returned from attr_filter.pre-proxy (rlm_attr_filter) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [attr_filter.pre-proxy] = updated
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail) for request 161
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/pre-proxy-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (161) pre_proxy_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/pre-proxy-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (161) pre_proxy_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/pre-proxy-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (161) pre_proxy_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [pre_proxy_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (161)  } #  pre-proxy = updated
Tue Nov 12 13:13:06 2013 : Debug: (161) proxy: Trying to allocate ID (0/2)
Tue Nov 12 13:13:06 2013 : Debug: (161) proxy: request is now in proxy hash
Tue Nov 12 13:13:06 2013 : Debug: (161)  proxy: allocating destination 194.83.56.233 port 1812 - Id 10
Tue Nov 12 13:13:06 2013 : Debug: (161) Proxying request to home server 194.83.56.233 port 1812
Sending Access-Request of id 10 from 0.0.0.0 port 1814 to 194.83.56.233 port 1812
User-Name = 'swansea.ac.uk@eduroam.ac.uk'
NAS-IP-Address = 137.44.0.2
EAP-Message = 0x0201007a198000000070160301006b01000067030152822962e4231c9e771215d6a36955588c3bc27a2c7d5bbc6a550a4f89ae664300003a00390038008800870035008400160013000a00330032009a009900450044002f00960041000500040015001200090014001100080006000300ff0100000400230000
State = 0x6ee887f26ee99ed95ce9a084cc329b80
Message-Authenticator = 0x3e189ee0ed4f4d44ecc15b259e54245c
Proxy-State = 0x31
Tue Nov 12 13:13:06 2013 : Debug: (139) Cleaning up request packet ID 9 with timestamp +31
Tue Nov 12 13:13:06 2013 : Debug: Waking up in 0.3 seconds.
rad_recv: Access-Challenge packet from host 194.83.56.233 port 1812, id=10, length=1093
EAP-Message = 
Message-Authenticator = 0x994dd1a59a24eb48a85ea6b7548afcf6
State = 0x6ee887f26fea9ed95ce9a084cc329b80
Proxy-State = 0x31
Tue Nov 12 13:13:06 2013 : Debug: (161) proxy: request is no longer in proxy hash
Tue Nov 12 13:13:06 2013 : Debug: (161) # Executing section post-proxy from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (161)   post-proxy {
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[post-proxy]: calling post_proxy_log (rlm_detail) for request 161
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/post-proxy-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (161) post_proxy_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/post-proxy-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (161) post_proxy_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/post-proxy-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (161) post_proxy_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[post-proxy]: returned from post_proxy_log (rlm_detail) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [post_proxy_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[post-proxy]: calling eap (rlm_eap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161) eap : No pre-existing handler found
Tue Nov 12 13:13:06 2013 : Debug: (161)   modsingle[post-proxy]: returned from eap (rlm_eap) for request 161
Tue Nov 12 13:13:06 2013 : Debug: (161)   [eap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (161)  } #  post-proxy = ok
Sending Access-Challenge of id 1 from 137.44.1.53 port 1812 to 123.44.55.66 port 37026
EAP-Message = 
Message-Authenticator = 0x994dd1a59a24eb48a85ea6b7548afcf6
State = 0x6ee887f26fea9ed95ce9a084cc329b80
Tue Nov 12 13:13:06 2013 : Debug: (161) Finished request 161.
Tue Nov 12 13:13:06 2013 : Debug: Waking up in 0.2 seconds.
rad_recv: Access-Request packet from host 123.44.55.66 port 37026, id=2, length=154
User-Name = 'swansea.ac.uk@eduroam.ac.uk'
Calling-Station-Id = '02-00-00-00-00-01'
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Connect-Info = 'CONNECT 11Mbps 802.11b'
NAS-IP-Address = 137.44.0.2
EAP-Message = 0x020200061900
State = 0x6ee887f26fea9ed95ce9a084cc329b80
Message-Authenticator = 0x81d5ddca52123616fc193cd8a980b775
Tue Nov 12 13:13:06 2013 : Debug: (162) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (162)   authorize {
Tue Nov 12 13:13:06 2013 : Debug: (162)   filter_username filter_username {
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (User-Name =~ /@.*@/ ) 
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (User-Name =~ /@.*@/ )  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))  
Tue Nov 12 13:13:06 2013 : Debug: (162) %{0}: Inserting new value "@"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{1}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{2}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{3}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{0}: Inserting new value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{1}: Inserting new value "eduroam.ac"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{2}: Inserting new value "uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{3}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (User-Name =~ /\\.$/)  
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (User-Name =~ /\\.$/)   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (User-Name =~ /@\\./)  
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (User-Name =~ /@\\./)   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)   } # filter_username filter_username = notfound
Tue Nov 12 13:13:06 2013 : Debug: (162)   ? if ("%{reply:Reply-Message}" !~ /MAC-AUTH/) 
Tue Nov 12 13:13:06 2013 : Debug: %{reply:Reply-Message}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Reply-Message
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 2
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{reply:Reply-Message}" -> ''
Tue Nov 12 13:13:06 2013 : Debug: (162)   ? if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (162)   if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  {
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/) 
Tue Nov 12 13:13:06 2013 : Debug: %{User-Name}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: User-Name
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{User-Name}" -> 'swansea.ac.uk@eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (162) %{0}: Inserting new value "swansea.ac.uk@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{1}: Inserting new value "swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{2}: Inserting new value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{3}: Inserting new value "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (162)    if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  {
Tue Nov 12 13:13:06 2013 : Debug: (162)     ? if ("%{3}") 
Tue Nov 12 13:13:06 2013 : Debug: %{3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: regex-var: 3
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{3}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (162)     ? if ("%{3}")  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (162)     if ("%{3}")  {
Tue Nov 12 13:13:06 2013 : Debug: (162)      ? if ((User-Name =~ /([a-z0-9_\.\-]+)@(swan|colegcymraeg|swansea|abertawe|test\.colegcymraeg|test\.swansea|test\.abertawe)\.ac\.uk/i) || (User-Name =~ /@(swan|colegcymraeg|swansea|abertawe)\.ac\.uk/i)) 
Tue Nov 12 13:13:06 2013 : Debug: (162)      ? if ((User-Name =~ /([a-z0-9_\.\-]+)@(swan|colegcymraeg|swansea|abertawe|test\.colegcymraeg|test\.swansea|test\.abertawe)\.ac\.uk/i) || (User-Name =~ /@(swan|colegcymraeg|swansea|abertawe)\.ac\.uk/i))  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)      else else {
Tue Nov 12 13:13:06 2013 : Debug: (162)       ? if ((User-Name =~ /3gppnetwork\.org/i) || (User-Name =~ /\.acuk$/i) || (User-Name =~ /\.aaac\.uk\/$/i)) 
Tue Nov 12 13:13:06 2013 : Debug: (162)       ? if ((User-Name =~ /3gppnetwork\.org/i) || (User-Name =~ /\.acuk$/i) || (User-Name =~ /\.aaac\.uk\/$/i))  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)       else else {
Tue Nov 12 13:13:06 2013 : Debug: (162)        update request {
Tue Nov 12 13:13:06 2013 : Debug: %{3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: regex-var: 3
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{3}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (162) Stripped-User-Domain = "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: FROM 1 TO 9 MAX 10
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: Examining Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: APPENDING Stripped-User-Domain FROM 0 TO 9
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: TO in 9 out 10
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[7] = State
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[8] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[9] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (162)        } # update request = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)       } # else else = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)      } # else else = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)     } # if ("%{3}")  = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)      ... skipping else for request 162: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (162)    } # if ("%{User-Name}" =~ /^([^@]*)(@([-[:alnum:].]+))?$/)  = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)     ... skipping else for request 162: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./)) 
Tue Nov 12 13:13:06 2013 : Debug: %{NAS-IP-Address}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{NAS-IP-Address}" -> '137.44.0.2'
Tue Nov 12 13:13:06 2013 : Debug: (162) %{0}: Inserting new value "137.44."
Tue Nov 12 13:13:06 2013 : Debug: (162) %{1}: Clearing old value "swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{2}: Clearing old value "@eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{3}: Clearing old value "eduroam.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) %{4}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{5}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{6}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{7}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162) %{8}: Was empty
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  -> TRUE
Tue Nov 12 13:13:06 2013 : Debug: (162)    if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  {
Tue Nov 12 13:13:06 2013 : Debug: (162)     switch %{Stripped-User-Domain} {
Tue Nov 12 13:13:06 2013 : Debug: %{Stripped-User-Domain}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{Stripped-User-Domain}" -> 'eduroam.ac.uk'
Tue Nov 12 13:13:06 2013 : Debug: (162)     switch %{Stripped-User-Domain} {
Tue Nov 12 13:13:06 2013 : Debug: (162)      case (null) {
Tue Nov 12 13:13:06 2013 : Debug: (162)       update control {
Tue Nov 12 13:13:06 2013 : Debug: (162) Proxy-To-Realm := 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: FROM 1 TO 0 MAX 1
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: Examining Proxy-To-Realm
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: APPENDING Proxy-To-Realm FROM 0 TO 0
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: TO in 0 out 1
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[0] = Proxy-To-Realm
Tue Nov 12 13:13:06 2013 : Debug: (162)       } # update control = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)       update request {
Tue Nov 12 13:13:06 2013 : Debug: (162) Realm := 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: FROM 1 TO 10 MAX 11
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: Examining Realm
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: APPENDING Realm FROM 0 TO 10
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: TO in 10 out 11
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[7] = State
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[8] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[9] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[10] = Realm
Tue Nov 12 13:13:06 2013 : Debug: (162) Operator-Name := "1swansea.ac.uk"
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: FROM 1 TO 11 MAX 12
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: Examining Operator-Name
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: APPENDING Operator-Name FROM 0 TO 11
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: TO in 11 out 12
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[0] = User-Name
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[1] = Calling-Station-Id
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[2] = Framed-MTU
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[3] = NAS-Port-Type
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[4] = Connect-Info
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[5] = NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[6] = EAP-Message
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[7] = State
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[8] = Message-Authenticator
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[9] = Stripped-User-Domain
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[10] = Realm
Tue Nov 12 13:13:06 2013 : Debug: (162) ::: to[11] = Operator-Name
Tue Nov 12 13:13:06 2013 : Debug: (162)       } # update request = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)      } # case  = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)     } # switch %{Stripped-User-Domain} = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)    } # if (("%{NAS-IP-Address}" =~ /^137\.44\./) || ("%{NAS-IP-Address}" =~ /^10\.56\.14\./)  || ("%{NAS-IP-Address}" =~ /^10\.60\./) || ("%{NAS-IP-Address}" =~ /^10\.10\.246\./))  = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)     ... skipping else for request 162: Preceding "if" was taken
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if ("%{Realm}" != "jrs") 
Tue Nov 12 13:13:06 2013 : Debug: jrs
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "jrs" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: %{Realm}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Realm
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{Realm}" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (162)    ? if ("%{Realm}" != "jrs")  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)   } # if ("%{reply:Reply-Message}" !~ /MAC-AUTH/)  = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [preprocess] = ok
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling auth_log (rlm_detail) for request 162
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/auth-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (162) auth_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/auth-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (162) auth_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/auth-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (162) auth_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from auth_log (rlm_detail) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [auth_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling chap (rlm_chap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from chap (rlm_chap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [chap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling mschap (rlm_mschap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from mschap (rlm_mschap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [mschap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling suffix (rlm_realm) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162) suffix : Request already has destination realm set.  Ignoring.
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from suffix (rlm_realm) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [suffix] = ok
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling ntdomain (rlm_realm) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162) ntdomain : Request already has destination realm set.  Ignoring.
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from ntdomain (rlm_realm) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [ntdomain] = ok
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling eap (rlm_eap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162) eap : Request is supposed to be proxied to Realm jrs. Not doing EAP.
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from eap (rlm_eap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [eap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)   ? if (("%{NAS-IP-Address}" =~ /137.44.47.2[0-9]+[0-9]+/) && ("%{control:Tmp-String-2}" =~ /local|virus|banned|accomban/i))  
Tue Nov 12 13:13:06 2013 : Debug: %{NAS-IP-Address}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: NAS-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{NAS-IP-Address}" -> '137.44.0.2'
Tue Nov 12 13:13:06 2013 : Debug: (162)   ? if (("%{NAS-IP-Address}" =~ /137.44.47.2[0-9]+[0-9]+/) && ("%{control:Tmp-String-2}" =~ /local|virus|banned|accomban/i))   -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)   ? if ("%{control:Tmp-String-3}" == "guest") 
Tue Nov 12 13:13:06 2013 : Debug: guest
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: 'guest'
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "guest" -> 'guest'
Tue Nov 12 13:13:06 2013 : Debug: %{control:Tmp-String-3}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Tmp-String-3
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 3
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) expand: "%{control:Tmp-String-3}" -> ''
Tue Nov 12 13:13:06 2013 : Debug: (162)   ? if ("%{control:Tmp-String-3}" == "guest")  -> FALSE
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling logintime (rlm_logintime) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from logintime (rlm_logintime) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [logintime] = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: calling pap (rlm_pap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[authorize]: returned from pap (rlm_pap) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [pap] = noop
Tue Nov 12 13:13:06 2013 : Debug: (162)  } #  authorize = ok
Tue Nov 12 13:13:06 2013 : Debug: (162) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:06 2013 : Debug: (162)   pre-proxy {
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[pre-proxy]: calling attr_filter.pre-proxy (rlm_attr_filter) for request 162
Tue Nov 12 13:13:06 2013 : Debug: %{Realm}
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: attribute: Realm
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: (162) attr_filter.pre-proxy : expand: "%{Realm}" -> 'jrs'
Tue Nov 12 13:13:06 2013 : Debug: (162) attr_filter.pre-proxy : Matched entry DEFAULT at line 50
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[pre-proxy]: returned from attr_filter.pre-proxy (rlm_attr_filter) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [attr_filter.pre-proxy] = updated
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail) for request 162
Tue Nov 12 13:13:06 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:06 2013 : Debug: if {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: else {
Tue Nov 12 13:13:06 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:06 2013 : Debug: {
Tue Nov 12 13:13:06 2013 : Debug: ref  2
Tue Nov 12 13:13:06 2013 : Debug: list 1
Tue Nov 12 13:13:06 2013 : Debug: tag -128
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: }
Tue Nov 12 13:13:06 2013 : Debug: literal: '/pre-proxy-detail-'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:06 2013 : Debug: (162) pre_proxy_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/pre-proxy-detail-20131112'
Tue Nov 12 13:13:06 2013 : Debug: (162) pre_proxy_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/pre-proxy-detail-20131112
Tue Nov 12 13:13:06 2013 : Debug: %t
Tue Nov 12 13:13:06 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:06 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:06 2013 : Debug: (162) pre_proxy_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:06 2013 : Debug: (162)   modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail) for request 162
Tue Nov 12 13:13:06 2013 : Debug: (162)   [pre_proxy_log] = ok
Tue Nov 12 13:13:06 2013 : Debug: (162)  } #  pre-proxy = updated
Tue Nov 12 13:13:06 2013 : Debug: (162) proxy: Trying to allocate ID (0/2)
Tue Nov 12 13:13:06 2013 : Debug: (162) proxy: request is now in proxy hash
Tue Nov 12 13:13:06 2013 : Debug: (162)  proxy: allocating destination 194.83.56.233 port 1812 - Id 252
Tue Nov 12 13:13:06 2013 : Debug: (162) Proxying request to home server 194.83.56.233 port 1812
Sending Access-Request of id 252 from 0.0.0.0 port 1814 to 194.83.56.233 port 1812
User-Name = 'swansea.ac.uk@eduroam.ac.uk'
NAS-IP-Address = 137.44.0.2
EAP-Message = 0x020200061900
State = 0x6ee887f26fea9ed95ce9a084cc329b80
Message-Authenticator = 0x81d5ddca52123616fc193cd8a980b775
Proxy-State = 0x32
Tue Nov 12 13:13:06 2013 : Debug: Waking up in 0.2 seconds.
Tue Nov 12 13:13:07 2013 : Debug: Waking up in 0.4 seconds.
Tue Nov 12 13:13:07 2013 : Debug: (162) Expecting proxy response no later than 30 seconds from now
Tue Nov 12 13:13:07 2013 : Debug: Waking up in 1.4 seconds.
Tue Nov 12 13:13:09 2013 : Debug: (140) Cleaning up request packet ID 0 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (141) Cleaning up request packet ID 1 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (142) Cleaning up request packet ID 2 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (143) Cleaning up request packet ID 3 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (144) Cleaning up request packet ID 4 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (145) Cleaning up request packet ID 5 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (146) Cleaning up request packet ID 6 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (147) Cleaning up request packet ID 7 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (148) Cleaning up request packet ID 8 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: (149) Cleaning up request packet ID 9 with timestamp +34
Tue Nov 12 13:13:09 2013 : Debug: Waking up in 0.8 seconds.
rad_recv: Access-Request packet from host 123.44.55.66 port 37026, id=2, length=154
Tue Nov 12 13:13:09 2013 : Debug: (162) Sending duplicate proxied request to home server 194.83.56.233 port 1812 - ID: 252
Sending Access-Request of id 252 from 0.0.0.0 port 1814 to 194.83.56.233 port 1812
User-Name = 'swansea.ac.uk@eduroam.ac.uk'
NAS-IP-Address = 137.44.0.2
EAP-Message = 0x020200061900
State = 0x6ee887f26fea9ed95ce9a084cc329b80
Message-Authenticator = 0x81d5ddca52123616fc193cd8a980b775
Proxy-State = 0x32
Tue Nov 12 13:13:09 2013 : Debug: Waking up in 0.5 seconds.
rad_recv: Access-Reject packet from host 194.83.56.233 port 1812, id=252, length=39
Reply-Message = 'Request Denied'
Proxy-State = 0x32
Tue Nov 12 13:13:09 2013 : Debug: (162) # Executing section post-proxy from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:09 2013 : Debug: (162)   post-proxy {
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-proxy]: calling post_proxy_log (rlm_detail) for request 162
Tue Nov 12 13:13:09 2013 : Debug: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d
Tue Nov 12 13:13:09 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:09 2013 : Debug: literal: '/usr/local/var/log/radius/radacct/'
Tue Nov 12 13:13:09 2013 : Debug: if {
Tue Nov 12 13:13:09 2013 : Debug: attribute: Packet-Src-IP-Address
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 1
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: else {
Tue Nov 12 13:13:09 2013 : Debug: attribute: Packet-Src-IPv6-Address
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 1
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: literal: '/post-proxy-detail-'
Tue Nov 12 13:13:09 2013 : Debug: literal (with %): 'Y'
Tue Nov 12 13:13:09 2013 : Debug: literal (with %): 'm'
Tue Nov 12 13:13:09 2013 : Debug: literal (with %): 'd'
Tue Nov 12 13:13:09 2013 : Debug: (162) post_proxy_log : expand: "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" -> '/usr/local/var/log/radius/radacct/123.44.55.66/post-proxy-detail-20131112'
Tue Nov 12 13:13:09 2013 : Debug: (162) post_proxy_log : /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/123.44.55.66/post-proxy-detail-20131112
Tue Nov 12 13:13:09 2013 : Debug: %t
Tue Nov 12 13:13:09 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:09 2013 : Debug: literal (with %): 't'
Tue Nov 12 13:13:09 2013 : Debug: (162) post_proxy_log : expand: "%t" -> 'Tue Nov 12 13:13:06 2013'
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-proxy]: returned from post_proxy_log (rlm_detail) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162)   [post_proxy_log] = ok
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-proxy]: calling eap (rlm_eap) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162) eap : No pre-existing handler found
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-proxy]: returned from eap (rlm_eap) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162)   [eap] = noop
Tue Nov 12 13:13:09 2013 : Debug: (162)  } #  post-proxy = ok
Tue Nov 12 13:13:09 2013 : Debug: (162) Using Post-Auth-Type Reject
Tue Nov 12 13:13:09 2013 : Debug: (162) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 12 13:13:09 2013 : Debug: (162)  Post-Auth-Type REJECT {
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: calling sql (rlm_sql) for request 162
Tue Nov 12 13:13:09 2013 : Debug: .query
Tue Nov 12 13:13:09 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:09 2013 : Debug: literal: '.query'
Tue Nov 12 13:13:09 2013 : Debug: (162) sql : expand: ".query" -> '.query'
Tue Nov 12 13:13:09 2013 : Debug: (162) sql : Using query template 'query'
Tue Nov 12 13:13:09 2013 : Debug: rlm_sql (sql): Reserved connection (4)
Tue Nov 12 13:13:09 2013 : Debug: %{User-Name}
Tue Nov 12 13:13:09 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:09 2013 : Debug: attribute: User-Name
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 1
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: (162) sql : expand: "%{User-Name}" -> 'swansea.ac.uk@eduroam.ac.uk'
Tue Nov 12 13:13:09 2013 : Debug: (162) sql : SQL-User-Name set to "swansea.ac.uk@eduroam.ac.uk"
Tue Nov 12 13:13:09 2013 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Tue Nov 12 13:13:09 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:09 2013 : Debug: literal: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ''
Tue Nov 12 13:13:09 2013 : Debug: attribute: SQL-User-Name
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 1
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: literal: '', ''
Tue Nov 12 13:13:09 2013 : Debug: if {
Tue Nov 12 13:13:09 2013 : Debug: attribute: User-Password
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 1
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: else {
Tue Nov 12 13:13:09 2013 : Debug: attribute: CHAP-Password
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 1
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: literal: '', ''
Tue Nov 12 13:13:09 2013 : Debug: attribute: Packet-Type
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 2
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: literal: '', ''
Tue Nov 12 13:13:09 2013 : Debug: literal (with %): 'S'
Tue Nov 12 13:13:09 2013 : Debug: literal: '')'
Tue Nov 12 13:13:09 2013 : Debug: (162) sql : expand: "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" -> 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'swansea.ac.uk@eduroam.ac.uk', '', 'Access-Reject', '2013-11-12 13:13:06')'
Tue Nov 12 13:13:09 2013 : Debug: rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'swansea.ac.uk@eduroam.ac.uk', '', 'Access-Reject', '2013-11-12 13:13:06')'
Tue Nov 12 13:13:09 2013 : Debug: rlm_sql (sql): Released connection (4)
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: returned from sql (rlm_sql) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162)   [-sql] = ok
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 162
Tue Nov 12 13:13:09 2013 : Debug: %{User-Name}
Tue Nov 12 13:13:09 2013 : Debug: Parsed xlat tree:
Tue Nov 12 13:13:09 2013 : Debug: attribute: User-Name
Tue Nov 12 13:13:09 2013 : Debug: {
Tue Nov 12 13:13:09 2013 : Debug: ref  2
Tue Nov 12 13:13:09 2013 : Debug: list 1
Tue Nov 12 13:13:09 2013 : Debug: tag -128
Tue Nov 12 13:13:09 2013 : Debug: }
Tue Nov 12 13:13:09 2013 : Debug: (162) attr_filter.access_reject : expand: "%{User-Name}" -> 'swansea.ac.uk@eduroam.ac.uk'
Tue Nov 12 13:13:09 2013 : Debug: (162) attr_filter.access_reject : Matched entry DEFAULT at line 11
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162)   [attr_filter.access_reject] = updated
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: calling eap (rlm_eap) for request 162
Tue Nov 12 13:13:09 2013 : Error: rlm_eap (EAP): No EAP session matching state 0x6ee887f26fea9ed9
Tue Nov 12 13:13:09 2013 : Debug: (162) eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
Tue Nov 12 13:13:09 2013 : Debug: (162) eap : Failed to get handler, probably already removed, not inserting EAP-Failure
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: returned from eap (rlm_eap) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162)   [eap] = noop
Tue Nov 12 13:13:09 2013 : Debug: (162)   remove_reply_message_if_eap remove_reply_message_if_eap {
Tue Nov 12 13:13:09 2013 : Debug: (162)    ? if (reply:EAP-Message && reply:Reply-Message) 
Tue Nov 12 13:13:09 2013 : Debug: (162)    ? if (reply:EAP-Message && reply:Reply-Message)  -> FALSE
Tue Nov 12 13:13:09 2013 : Debug: (162)    else else {
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: calling noop (rlm_always) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162)   modsingle[post-auth]: returned from noop (rlm_always) for request 162
Tue Nov 12 13:13:09 2013 : Debug: (162)     [noop] = noop
Tue Nov 12 13:13:09 2013 : Debug: (162)    } # else else = noop
Tue Nov 12 13:13:09 2013 : Debug: (162)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
Tue Nov 12 13:13:09 2013 : Debug: (162)  } # Post-Auth-Type REJECT = updated
Tue Nov 12 13:13:09 2013 : Debug: (162) Finished request 162.
Tue Nov 12 13:13:09 2013 : Debug: Waking up in 0.3 seconds.
Tue Nov 12 13:13:10 2013 : Debug: Waking up in 0.1 seconds.
Tue Nov 12 13:13:10 2013 : Debug: (150) Cleaning up request packet ID 0 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (151) Cleaning up request packet ID 1 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (152) Cleaning up request packet ID 2 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (153) Cleaning up request packet ID 3 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (154) Cleaning up request packet ID 4 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (155) Cleaning up request packet ID 5 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (156) Cleaning up request packet ID 6 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (157) Cleaning up request packet ID 7 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (158) Cleaning up request packet ID 8 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: (159) Cleaning up request packet ID 9 with timestamp +35
Tue Nov 12 13:13:10 2013 : Debug: Waking up in 0.1 seconds.
Tue Nov 12 13:13:10 2013 : Debug: (162) Sending delayed reject
Sending Access-Reject of id 2 from 137.44.1.53 port 1812 to 123.44.55.66 port 37026
Reply-Message = 'Request Denied'
Tue Nov 12 13:13:10 2013 : Debug: Waking up in 0.8 seconds.
Tue Nov 12 13:13:11 2013 : Debug: (160) Cleaning up request packet ID 0 with timestamp +36
Tue Nov 12 13:13:11 2013 : Debug: (161) Cleaning up request packet ID 1 with timestamp +36
Tue Nov 12 13:13:11 2013 : Debug: Waking up in 4.0 seconds.
Tue Nov 12 13:13:15 2013 : Debug: (162) Waiting for more responses from the home server
Tue Nov 12 13:13:15 2013 : Debug: (162) Waiting for more responses from the home server

...
This line is then repeated over 1 million times
...

Tue Nov 12 13:13:36 2013 : Debug: (162) Waiting for more responses from the home server
Tue Nov 12 13:13:36 2013 : Debug: (162) proxy: request is no longer in proxy hash
Tue Nov 12 13:13:36 2013 : Debug: (162) Cleaning up request packet ID 2 with timestamp +36
Tue Nov 12 13:13:36 2013 : Info: Ready to process requests.

RE: attrs.filter differences between FR 2.2.0 and FR 3

Palmer J.D.F.