User-Name return glitch in FR 3.0.17?
Stefan Paetow
Stefan.Paetow at jisc.ac.uk
Mon Apr 23 17:51:44 CEST 2018
Right,
So, this is an authentication on FreeRADIUS 3.0.17 that I've just upgraded to on our 'playpen' network. Previously, it would simply return the User-Name as 'root' (I know, I know...) but now it appears that the server adds the outer User-Name *first*, and then restores the session-state one (which was set by the inner-tunnel as 'root').
This doesn't look right... Alan? Arran?
The /etc/raddb/users file looks like this:
bob Cleartext-Password := <<password>>
Reply-Message := 'Bob has authenticated',
User-Name := 'root'
-- log follows --
FreeRADIUS Version 3.0.17
Copyright (C) 1999-2017 The FreeRADIUS server project and contributors
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License
For more information about these matters, see the file named COPYRIGHT
Starting - reading configuration files ...
including dictionary file /usr/share/freeradius/dictionary
including dictionary file /usr/share/freeradius/dictionary.dhcp
including dictionary file /usr/share/freeradius/dictionary.vqp
including dictionary file /etc/raddb/dictionary
including configuration file /etc/raddb/radiusd.conf
including configuration file /etc/raddb/proxy.conf
including configuration file /etc/raddb/clients.conf
including files in directory /etc/raddb/mods-enabled/
including configuration file /etc/raddb/mods-enabled/always
including configuration file /etc/raddb/mods-enabled/attr_filter
including configuration file /etc/raddb/mods-enabled/cache_eap
including configuration file /etc/raddb/mods-enabled/chap
including configuration file /etc/raddb/mods-enabled/date
including configuration file /etc/raddb/mods-enabled/detail
including configuration file /etc/raddb/mods-enabled/detail.log
including configuration file /etc/raddb/mods-enabled/digest
including configuration file /etc/raddb/mods-enabled/dynamic_clients
including configuration file /etc/raddb/mods-enabled/eap
including configuration file /etc/raddb/mods-enabled/echo
including configuration file /etc/raddb/mods-enabled/exec
including configuration file /etc/raddb/mods-enabled/expiration
including configuration file /etc/raddb/mods-enabled/expr
including configuration file /etc/raddb/mods-enabled/files
including configuration file /etc/raddb/mods-enabled/linelog
including configuration file /etc/raddb/mods-enabled/logintime
including configuration file /etc/raddb/mods-enabled/mschap
including configuration file /etc/raddb/mods-enabled/ntlm_auth
including configuration file /etc/raddb/mods-enabled/pap
including configuration file /etc/raddb/mods-enabled/passwd
including configuration file /etc/raddb/mods-enabled/preprocess
including configuration file /etc/raddb/mods-enabled/radutmp
including configuration file /etc/raddb/mods-enabled/realm
including configuration file /etc/raddb/mods-enabled/replicate
including configuration file /etc/raddb/mods-enabled/soh
including configuration file /etc/raddb/mods-enabled/sradutmp
including configuration file /etc/raddb/mods-enabled/unix
including configuration file /etc/raddb/mods-enabled/unpack
including configuration file /etc/raddb/mods-enabled/utf8
including configuration file /etc/raddb/mods-enabled/abfab_psk_sql
including files in directory /etc/raddb/policy.d/
including configuration file /etc/raddb/policy.d/abfab-tr
including configuration file /etc/raddb/policy.d/accounting
including configuration file /etc/raddb/policy.d/canonicalization
including configuration file /etc/raddb/policy.d/control
including configuration file /etc/raddb/policy.d/cui
including configuration file /etc/raddb/policy.d/debug
including configuration file /etc/raddb/policy.d/dhcp
including configuration file /etc/raddb/policy.d/eap
including configuration file /etc/raddb/policy.d/filter
including configuration file /etc/raddb/policy.d/operator-name
including configuration file /etc/raddb/policy.d/moonshot-targeted-ids
including files in directory /etc/raddb/sites-enabled/
including configuration file /etc/raddb/sites-enabled/channel_bindings
including configuration file /etc/raddb/sites-enabled/default
including configuration file /etc/raddb/sites-enabled/inner-tunnel
including configuration file /etc/raddb/sites-enabled/abfab-tls
including configuration file /etc/raddb/sites-enabled/abfab-tr-idp
main {
name = "radiusd"
prefix = "/usr"
localstatedir = "/var"
sbindir = "/usr/sbin"
logdir = "/var/log/radius"
run_dir = "/var/run/radiusd"
libdir = "/usr/lib64/freeradius"
radacctdir = "/var/log/radius/radacct"
hostname_lookups = no
max_request_time = 30
cleanup_delay = 5
max_requests = 16384
pidfile = "/var/run/radiusd/radiusd.pid"
checkrad = "/usr/sbin/checkrad"
debug_level = 0
proxy_requests = yes
log {
stripped_names = no
auth = no
auth_badpass = no
auth_goodpass = no
colourise = yes
msg_denied = "You are already logged in - access denied"
}
resources {
}
security {
max_attributes = 200
reject_delay = 1.000000
status_server = yes
allow_vulnerable_openssl = "yes"
}
}
radiusd: #### Loading Realms and Home Servers ####
proxy server {
retry_delay = 5
retry_count = 3
default_fallback = no
dynamic = yes
dead_time = 120
wake_all_if_all_dead = no
}
home_server localhost {
ipaddr = 127.0.0.1
port = 1812
type = "auth"
secret = <<< secret >>>
response_window = 20.000000
response_timeouts = 1
max_outstanding = 65536
zombie_period = 40
status_check = "status-server"
ping_interval = 30
check_interval = 30
check_timeout = 4
num_answers_to_alive = 3
revive_interval = 120
limit {
max_connections = 16
max_requests = 0
lifetime = 0
idle_timeout = 0
}
coa {
irt = 2
mrt = 16
mrc = 5
mrd = 30
}
}
realm idp.test.assent {
}
home_server_pool my_auth_failover {
type = fail-over
home_server = localhost
}
realm example.com {
auth_pool = my_auth_failover
}
realm LOCAL {
}
radiusd: #### Loading Clients ####
client localhost {
ipaddr = 127.0.0.1
require_message_authenticator = no
secret = <<< secret >>>
nas_type = "other"
proto = "*"
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
client localhost_ipv6 {
ipv6addr = ::1
require_message_authenticator = no
secret = <<< secret >>>
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
Debug state unknown (cap_sys_ptrace capability not set)
# Creating Auth-Type = mschap
# Creating Auth-Type = digest
# Creating Auth-Type = eap
# Creating Auth-Type = PAP
# Creating Auth-Type = CHAP
# Creating Auth-Type = MS-CHAP
radiusd: #### Instantiating modules ####
modules {
# Loaded module rlm_always
# Loading module "reject" from file /etc/raddb/mods-enabled/always
always reject {
rcode = "reject"
simulcount = 0
mpp = no
}
# Loading module "fail" from file /etc/raddb/mods-enabled/always
always fail {
rcode = "fail"
simulcount = 0
mpp = no
}
# Loading module "ok" from file /etc/raddb/mods-enabled/always
always ok {
rcode = "ok"
simulcount = 0
mpp = no
}
# Loading module "handled" from file /etc/raddb/mods-enabled/always
always handled {
rcode = "handled"
simulcount = 0
mpp = no
}
# Loading module "invalid" from file /etc/raddb/mods-enabled/always
always invalid {
rcode = "invalid"
simulcount = 0
mpp = no
}
# Loading module "userlock" from file /etc/raddb/mods-enabled/always
always userlock {
rcode = "userlock"
simulcount = 0
mpp = no
}
# Loading module "notfound" from file /etc/raddb/mods-enabled/always
always notfound {
rcode = "notfound"
simulcount = 0
mpp = no
}
# Loading module "noop" from file /etc/raddb/mods-enabled/always
always noop {
rcode = "noop"
simulcount = 0
mpp = no
}
# Loading module "updated" from file /etc/raddb/mods-enabled/always
always updated {
rcode = "updated"
simulcount = 0
mpp = no
}
# Loaded module rlm_attr_filter
# Loading module "attr_filter.post-proxy" from file /etc/raddb/mods-enabled/attr_filter
attr_filter attr_filter.post-proxy {
filename = "/etc/raddb/mods-config/attr_filter/post-proxy"
key = "%{Realm}"
relaxed = no
}
# Loading module "attr_filter.pre-proxy" from file /etc/raddb/mods-enabled/attr_filter
attr_filter attr_filter.pre-proxy {
filename = "/etc/raddb/mods-config/attr_filter/pre-proxy"
key = "%{Realm}"
relaxed = no
}
# Loading module "attr_filter.access_reject" from file /etc/raddb/mods-enabled/attr_filter
attr_filter attr_filter.access_reject {
filename = "/etc/raddb/mods-config/attr_filter/access_reject"
key = "%{User-Name}"
relaxed = no
}
# Loading module "attr_filter.access_challenge" from file /etc/raddb/mods-enabled/attr_filter
attr_filter attr_filter.access_challenge {
filename = "/etc/raddb/mods-config/attr_filter/access_challenge"
key = "%{User-Name}"
relaxed = no
}
# Loading module "attr_filter.accounting_response" from file /etc/raddb/mods-enabled/attr_filter
attr_filter attr_filter.accounting_response {
filename = "/etc/raddb/mods-config/attr_filter/accounting_response"
key = "%{User-Name}"
relaxed = no
}
# Loaded module rlm_cache
# Loading module "cache_eap" from file /etc/raddb/mods-enabled/cache_eap
cache cache_eap {
driver = "rlm_cache_rbtree"
key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}"
ttl = 15
max_entries = 0
epoch = 0
add_stats = no
}
# Loaded module rlm_chap
# Loading module "chap" from file /etc/raddb/mods-enabled/chap
# Loaded module rlm_date
# Loading module "date" from file /etc/raddb/mods-enabled/date
date {
format = "%b %e %Y %H:%M:%S %Z"
utc = no
}
# Loaded module rlm_detail
# Loading module "detail" from file /etc/raddb/mods-enabled/detail
detail {
filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
header = "%t"
permissions = 384
locking = no
escape_filenames = no
log_packet_header = no
}
# Loading module "auth_log" from file /etc/raddb/mods-enabled/detail.log
detail auth_log {
filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d"
header = "%t"
permissions = 384
locking = no
escape_filenames = no
log_packet_header = no
}
# Loading module "reply_log" from file /etc/raddb/mods-enabled/detail.log
detail reply_log {
filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d"
header = "%t"
permissions = 384
locking = no
escape_filenames = no
log_packet_header = no
}
# Loading module "pre_proxy_log" from file /etc/raddb/mods-enabled/detail.log
detail pre_proxy_log {
filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d"
header = "%t"
permissions = 384
locking = no
escape_filenames = no
log_packet_header = no
}
# Loading module "post_proxy_log" from file /etc/raddb/mods-enabled/detail.log
detail post_proxy_log {
filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d"
header = "%t"
permissions = 384
locking = no
escape_filenames = no
log_packet_header = no
}
# Loaded module rlm_digest
# Loading module "digest" from file /etc/raddb/mods-enabled/digest
# Loaded module rlm_dynamic_clients
# Loading module "dynamic_clients" from file /etc/raddb/mods-enabled/dynamic_clients
# Loaded module rlm_eap
# Loading module "eap" from file /etc/raddb/mods-enabled/eap
eap {
default_eap_type = "ttls"
timer_expire = 60
ignore_unknown_eap_types = no
cisco_accounting_username_bug = no
max_sessions = 16384
}
# Loaded module rlm_exec
# Loading module "echo" from file /etc/raddb/mods-enabled/echo
exec echo {
wait = yes
program = "/bin/echo %{User-Name}"
input_pairs = "request"
output_pairs = "reply"
shell_escape = yes
}
# Loading module "exec" from file /etc/raddb/mods-enabled/exec
exec {
wait = no
input_pairs = "request"
shell_escape = yes
timeout = 10
}
# Loaded module rlm_expiration
# Loading module "expiration" from file /etc/raddb/mods-enabled/expiration
# Loaded module rlm_expr
# Loading module "expr" from file /etc/raddb/mods-enabled/expr
expr {
safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
}
# Loaded module rlm_files
# Loading module "files" from file /etc/raddb/mods-enabled/files
files {
filename = "/etc/raddb/mods-config/files/authorize"
acctusersfile = "/etc/raddb/mods-config/files/accounting"
preproxy_usersfile = "/etc/raddb/mods-config/files/pre-proxy"
}
# Loaded module rlm_linelog
# Loading module "linelog" from file /etc/raddb/mods-enabled/linelog
linelog {
filename = "/var/log/radius/linelog"
escape_filenames = no
syslog_severity = "info"
permissions = 384
format = "This is a log message for %{User-Name}"
reference = "messages.%{%{reply:Packet-Type}:-default}"
}
# Loading module "log_accounting" from file /etc/raddb/mods-enabled/linelog
linelog log_accounting {
filename = "/var/log/radius/linelog-accounting"
escape_filenames = no
syslog_severity = "info"
permissions = 384
format = ""
reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}"
}
# Loaded module rlm_logintime
# Loading module "logintime" from file /etc/raddb/mods-enabled/logintime
logintime {
minimum_timeout = 60
}
# Loaded module rlm_mschap
# Loading module "mschap" from file /etc/raddb/mods-enabled/mschap
mschap {
use_mppe = yes
require_encryption = no
require_strong = no
with_ntdomain_hack = yes
passchange {
}
allow_retry = yes
winbind_retry_with_normalised_username = no
}
# Loading module "ntlm_auth" from file /etc/raddb/mods-enabled/ntlm_auth
exec ntlm_auth {
wait = yes
program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}"
shell_escape = yes
}
# Loaded module rlm_pap
# Loading module "pap" from file /etc/raddb/mods-enabled/pap
pap {
normalise = yes
}
# Loaded module rlm_passwd
# Loading module "etc_passwd" from file /etc/raddb/mods-enabled/passwd
passwd etc_passwd {
filename = "/etc/passwd"
format = "*User-Name:Crypt-Password:"
delimiter = ":"
ignore_nislike = no
ignore_empty = yes
allow_multiple_keys = no
hash_size = 100
}
# Loaded module rlm_preprocess
# Loading module "preprocess" from file /etc/raddb/mods-enabled/preprocess
preprocess {
huntgroups = "/etc/raddb/mods-config/preprocess/huntgroups"
hints = "/etc/raddb/mods-config/preprocess/hints"
with_ascend_hack = no
ascend_channels_per_line = 23
with_ntdomain_hack = no
with_specialix_jetstream_hack = no
with_cisco_vsa_hack = no
with_alvarion_vsa_hack = no
}
# Loaded module rlm_radutmp
# Loading module "radutmp" from file /etc/raddb/mods-enabled/radutmp
radutmp {
filename = "/var/log/radius/radutmp"
username = "%{User-Name}"
case_sensitive = yes
check_with_nas = yes
permissions = 384
caller_id = yes
}
# Loaded module rlm_realm
# Loading module "IPASS" from file /etc/raddb/mods-enabled/realm
realm IPASS {
format = "prefix"
delimiter = "/"
ignore_default = no
ignore_null = no
default_community = "none"
rp_realm = "none"
trust_router = "none"
tr_port = 0
rekey_enabled = no
realm_lifetime = 0
}
# Loading module "suffix" from file /etc/raddb/mods-enabled/realm
realm suffix {
format = "suffix"
delimiter = "@"
ignore_default = no
ignore_null = no
default_community = "apc.test.assent"
rp_realm = "assent-fr-idp.test.assent"
trust_router = "tr.moonshot-playpen.ti.ja.net"
tr_port = 0
rekey_enabled = no
realm_lifetime = 0
}
# Loading module "realmpercent" from file /etc/raddb/mods-enabled/realm
realm realmpercent {
format = "suffix"
delimiter = "%"
ignore_default = no
ignore_null = no
default_community = "none"
rp_realm = "none"
trust_router = "none"
tr_port = 0
rekey_enabled = no
realm_lifetime = 0
}
# Loading module "ntdomain" from file /etc/raddb/mods-enabled/realm
realm ntdomain {
format = "prefix"
delimiter = "\\"
ignore_default = no
ignore_null = no
default_community = "none"
rp_realm = "none"
trust_router = "none"
tr_port = 0
rekey_enabled = no
realm_lifetime = 0
}
# Loaded module rlm_replicate
# Loading module "replicate" from file /etc/raddb/mods-enabled/replicate
# Loaded module rlm_soh
# Loading module "soh" from file /etc/raddb/mods-enabled/soh
soh {
dhcp = yes
}
# Loading module "sradutmp" from file /etc/raddb/mods-enabled/sradutmp
radutmp sradutmp {
filename = "/var/log/radius/sradutmp"
username = "%{User-Name}"
case_sensitive = yes
check_with_nas = yes
permissions = 420
caller_id = no
}
# Loaded module rlm_unix
# Loading module "unix" from file /etc/raddb/mods-enabled/unix
unix {
radwtmp = "/var/log/radius/radwtmp"
}
Creating attribute Unix-Group
# Loaded module rlm_unpack
# Loading module "unpack" from file /etc/raddb/mods-enabled/unpack
# Loaded module rlm_utf8
# Loading module "utf8" from file /etc/raddb/mods-enabled/utf8
# Loaded module rlm_sql
# Loading module "psksql" from file /etc/raddb/mods-enabled/abfab_psk_sql
sql psksql {
driver = "rlm_sql_sqlite"
server = ""
port = 0
login = ""
password = <<< secret >>>
radius_db = "radius"
read_groups = yes
read_profiles = yes
read_clients = no
delete_stale_sessions = yes
sql_user_name = ""
default_user_profile = ""
client_query = "SELECT id,nasname,shortname,type,secret FROM nas"
safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
accounting {
reference = ".query"
type {
accounting-on {
}
accounting-off {
}
start {
}
interim-update {
}
stop {
}
}
}
post-auth {
reference = ".query"
}
}
rlm_sql (psksql): Driver rlm_sql_sqlite (module rlm_sql_sqlite) loaded and linked
instantiate {
}
# Instantiating module "reject" from file /etc/raddb/mods-enabled/always
# Instantiating module "fail" from file /etc/raddb/mods-enabled/always
# Instantiating module "ok" from file /etc/raddb/mods-enabled/always
# Instantiating module "handled" from file /etc/raddb/mods-enabled/always
# Instantiating module "invalid" from file /etc/raddb/mods-enabled/always
# Instantiating module "userlock" from file /etc/raddb/mods-enabled/always
# Instantiating module "notfound" from file /etc/raddb/mods-enabled/always
# Instantiating module "noop" from file /etc/raddb/mods-enabled/always
# Instantiating module "updated" from file /etc/raddb/mods-enabled/always
# Instantiating module "attr_filter.post-proxy" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/post-proxy
# Instantiating module "attr_filter.pre-proxy" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/pre-proxy
# Instantiating module "attr_filter.access_reject" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_reject
[/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT".
[/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT".
# Instantiating module "attr_filter.access_challenge" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_challenge
# Instantiating module "attr_filter.accounting_response" from file /etc/raddb/mods-enabled/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/accounting_response
# Instantiating module "cache_eap" from file /etc/raddb/mods-enabled/cache_eap
rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked
# Instantiating module "detail" from file /etc/raddb/mods-enabled/detail
# Instantiating module "auth_log" from file /etc/raddb/mods-enabled/detail.log
rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output
# Instantiating module "reply_log" from file /etc/raddb/mods-enabled/detail.log
# Instantiating module "pre_proxy_log" from file /etc/raddb/mods-enabled/detail.log
# Instantiating module "post_proxy_log" from file /etc/raddb/mods-enabled/detail.log
# Instantiating module "eap" from file /etc/raddb/mods-enabled/eap
# Linked to sub-module rlm_eap_md5
# Linked to sub-module rlm_eap_leap
# Linked to sub-module rlm_eap_gtc
gtc {
challenge = "Password: "
auth_type = "PAP"
}
# Linked to sub-module rlm_eap_tls
tls {
tls = "tls-common"
}
tls-config tls-common {
verify_depth = 0
ca_path = "/etc/raddb/certs"
pem_file_type = yes
private_key_file = "/etc/raddb/certs/server.pem"
certificate_file = "/etc/raddb/certs/server.pem"
ca_file = "/etc/raddb/certs/ca.pem"
private_key_password = <<< secret >>>
dh_file = "/etc/raddb/certs/dh"
fragment_size = 1024
include_length = yes
auto_chain = yes
check_crl = no
check_all_crl = no
cipher_list = "DEFAULT"
cipher_server_preference = no
ecdh_curve = "prime256v1"
tls_max_version = ""
tls_min_version = "1.0"
cache {
enable = no
lifetime = 24
max_entries = 255
}
verify {
skip_if_ocsp_ok = no
}
ocsp {
enable = no
override_cert_url = yes
url = "http://127.0.0.1/ocsp/"
use_nonce = yes
timeout = 0
softfail = no
}
}
# Linked to sub-module rlm_eap_ttls
ttls {
tls = "tls-common"
default_eap_type = "md5"
copy_request_to_tunnel = no
use_tunneled_reply = no
virtual_server = "inner-tunnel"
include_length = yes
require_client_cert = no
}
tls: Using cached TLS configuration from previous invocation
# Linked to sub-module rlm_eap_peap
peap {
tls = "tls-common"
default_eap_type = "mschapv2"
copy_request_to_tunnel = no
use_tunneled_reply = no
proxy_tunneled_request_as_eap = yes
virtual_server = "inner-tunnel"
soh = no
require_client_cert = no
}
tls: Using cached TLS configuration from previous invocation
# Linked to sub-module rlm_eap_mschapv2
mschapv2 {
with_ntdomain_hack = no
send_error = no
}
# Instantiating module "expiration" from file /etc/raddb/mods-enabled/expiration
# Instantiating module "files" from file /etc/raddb/mods-enabled/files
reading pairlist file /etc/raddb/mods-config/files/authorize
reading pairlist file /etc/raddb/mods-config/files/accounting
reading pairlist file /etc/raddb/mods-config/files/pre-proxy
# Instantiating module "linelog" from file /etc/raddb/mods-enabled/linelog
# Instantiating module "log_accounting" from file /etc/raddb/mods-enabled/linelog
# Instantiating module "logintime" from file /etc/raddb/mods-enabled/logintime
# Instantiating module "mschap" from file /etc/raddb/mods-enabled/mschap
rlm_mschap (mschap): using internal authentication
# Instantiating module "pap" from file /etc/raddb/mods-enabled/pap
# Instantiating module "etc_passwd" from file /etc/raddb/mods-enabled/passwd
rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no
# Instantiating module "preprocess" from file /etc/raddb/mods-enabled/preprocess
reading pairlist file /etc/raddb/mods-config/preprocess/huntgroups
reading pairlist file /etc/raddb/mods-config/preprocess/hints
# Instantiating module "IPASS" from file /etc/raddb/mods-enabled/realm
# Instantiating module "suffix" from file /etc/raddb/mods-enabled/realm
# Instantiating module "realmpercent" from file /etc/raddb/mods-enabled/realm
# Instantiating module "ntdomain" from file /etc/raddb/mods-enabled/realm
# Instantiating module "psksql" from file /etc/raddb/mods-enabled/abfab_psk_sql
rlm_sql_sqlite: libsqlite version: 3.7.17
sqlite {
filename = "/var/lib/trust_router/keys"
busy_timeout = 200
}
rlm_sql (psksql): Attempting to connect to database "radius"
rlm_sql (psksql): Initialising connection pool
pool {
start = 5
min = 5
max = 10
spare = 3
uses = 0
lifetime = 0
cleanup_interval = 30
idle_timeout = 60
retry_delay = 1
spread = no
}
rlm_sql (psksql): Opening additional connection (0), 1 of 10 pending slots used
rlm_sql_sqlite: Opening SQLite database "/var/lib/trust_router/keys"
rlm_sql (psksql): Opening additional connection (1), 1 of 9 pending slots used
rlm_sql_sqlite: Opening SQLite database "/var/lib/trust_router/keys"
rlm_sql (psksql): Opening additional connection (2), 1 of 8 pending slots used
rlm_sql_sqlite: Opening SQLite database "/var/lib/trust_router/keys"
rlm_sql (psksql): Opening additional connection (3), 1 of 7 pending slots used
rlm_sql_sqlite: Opening SQLite database "/var/lib/trust_router/keys"
rlm_sql (psksql): Opening additional connection (4), 1 of 6 pending slots used
rlm_sql_sqlite: Opening SQLite database "/var/lib/trust_router/keys"
} # modules
radiusd: #### Loading Virtual Servers ####
server { # from file /etc/raddb/radiusd.conf
} # server
server channel_bindings { # from file /etc/raddb/sites-enabled/channel_bindings
# Loading authorize {...}
} # server channel_bindings
server default { # from file /etc/raddb/sites-enabled/default
# Loading authenticate {...}
# Loading authorize {...}
Ignoring "sql" (see raddb/mods-available/README.rst)
Ignoring "ldap" (see raddb/mods-available/README.rst)
# Loading preacct {...}
# Loading accounting {...}
# Loading post-proxy {...}
# Loading post-auth {...}
} # server default
server inner-tunnel { # from file /etc/raddb/sites-enabled/inner-tunnel
# Loading authenticate {...}
# Loading authorize {...}
# Loading session {...}
# Loading post-proxy {...}
# Loading post-auth {...}
} # server inner-tunnel
server abfab-idp { # from file /etc/raddb/sites-enabled/abfab-tr-idp
# Loading authenticate {...}
# Loading authorize {...}
# Loading post-proxy {...}
# Loading post-auth {...}
} # server abfab-idp
thread pool {
start_servers = 5
max_servers = 32
min_spare_servers = 3
max_spare_servers = 10
max_requests_per_server = 0
cleanup_delay = 5
max_queue_size = 65536
auto_limit_acct = no
}
Thread spawned new child 1. Total threads in pool: 1
Thread spawned new child 2. Total threads in pool: 2
Thread spawned new child 3. Total threads in pool: 3
Thread spawned new child 4. Total threads in pool: 4
Thread spawned new child 5. Total threads in pool: 5
Thread pool initialized
radiusd: #### Opening IP addresses and Ports ####
listen {
type = "auth"
virtual_server = "abfab-idp"
ipaddr = *
port = 2083
proto = "tcp"
tls {
verify_depth = 0
ca_path = "/etc/raddb/certs"
pem_file_type = yes
private_key_file = "/etc/raddb/certs/server.key"
certificate_file = "/etc/raddb/certs/server.pem"
ca_file = "/etc/raddb/certs/ca.pem"
private_key_password = <<< secret >>>
psk_query = "%{psksql:select hex(key) from psk_keys where keyid = '%{TLS-PSK-Identity}'}"
dh_file = "/etc/raddb/certs/dh"
fragment_size = 8192
include_length = yes
auto_chain = yes
check_crl = no
check_all_crl = no
cipher_list = "DEFAULT"
require_client_cert = yes
ecdh_curve = "prime256v1"
tls_max_version = ""
tls_min_version = "1.0"
cache {
enable = no
lifetime = 24
name = "abfab-tls"
max_entries = 255
}
verify {
skip_if_ocsp_ok = no
}
ocsp {
enable = no
override_cert_url = no
use_nonce = yes
timeout = 0
softfail = no
}
}
Thread 4 waiting to be assigned a request
Thread 5 waiting to be assigned a request
Thread 1 waiting to be assigned a request
Thread 2 waiting to be assigned a request
Thread 3 waiting to be assigned a request
clients = "radsec-abfab"
client default {
ipaddr = 0.0.0.0/0
require_message_authenticator = no
proto = "tls"
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
}
listen {
type = "auth"
ipaddr = *
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "acct"
ipaddr = *
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "auth"
ipv6addr = ::
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "acct"
ipv6addr = ::
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "auth"
ipaddr = 127.0.0.1
port = 18120
}
Listening on auth proto tcp address * port 2083 (TLS) bound to server abfab-idp
Listening on auth address * port 1812 bound to server default
Listening on acct address * port 1813 bound to server default
Listening on auth address :: port 1812 bound to server default
Listening on acct address :: port 1813 bound to server default
Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel
Listening on proxy address * port 38341
Listening on proxy address :: port 43559
Ready to process requests
... new connection request on TCP socket
Listening on auth from client (13.94.115.212, 48186) -> (*, 2083, virtual-server=abfab-idp)
Waking up in 0.7 seconds.
(0) Initiating new EAP-TLS session
(0) Setting verify mode to require certificate from client
(0) (other): before/accept initialization
(0) TLS_accept: before/accept initialization
(0) <<< recv TLS 1.2 [length 0060]
(0) TLS_accept: SSLv3 read client hello A
(0) >>> send TLS 1.2 [length 0036]
(0) TLS_accept: SSLv3 write server hello A
(0) >>> send TLS 1.2 [length 0004]
(0) TLS_accept: SSLv3 write server done A
(0) TLS_accept: SSLv3 flush data
(0) TLS_accept: SSLv3 read client certificate A
(0) TLS_accept: Need to read more data: SSLv3 read client key exchange A
(0) TLS_accept: Need to read more data: SSLv3 read client key exchange A
(0) In SSL Handshake Phase
(0) In SSL Accept mode
Waking up in 0.7 seconds.
(0) <<< recv TLS 1.2 [length 0010]
rlm_sql (psksql): Reserved connection (0)
(0) Executing select query: select hex(key) from psk_keys where keyid = 'key-4e72e5'
rlm_sql (psksql): Released connection (0)
(0) EXPAND %{psksql:select hex(key) from psk_keys where keyid = '%{TLS-PSK-Identity}'}
(0) --> 544233A38D055202F75127A33B3EBD5BA9563978C788959361BD61D746EF6DCF82580789031CDDDEF3A27B46C108F678807500B4B9A5578A513E5148A1B1588DF2AD347A90F371468309F1C5C217B41C7B8188FECD1D09A378FA2BA8A858C4A230ECF721AADB4C32721CACBE48F23FD29EE8F3C97DA2BF954CFED68FC89247921570531BD23F2CAAF9E02FFA0344A0C8F2423EBC7CC76BF165843F985EA25198663C5971529BB415E6F70B9BA871B0FD172D36B37ABB4C71D88EF04D2AE6FD00795F53DD4D12D725FA6570BDE2CDAF116FA48BA8622BED439CB1CC7ED59D872F090046F7BEBCE9FDE0256E1AB939BA8401A37D9C5AB53B437CE1635F1EE71D21
(0) TLS_accept: SSLv3 read client key exchange A
(0) TLS_accept: SSLv3 read certificate verify A
(0) <<< recv TLS 1.2 [length 0001]
(0) <<< recv TLS 1.2 [length 0010]
(0) TLS_accept: SSLv3 read finished A
(0) >>> send TLS 1.2 [length 0001]
(0) TLS_accept: SSLv3 write change cipher spec A
(0) >>> send TLS 1.2 [length 0010]
(0) TLS_accept: SSLv3 write finished A
(0) TLS_accept: SSLv3 flush data
(0) (other): SSL negotiation finished successfully
(0) SSL Connection Established
Waking up in 0.7 seconds.
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=222, length=186
Threads: total/active/spare threads = 5/0/5
Waking up in 0.3 seconds.
Thread 5 got semaphore
Thread 5 handling request 0, (1 handled so far)
(0) Retrieved psk identity: key-4e72e5
(0) Received Access-Request Id 222 from 13.94.115.212:48186 to 0.0.0.0:2083 length 186
(0) TLS-PSK-Identity := "key-4e72e5"
(0) User-Name = "@idp.test.assent"
(0) EAP-Message = 0x0200001501406964702e746573742e617373656e74
(0) Message-Authenticator = 0x904db79a53aa1ee03a4a72f2e960f441
(0) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(0) Trust-Router-COI = "apc.test.assent"
(0) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(0) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(0) NAS-IP-Address = 127.0.0.1
(0) Proxy-State = 0x30
(0) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(0) authorize {
(0) policy psk_authorize {
(0) if (&TLS-PSK-Identity) {
(0) if (&TLS-PSK-Identity) -> TRUE
(0) if (&TLS-PSK-Identity) {
(0) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (1)
(0) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (1)
(0) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(0) --> key-4e72e5
(0) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(0) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(0) ... skipping else: Preceding "if" was taken
(0) } # if (&TLS-PSK-Identity) = notfound
(0) } # policy psk_authorize = notfound
(0) policy abfab_client_check {
(0) if ("%{client:gss_acceptor_host_name}") {
(0) EXPAND %{client:gss_acceptor_host_name}
(0) -->
(0) if ("%{client:gss_acceptor_host_name}") -> FALSE
(0) if ("%{client:trust_router_coi}") {
(0) EXPAND %{client:trust_router_coi}
(0) --> apc.test.assent
(0) if ("%{client:trust_router_coi}") -> TRUE
(0) if ("%{client:trust_router_coi}") {
(0) update request {
(0) EXPAND %{client:trust_router_coi}
(0) --> apc.test.assent
(0) Trust-Router-COI := apc.test.assent
(0) } # update request = noop
(0) } # if ("%{client:trust_router_coi}") = noop
(0) if ("%{client:gss_acceptor_realm_name}") {
(0) EXPAND %{client:gss_acceptor_realm_name}
(0) --> assent-fr-idp.test.assent
(0) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(0) if ("%{client:gss_acceptor_realm_name}") {
(0) update request {
(0) EXPAND %{client:gss_acceptor_realm_name}
(0) --> assent-fr-idp.test.assent
(0) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(0) } # update request = noop
(0) } # if ("%{client:gss_acceptor_realm_name}") = noop
(0) if ("%{client:gss_acceptor_service_name}") {
(0) EXPAND %{client:gss_acceptor_service_name}
(0) -->
(0) if ("%{client:gss_acceptor_service_name}") -> FALSE
(0) } # policy abfab_client_check = noop
(0) policy filter_username {
(0) if (&User-Name) {
(0) if (&User-Name) -> TRUE
(0) if (&User-Name) {
(0) if (&User-Name =~ / /) {
(0) if (&User-Name =~ / /) -> FALSE
(0) if (&User-Name =~ /@[^@]*@/ ) {
(0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(0) if (&User-Name =~ /\.\./ ) {
(0) if (&User-Name =~ /\.\./ ) -> FALSE
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(0) if (&User-Name =~ /\.$/) {
(0) if (&User-Name =~ /\.$/) -> FALSE
(0) if (&User-Name =~ /@\./) {
(0) if (&User-Name =~ /@\./) -> FALSE
(0) } # if (&User-Name) = noop
(0) } # policy filter_username = noop
(0) [preprocess] = ok
(0) suffix: Checking for suffix after "@"
(0) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(0) suffix: No trust router configured, skipping dynamic realm lookup
(0) suffix: Found realm "idp.test.assent"
(0) suffix: Adding Stripped-User-Name = ""
(0) suffix: Adding Realm = "idp.test.assent"
(0) suffix: Authentication realm is LOCAL
(0) [suffix] = ok
(0) eap: Peer sent EAP Response (code 2) ID 0 length 21
(0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(0) [eap] = ok
(0) } # authorize = ok
(0) Found Auth-Type = eap
(0) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(0) authenticate {
(0) eap: Peer sent packet with method EAP Identity (1)
(0) eap: Calling submodule eap_ttls to process data
(0) eap_ttls: Initiating new EAP-TLS session
(0) eap_ttls: [eaptls start] = request
(0) eap: Sending EAP Request (code 1) ID 1 length 6
(0) eap: EAP session adding &reply:State = 0x99ee34c099ef2160
(0) [eap] = handled
(0) } # authenticate = handled
(0) Using Post-Auth-Type Challenge
(0) Post-Auth-Type sub-section not found. Ignoring.
(0) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(0) Sent Access-Challenge Id 222 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(0) EAP-Message = 0x010100061520
(0) Message-Authenticator = 0x00000000000000000000000000000000
(0) State = 0x99ee34c099ef21606abcbf8df3266bc7
(0) Proxy-State = 0x30
(0) Finished request
Thread 5 waiting to be assigned a request
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=207, length=496
Waking up in 0.2 seconds.
Thread 4 got semaphore
Thread 4 handling request 1, (1 handled so far)
(1) Retrieved psk identity: key-4e72e5
(1) Received Access-Request Id 207 from 13.94.115.212:48186 to 0.0.0.0:2083 length 496
(1) TLS-PSK-Identity := "key-4e72e5"
(1) User-Name = "@idp.test.assent"
(1) EAP-Message = 0x020101371500160301012c0100012803032511bb54ecd0c2c9f87ce917b94c1a2a653ee2f53266fffc75406d78eac6a4b10000aac030c02cc028c024c014c00a00a500a300a1009f006b006a0069006800390038003700360088008700860085c032c02ec02ac026c00fc005009d003d00350084c02fc0
(1) State = 0x99ee34c099ef21606abcbf8df3266bc7
(1) Message-Authenticator = 0x2f4cf0aaa31a35695a73957ae5e0a21f
(1) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(1) Trust-Router-COI = "apc.test.assent"
(1) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(1) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(1) NAS-IP-Address = 127.0.0.1
(1) Proxy-State = 0x30
(1) session-state: No cached attributes
(1) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(1) authorize {
(1) policy psk_authorize {
(1) if (&TLS-PSK-Identity) {
(1) if (&TLS-PSK-Identity) -> TRUE
(1) if (&TLS-PSK-Identity) {
(1) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (2)
(1) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (2)
(1) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(1) --> key-4e72e5
(1) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(1) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(1) ... skipping else: Preceding "if" was taken
(1) } # if (&TLS-PSK-Identity) = notfound
(1) } # policy psk_authorize = notfound
(1) policy abfab_client_check {
(1) if ("%{client:gss_acceptor_host_name}") {
(1) EXPAND %{client:gss_acceptor_host_name}
(1) -->
(1) if ("%{client:gss_acceptor_host_name}") -> FALSE
(1) if ("%{client:trust_router_coi}") {
(1) EXPAND %{client:trust_router_coi}
(1) --> apc.test.assent
(1) if ("%{client:trust_router_coi}") -> TRUE
(1) if ("%{client:trust_router_coi}") {
(1) update request {
(1) EXPAND %{client:trust_router_coi}
(1) --> apc.test.assent
(1) Trust-Router-COI := apc.test.assent
(1) } # update request = noop
(1) } # if ("%{client:trust_router_coi}") = noop
(1) if ("%{client:gss_acceptor_realm_name}") {
(1) EXPAND %{client:gss_acceptor_realm_name}
(1) --> assent-fr-idp.test.assent
(1) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(1) if ("%{client:gss_acceptor_realm_name}") {
(1) update request {
(1) EXPAND %{client:gss_acceptor_realm_name}
(1) --> assent-fr-idp.test.assent
(1) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(1) } # update request = noop
(1) } # if ("%{client:gss_acceptor_realm_name}") = noop
(1) if ("%{client:gss_acceptor_service_name}") {
(1) EXPAND %{client:gss_acceptor_service_name}
(1) -->
(1) if ("%{client:gss_acceptor_service_name}") -> FALSE
(1) } # policy abfab_client_check = noop
(1) policy filter_username {
(1) if (&User-Name) {
(1) if (&User-Name) -> TRUE
(1) if (&User-Name) {
(1) if (&User-Name =~ / /) {
(1) if (&User-Name =~ / /) -> FALSE
(1) if (&User-Name =~ /@[^@]*@/ ) {
(1) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(1) if (&User-Name =~ /\.\./ ) {
(1) if (&User-Name =~ /\.\./ ) -> FALSE
(1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(1) if (&User-Name =~ /\.$/) {
(1) if (&User-Name =~ /\.$/) -> FALSE
(1) if (&User-Name =~ /@\./) {
(1) if (&User-Name =~ /@\./) -> FALSE
(1) } # if (&User-Name) = noop
(1) } # policy filter_username = noop
(1) [preprocess] = ok
(1) suffix: Checking for suffix after "@"
(1) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(1) suffix: No trust router configured, skipping dynamic realm lookup
(1) suffix: Found realm "idp.test.assent"
(1) suffix: Adding Stripped-User-Name = ""
(1) suffix: Adding Realm = "idp.test.assent"
(1) suffix: Authentication realm is LOCAL
(1) [suffix] = ok
(1) eap: Peer sent EAP Response (code 2) ID 1 length 311
(1) eap: Continuing tunnel setup
(1) [eap] = ok
(1) } # authorize = ok
(1) Found Auth-Type = eap
(1) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(1) authenticate {
(1) eap: Expiring EAP session with state 0x99ee34c099ef2160
(1) eap: Finished EAP session with state 0x99ee34c099ef2160
(1) eap: Previous EAP request found for state 0x99ee34c099ef2160, released from the list
(1) eap: Peer sent packet with method EAP TTLS (21)
(1) eap: Calling submodule eap_ttls to process data
(1) eap_ttls: Authenticate
(1) eap_ttls: Continuing EAP-TLS
(1) eap_ttls: Got final TLS record fragment (305 bytes)
(1) eap_ttls: WARNING: Total received TLS record fragments (305 bytes), does not equal indicated TLS record length (0 bytes)
(1) eap_ttls: [eaptls verify] = ok
(1) eap_ttls: Done initial handshake
(1) eap_ttls: (other): before/accept initialization
(1) eap_ttls: TLS_accept: before/accept initialization
(1) eap_ttls: <<< recv TLS 1.2 [length 012c]
(1) eap_ttls: TLS_accept: SSLv3 read client hello A
(1) eap_ttls: >>> send TLS 1.2 [length 003e]
(1) eap_ttls: TLS_accept: SSLv3 write server hello A
(1) eap_ttls: >>> send TLS 1.2 [length 09f2]
(1) eap_ttls: TLS_accept: SSLv3 write certificate A
(1) eap_ttls: >>> send TLS 1.2 [length 014d]
(1) eap_ttls: TLS_accept: SSLv3 write key exchange A
(1) eap_ttls: >>> send TLS 1.2 [length 0004]
(1) eap_ttls: TLS_accept: SSLv3 write server done A
(1) eap_ttls: TLS_accept: SSLv3 flush data
(1) eap_ttls: TLS_accept: SSLv3 read client certificate A
(1) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client key exchange A
(1) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client key exchange A
(1) eap_ttls: In SSL Handshake Phase
(1) eap_ttls: In SSL Accept mode
(1) eap_ttls: [eaptls process] = handled
(1) eap: Sending EAP Request (code 1) ID 2 length 1004
(1) eap: EAP session adding &reply:State = 0x99ee34c098ec2160
(1) [eap] = handled
(1) } # authenticate = handled
(1) Using Post-Auth-Type Challenge
(1) Post-Auth-Type sub-section not found. Ignoring.
(1) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(1) Sent Access-Challenge Id 207 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(1) EAP-Message = 0x010203ec15c000000b95160303003e0200003a030303ad08db91f444207565cdeeb5e9c7c4e268921916965c0dd035e96a1d73e4e100c030000012ff01000100000b000403000102000f00010116030309f20b0009ee0009eb00044e3082044a30820332a003020102020101300d06092a864886f70d01
(1) Message-Authenticator = 0x00000000000000000000000000000000
(1) State = 0x99ee34c098ec21606abcbf8df3266bc7
(1) Proxy-State = 0x30
(1) Finished request
Thread 4 waiting to be assigned a request
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=84, length=189
Waking up in 0.2 seconds.
Thread 3 got semaphore
Thread 3 handling request 2, (1 handled so far)
(2) Retrieved psk identity: key-4e72e5
(2) Received Access-Request Id 84 from 13.94.115.212:48186 to 0.0.0.0:2083 length 189
(2) TLS-PSK-Identity := "key-4e72e5"
(2) User-Name = "@idp.test.assent"
(2) EAP-Message = 0x020200061500
(2) State = 0x99ee34c098ec21606abcbf8df3266bc7
(2) Message-Authenticator = 0x3b0e06a072a1c513cd23499e50dec081
(2) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(2) Trust-Router-COI = "apc.test.assent"
(2) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(2) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(2) NAS-IP-Address = 127.0.0.1
(2) Proxy-State = 0x30
(2) session-state: No cached attributes
(2) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(2) authorize {
(2) policy psk_authorize {
(2) if (&TLS-PSK-Identity) {
(2) if (&TLS-PSK-Identity) -> TRUE
(2) if (&TLS-PSK-Identity) {
(2) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (3)
(2) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (3)
(2) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(2) --> key-4e72e5
(2) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(2) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(2) ... skipping else: Preceding "if" was taken
(2) } # if (&TLS-PSK-Identity) = notfound
(2) } # policy psk_authorize = notfound
(2) policy abfab_client_check {
(2) if ("%{client:gss_acceptor_host_name}") {
(2) EXPAND %{client:gss_acceptor_host_name}
(2) -->
(2) if ("%{client:gss_acceptor_host_name}") -> FALSE
(2) if ("%{client:trust_router_coi}") {
(2) EXPAND %{client:trust_router_coi}
(2) --> apc.test.assent
(2) if ("%{client:trust_router_coi}") -> TRUE
(2) if ("%{client:trust_router_coi}") {
(2) update request {
(2) EXPAND %{client:trust_router_coi}
(2) --> apc.test.assent
(2) Trust-Router-COI := apc.test.assent
(2) } # update request = noop
(2) } # if ("%{client:trust_router_coi}") = noop
(2) if ("%{client:gss_acceptor_realm_name}") {
(2) EXPAND %{client:gss_acceptor_realm_name}
(2) --> assent-fr-idp.test.assent
(2) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(2) if ("%{client:gss_acceptor_realm_name}") {
(2) update request {
(2) EXPAND %{client:gss_acceptor_realm_name}
(2) --> assent-fr-idp.test.assent
(2) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(2) } # update request = noop
(2) } # if ("%{client:gss_acceptor_realm_name}") = noop
(2) if ("%{client:gss_acceptor_service_name}") {
(2) EXPAND %{client:gss_acceptor_service_name}
(2) -->
(2) if ("%{client:gss_acceptor_service_name}") -> FALSE
(2) } # policy abfab_client_check = noop
(2) policy filter_username {
(2) if (&User-Name) {
(2) if (&User-Name) -> TRUE
(2) if (&User-Name) {
(2) if (&User-Name =~ / /) {
(2) if (&User-Name =~ / /) -> FALSE
(2) if (&User-Name =~ /@[^@]*@/ ) {
(2) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(2) if (&User-Name =~ /\.\./ ) {
(2) if (&User-Name =~ /\.\./ ) -> FALSE
(2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(2) if (&User-Name =~ /\.$/) {
(2) if (&User-Name =~ /\.$/) -> FALSE
(2) if (&User-Name =~ /@\./) {
(2) if (&User-Name =~ /@\./) -> FALSE
(2) } # if (&User-Name) = noop
(2) } # policy filter_username = noop
(2) [preprocess] = ok
(2) suffix: Checking for suffix after "@"
(2) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(2) suffix: No trust router configured, skipping dynamic realm lookup
(2) suffix: Found realm "idp.test.assent"
(2) suffix: Adding Stripped-User-Name = ""
(2) suffix: Adding Realm = "idp.test.assent"
(2) suffix: Authentication realm is LOCAL
(2) [suffix] = ok
(2) eap: Peer sent EAP Response (code 2) ID 2 length 6
(2) eap: Continuing tunnel setup
(2) [eap] = ok
(2) } # authorize = ok
(2) Found Auth-Type = eap
(2) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(2) authenticate {
(2) eap: Expiring EAP session with state 0x99ee34c098ec2160
(2) eap: Finished EAP session with state 0x99ee34c098ec2160
(2) eap: Previous EAP request found for state 0x99ee34c098ec2160, released from the list
(2) eap: Peer sent packet with method EAP TTLS (21)
(2) eap: Calling submodule eap_ttls to process data
(2) eap_ttls: Authenticate
(2) eap_ttls: Continuing EAP-TLS
(2) eap_ttls: Peer ACKed our handshake fragment
(2) eap_ttls: [eaptls verify] = request
(2) eap_ttls: [eaptls process] = handled
(2) eap: Sending EAP Request (code 1) ID 3 length 1004
(2) eap: EAP session adding &reply:State = 0x99ee34c09bed2160
(2) [eap] = handled
(2) } # authenticate = handled
(2) Using Post-Auth-Type Challenge
(2) Post-Auth-Type sub-section not found. Ignoring.
(2) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(2) Sent Access-Challenge Id 84 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(2) EAP-Message = 0x010303ec15c000000b957bf00fb3723fe2b582405cc3a74e7ab536ae9cc835c2c003636f275ff298982c68049eaa0c6b20bcc571dee510518708b05d49740ead4b0533a3f7d6198257bd78d381cd8ee99c995fa5e0091214ce297ae2a75977b468b039b838054d458a86f65bb0ae89d85b70facb7972d5
(2) Message-Authenticator = 0x00000000000000000000000000000000
(2) State = 0x99ee34c09bed21606abcbf8df3266bc7
(2) Proxy-State = 0x30
(2) Finished request
Thread 3 waiting to be assigned a request
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=66, length=189
Waking up in 0.1 seconds.
Thread 2 got semaphore
Thread 2 handling request 3, (1 handled so far)
(3) Retrieved psk identity: key-4e72e5
(3) Received Access-Request Id 66 from 13.94.115.212:48186 to 0.0.0.0:2083 length 189
(3) TLS-PSK-Identity := "key-4e72e5"
(3) User-Name = "@idp.test.assent"
(3) EAP-Message = 0x020300061500
(3) State = 0x99ee34c09bed21606abcbf8df3266bc7
(3) Message-Authenticator = 0x3e92ccb72595994fbf44f101ea9b9e7f
(3) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(3) Trust-Router-COI = "apc.test.assent"
(3) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(3) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(3) NAS-IP-Address = 127.0.0.1
(3) Proxy-State = 0x30
(3) session-state: No cached attributes
(3) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(3) authorize {
(3) policy psk_authorize {
(3) if (&TLS-PSK-Identity) {
(3) if (&TLS-PSK-Identity) -> TRUE
(3) if (&TLS-PSK-Identity) {
(3) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (4)
(3) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (4)
(3) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(3) --> key-4e72e5
(3) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(3) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(3) ... skipping else: Preceding "if" was taken
(3) } # if (&TLS-PSK-Identity) = notfound
(3) } # policy psk_authorize = notfound
(3) policy abfab_client_check {
(3) if ("%{client:gss_acceptor_host_name}") {
(3) EXPAND %{client:gss_acceptor_host_name}
(3) -->
(3) if ("%{client:gss_acceptor_host_name}") -> FALSE
(3) if ("%{client:trust_router_coi}") {
(3) EXPAND %{client:trust_router_coi}
(3) --> apc.test.assent
(3) if ("%{client:trust_router_coi}") -> TRUE
(3) if ("%{client:trust_router_coi}") {
(3) update request {
(3) EXPAND %{client:trust_router_coi}
(3) --> apc.test.assent
(3) Trust-Router-COI := apc.test.assent
(3) } # update request = noop
(3) } # if ("%{client:trust_router_coi}") = noop
(3) if ("%{client:gss_acceptor_realm_name}") {
(3) EXPAND %{client:gss_acceptor_realm_name}
(3) --> assent-fr-idp.test.assent
(3) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(3) if ("%{client:gss_acceptor_realm_name}") {
(3) update request {
(3) EXPAND %{client:gss_acceptor_realm_name}
(3) --> assent-fr-idp.test.assent
(3) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(3) } # update request = noop
(3) } # if ("%{client:gss_acceptor_realm_name}") = noop
(3) if ("%{client:gss_acceptor_service_name}") {
(3) EXPAND %{client:gss_acceptor_service_name}
(3) -->
(3) if ("%{client:gss_acceptor_service_name}") -> FALSE
(3) } # policy abfab_client_check = noop
(3) policy filter_username {
(3) if (&User-Name) {
(3) if (&User-Name) -> TRUE
(3) if (&User-Name) {
(3) if (&User-Name =~ / /) {
(3) if (&User-Name =~ / /) -> FALSE
(3) if (&User-Name =~ /@[^@]*@/ ) {
(3) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(3) if (&User-Name =~ /\.\./ ) {
(3) if (&User-Name =~ /\.\./ ) -> FALSE
(3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(3) if (&User-Name =~ /\.$/) {
(3) if (&User-Name =~ /\.$/) -> FALSE
(3) if (&User-Name =~ /@\./) {
(3) if (&User-Name =~ /@\./) -> FALSE
(3) } # if (&User-Name) = noop
(3) } # policy filter_username = noop
(3) [preprocess] = ok
(3) suffix: Checking for suffix after "@"
(3) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(3) suffix: No trust router configured, skipping dynamic realm lookup
(3) suffix: Found realm "idp.test.assent"
(3) suffix: Adding Stripped-User-Name = ""
(3) suffix: Adding Realm = "idp.test.assent"
(3) suffix: Authentication realm is LOCAL
(3) [suffix] = ok
(3) eap: Peer sent EAP Response (code 2) ID 3 length 6
(3) eap: Continuing tunnel setup
(3) [eap] = ok
(3) } # authorize = ok
(3) Found Auth-Type = eap
(3) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(3) authenticate {
(3) eap: Expiring EAP session with state 0x99ee34c09bed2160
(3) eap: Finished EAP session with state 0x99ee34c09bed2160
(3) eap: Previous EAP request found for state 0x99ee34c09bed2160, released from the list
(3) eap: Peer sent packet with method EAP TTLS (21)
(3) eap: Calling submodule eap_ttls to process data
(3) eap_ttls: Authenticate
(3) eap_ttls: Continuing EAP-TLS
(3) eap_ttls: Peer ACKed our handshake fragment
(3) eap_ttls: [eaptls verify] = request
(3) eap_ttls: [eaptls process] = handled
(3) eap: Sending EAP Request (code 1) ID 4 length 987
(3) eap: EAP session adding &reply:State = 0x99ee34c09aea2160
(3) [eap] = handled
(3) } # authenticate = handled
(3) Using Post-Auth-Type Challenge
(3) Post-Auth-Type sub-section not found. Ignoring.
(3) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(3) Sent Access-Challenge Id 66 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(3) EAP-Message = 0x010403db158000000b95663ceff515d00535b798c82edd71a7591a6517308201020603551d230481fa3081f780149c663ceff515d00535b798c82edd71a7591a6517a181d3a481d03081cd310b30090603550406130247423114301206035504080c0b4f78666f726473686972653110300e0603550407
(3) Message-Authenticator = 0x00000000000000000000000000000000
(3) State = 0x99ee34c09aea21606abcbf8df3266bc7
(3) Proxy-State = 0x30
(3) Finished request
Thread 2 waiting to be assigned a request
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=35, length=315
Thread 1 got semaphore
Thread 1 handling request 4, (1 handled so far)
(4) Retrieved psk identity: key-4e72e5
(4) Received Access-Request Id 35 from 13.94.115.212:48186 to 0.0.0.0:2083 length 315
(4) TLS-PSK-Identity := "key-4e72e5"
(4) User-Name = "@idp.test.assent"
(4) EAP-Message = 0x020400841500160303004610000042410468d99894f17aa98dc8611a7b2dcbe6872feb9ce4d67306a7de57e9896578636dcb96edb9f27f89ac4d37d9998436714567010fefd6c2ae4b28c989a974acf6311403030001011603030028a14d973586558f26407aea94cf8bc17a44b4c3819b349ab450a451
(4) State = 0x99ee34c09aea21606abcbf8df3266bc7
(4) Message-Authenticator = 0x5b48baac1553d9ae88fe0e42b7ddb874
(4) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(4) Trust-Router-COI = "apc.test.assent"
(4) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(4) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(4) NAS-IP-Address = 127.0.0.1
(4) Proxy-State = 0x30
(4) session-state: No cached attributes
(4) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(4) authorize {
(4) policy psk_authorize {
(4) if (&TLS-PSK-Identity) {
(4) if (&TLS-PSK-Identity) -> TRUE
(4) if (&TLS-PSK-Identity) {
(4) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (0)
(4) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (0)
(4) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(4) --> key-4e72e5
(4) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(4) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(4) ... skipping else: Preceding "if" was taken
(4) } # if (&TLS-PSK-Identity) = notfound
(4) } # policy psk_authorize = notfound
(4) policy abfab_client_check {
(4) if ("%{client:gss_acceptor_host_name}") {
(4) EXPAND %{client:gss_acceptor_host_name}
(4) -->
(4) if ("%{client:gss_acceptor_host_name}") -> FALSE
(4) if ("%{client:trust_router_coi}") {
(4) EXPAND %{client:trust_router_coi}
(4) --> apc.test.assent
(4) if ("%{client:trust_router_coi}") -> TRUE
(4) if ("%{client:trust_router_coi}") {
(4) update request {
(4) EXPAND %{client:trust_router_coi}
(4) --> apc.test.assent
(4) Trust-Router-COI := apc.test.assent
(4) } # update request = noop
(4) } # if ("%{client:trust_router_coi}") = noop
(4) if ("%{client:gss_acceptor_realm_name}") {
(4) EXPAND %{client:gss_acceptor_realm_name}
(4) --> assent-fr-idp.test.assent
(4) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(4) if ("%{client:gss_acceptor_realm_name}") {
(4) update request {
(4) EXPAND %{client:gss_acceptor_realm_name}
(4) --> assent-fr-idp.test.assent
(4) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(4) } # update request = noop
(4) } # if ("%{client:gss_acceptor_realm_name}") = noop
(4) if ("%{client:gss_acceptor_service_name}") {
(4) EXPAND %{client:gss_acceptor_service_name}
(4) -->
(4) if ("%{client:gss_acceptor_service_name}") -> FALSE
(4) } # policy abfab_client_check = noop
(4) policy filter_username {
(4) if (&User-Name) {
(4) if (&User-Name) -> TRUE
(4) if (&User-Name) {
(4) if (&User-Name =~ / /) {
(4) if (&User-Name =~ / /) -> FALSE
(4) if (&User-Name =~ /@[^@]*@/ ) {
(4) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(4) if (&User-Name =~ /\.\./ ) {
(4) if (&User-Name =~ /\.\./ ) -> FALSE
(4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(4) if (&User-Name =~ /\.$/) {
(4) if (&User-Name =~ /\.$/) -> FALSE
(4) if (&User-Name =~ /@\./) {
(4) if (&User-Name =~ /@\./) -> FALSE
(4) } # if (&User-Name) = noop
(4) } # policy filter_username = noop
(4) [preprocess] = ok
(4) suffix: Checking for suffix after "@"
(4) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(4) suffix: No trust router configured, skipping dynamic realm lookup
(4) suffix: Found realm "idp.test.assent"
(4) suffix: Adding Stripped-User-Name = ""
(4) suffix: Adding Realm = "idp.test.assent"
(4) suffix: Authentication realm is LOCAL
(4) [suffix] = ok
(4) eap: Peer sent EAP Response (code 2) ID 4 length 132
(4) eap: Continuing tunnel setup
(4) [eap] = ok
(4) } # authorize = ok
(4) Found Auth-Type = eap
(4) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(4) authenticate {
(4) eap: Expiring EAP session with state 0x99ee34c09aea2160
(4) eap: Finished EAP session with state 0x99ee34c09aea2160
(4) eap: Previous EAP request found for state 0x99ee34c09aea2160, released from the list
(4) eap: Peer sent packet with method EAP TTLS (21)
(4) eap: Calling submodule eap_ttls to process data
(4) eap_ttls: Authenticate
(4) eap_ttls: Continuing EAP-TLS
(4) eap_ttls: [eaptls verify] = ok
(4) eap_ttls: Done initial handshake
(4) eap_ttls: <<< recv TLS 1.2 [length 0046]
(4) eap_ttls: TLS_accept: SSLv3 read client key exchange A
(4) eap_ttls: TLS_accept: SSLv3 read certificate verify A
(4) eap_ttls: <<< recv TLS 1.2 [length 0001]
(4) eap_ttls: <<< recv TLS 1.2 [length 0010]
(4) eap_ttls: TLS_accept: SSLv3 read finished A
(4) eap_ttls: >>> send TLS 1.2 [length 0001]
(4) eap_ttls: TLS_accept: SSLv3 write change cipher spec A
(4) eap_ttls: >>> send TLS 1.2 [length 0010]
(4) eap_ttls: TLS_accept: SSLv3 write finished A
(4) eap_ttls: TLS_accept: SSLv3 flush data
(4) eap_ttls: (other): SSL negotiation finished successfully
(4) eap_ttls: SSL Connection Established
(4) eap_ttls: [eaptls process] = handled
(4) eap: Sending EAP Request (code 1) ID 5 length 61
(4) eap: EAP session adding &reply:State = 0x99ee34c09deb2160
(4) [eap] = handled
(4) } # authenticate = handled
(4) Using Post-Auth-Type Challenge
(4) Post-Auth-Type sub-section not found. Ignoring.
(4) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(4) Sent Access-Challenge Id 35 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(4) EAP-Message = 0x0105003d158000000033140303000101160303002896caae9b220ab065f33cee302945123fcd3953ed0f957d23becd25f738f9749e76680a61d9f70c11
(4) Message-Authenticator = 0x00000000000000000000000000000000
(4) State = 0x99ee34c09deb21606abcbf8df3266bc7
(4) Proxy-State = 0x30
(4) Finished request
Thread 1 waiting to be assigned a request
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=183, length=250
Thread 5 got semaphore
Thread 5 handling request 5, (2 handled so far)
(5) Retrieved psk identity: key-4e72e5
(5) Received Access-Request Id 183 from 13.94.115.212:48186 to 0.0.0.0:2083 length 250
(5) TLS-PSK-Identity := "key-4e72e5"
(5) User-Name = "@idp.test.assent"
(5) EAP-Message = 0x0205004315001703030038a14d973586558f274576c0dc8704eeb292bb84e8a3c9a809552d1d923c21226ab1bdce7821ccb920d0677a6048fb272d505685d90b557e35
(5) State = 0x99ee34c09deb21606abcbf8df3266bc7
(5) Message-Authenticator = 0x77c3d8c12657209875082fd71b5b3400
(5) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(5) Trust-Router-COI = "apc.test.assent"
(5) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(5) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(5) NAS-IP-Address = 127.0.0.1
(5) Proxy-State = 0x30
(5) session-state: No cached attributes
(5) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(5) authorize {
(5) policy psk_authorize {
(5) if (&TLS-PSK-Identity) {
(5) if (&TLS-PSK-Identity) -> TRUE
(5) if (&TLS-PSK-Identity) {
(5) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (1)
(5) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (1)
(5) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(5) --> key-4e72e5
(5) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(5) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(5) ... skipping else: Preceding "if" was taken
(5) } # if (&TLS-PSK-Identity) = notfound
(5) } # policy psk_authorize = notfound
(5) policy abfab_client_check {
(5) if ("%{client:gss_acceptor_host_name}") {
(5) EXPAND %{client:gss_acceptor_host_name}
(5) -->
(5) if ("%{client:gss_acceptor_host_name}") -> FALSE
(5) if ("%{client:trust_router_coi}") {
(5) EXPAND %{client:trust_router_coi}
(5) --> apc.test.assent
(5) if ("%{client:trust_router_coi}") -> TRUE
(5) if ("%{client:trust_router_coi}") {
(5) update request {
(5) EXPAND %{client:trust_router_coi}
(5) --> apc.test.assent
(5) Trust-Router-COI := apc.test.assent
(5) } # update request = noop
(5) } # if ("%{client:trust_router_coi}") = noop
(5) if ("%{client:gss_acceptor_realm_name}") {
(5) EXPAND %{client:gss_acceptor_realm_name}
(5) --> assent-fr-idp.test.assent
(5) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(5) if ("%{client:gss_acceptor_realm_name}") {
(5) update request {
(5) EXPAND %{client:gss_acceptor_realm_name}
(5) --> assent-fr-idp.test.assent
(5) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(5) } # update request = noop
(5) } # if ("%{client:gss_acceptor_realm_name}") = noop
(5) if ("%{client:gss_acceptor_service_name}") {
(5) EXPAND %{client:gss_acceptor_service_name}
(5) -->
(5) if ("%{client:gss_acceptor_service_name}") -> FALSE
(5) } # policy abfab_client_check = noop
(5) policy filter_username {
(5) if (&User-Name) {
(5) if (&User-Name) -> TRUE
(5) if (&User-Name) {
(5) if (&User-Name =~ / /) {
(5) if (&User-Name =~ / /) -> FALSE
(5) if (&User-Name =~ /@[^@]*@/ ) {
(5) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(5) if (&User-Name =~ /\.\./ ) {
(5) if (&User-Name =~ /\.\./ ) -> FALSE
(5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(5) if (&User-Name =~ /\.$/) {
(5) if (&User-Name =~ /\.$/) -> FALSE
(5) if (&User-Name =~ /@\./) {
(5) if (&User-Name =~ /@\./) -> FALSE
(5) } # if (&User-Name) = noop
(5) } # policy filter_username = noop
(5) [preprocess] = ok
(5) suffix: Checking for suffix after "@"
(5) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(5) suffix: No trust router configured, skipping dynamic realm lookup
(5) suffix: Found realm "idp.test.assent"
(5) suffix: Adding Stripped-User-Name = ""
(5) suffix: Adding Realm = "idp.test.assent"
(5) suffix: Authentication realm is LOCAL
(5) [suffix] = ok
(5) eap: Peer sent EAP Response (code 2) ID 5 length 67
(5) eap: Continuing tunnel setup
(5) [eap] = ok
(5) } # authorize = ok
(5) Found Auth-Type = eap
(5) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(5) authenticate {
(5) eap: Expiring EAP session with state 0x99ee34c09deb2160
(5) eap: Finished EAP session with state 0x99ee34c09deb2160
(5) eap: Previous EAP request found for state 0x99ee34c09deb2160, released from the list
(5) eap: Peer sent packet with method EAP TTLS (21)
(5) eap: Calling submodule eap_ttls to process data
(5) eap_ttls: Authenticate
(5) eap_ttls: Continuing EAP-TLS
(5) eap_ttls: [eaptls verify] = ok
(5) eap_ttls: Done initial handshake
(5) eap_ttls: [eaptls process] = ok
(5) eap_ttls: Session established. Proceeding to decode tunneled attributes
(5) eap_ttls: Got tunneled request
(5) eap_ttls: EAP-Message = 0x0200001801626f62406964702e746573742e617373656e74
(5) eap_ttls: FreeRADIUS-Proxied-To = 127.0.0.1
(5) eap_ttls: Got tunneled identity of bob at idp.test.assent
(5) eap_ttls: Setting default EAP type for tunneled EAP session
(5) eap_ttls: Sending tunneled request
(5) Virtual server inner-tunnel received request
(5) EAP-Message = 0x0200001801626f62406964702e746573742e617373656e74
(5) FreeRADIUS-Proxied-To = 127.0.0.1
(5) User-Name = "bob at idp.test.assent"
(5) server inner-tunnel {
(5) # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel
(5) authorize {
(5) policy filter_username {
(5) if (&User-Name) {
(5) if (&User-Name) -> TRUE
(5) if (&User-Name) {
(5) if (&User-Name =~ / /) {
(5) if (&User-Name =~ / /) -> FALSE
(5) if (&User-Name =~ /@[^@]*@/ ) {
(5) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(5) if (&User-Name =~ /\.\./ ) {
(5) if (&User-Name =~ /\.\./ ) -> FALSE
(5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(5) if (&User-Name =~ /\.$/) {
(5) if (&User-Name =~ /\.$/) -> FALSE
(5) if (&User-Name =~ /@\./) {
(5) if (&User-Name =~ /@\./) -> FALSE
(5) } # if (&User-Name) = notfound
(5) } # policy filter_username = notfound
(5) [chap] = noop
(5) [mschap] = noop
(5) suffix: Checking for suffix after "@"
(5) suffix: Looking up realm "idp.test.assent" for User-Name = "bob at idp.test.assent"
(5) suffix: No trust router configured, skipping dynamic realm lookup
(5) suffix: Found realm "idp.test.assent"
(5) suffix: Adding Stripped-User-Name = "bob"
(5) suffix: Adding Realm = "idp.test.assent"
(5) suffix: Authentication realm is LOCAL
(5) [suffix] = ok
(5) update control {
(5) &Proxy-To-Realm := LOCAL
(5) } # update control = noop
(5) eap: Peer sent EAP Response (code 2) ID 0 length 24
(5) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(5) [eap] = ok
(5) } # authorize = ok
(5) Found Auth-Type = eap
(5) # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
(5) authenticate {
(5) eap: Peer sent packet with method EAP Identity (1)
(5) eap: Calling submodule eap_md5 to process data
(5) eap_md5: Issuing MD5 Challenge
(5) eap: Sending EAP Request (code 1) ID 1 length 22
(5) eap: EAP session adding &reply:State = 0x3c80b67c3c81b298
(5) [eap] = handled
(5) } # authenticate = handled
(5) } # server inner-tunnel
(5) Virtual server sending reply
(5) EAP-Message = 0x0101001604108601bd43f14033602f432ae5adb72d86
(5) Message-Authenticator = 0x00000000000000000000000000000000
(5) State = 0x3c80b67c3c81b298e3175f119958de79
(5) eap_ttls: Got tunneled Access-Challenge
(5) eap: Sending EAP Request (code 1) ID 6 length 71
(5) eap: EAP session adding &reply:State = 0x99ee34c09ce82160
(5) [eap] = handled
(5) } # authenticate = handled
(5) Using Post-Auth-Type Challenge
(5) Post-Auth-Type sub-section not found. Ignoring.
(5) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(5) Sent Access-Challenge Id 183 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(5) EAP-Message = 0x0106004715800000003d170303003896caae9b220ab0660e76bacafaf2fe033362766fd145e32c0aba49fca7cafcc02dd038b81e3d971f85e056212ab2c47f4bc576ee0c259234
(5) Message-Authenticator = 0x00000000000000000000000000000000
(5) State = 0x99ee34c09ce821606abcbf8df3266bc7
(5) Proxy-State = 0x30
(5) Finished request
Thread 5 waiting to be assigned a request
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=189, length=310
Thread 4 got semaphore
Thread 4 handling request 6, (2 handled so far)
(6) Retrieved psk identity: key-4e72e5
(6) Received Access-Request Id 189 from 13.94.115.212:48186 to 0.0.0.0:2083 length 310
(6) TLS-PSK-Identity := "key-4e72e5"
(6) User-Name = "@idp.test.assent"
(6) EAP-Message = 0x0206007f15001703030074a14d973586558f280dd3a2f38f398bdac90710dafb687dba8df5b7ec1e33e9b47730696aff1bb6286ab4b68994f5bdb187edd27e5e83be6a1add9436d04cc1e9c91c62663cafd68ced457bf1cedf394fb4dbbc3aee0f6015025cdbcd6d4c397e10bef466308cbf87dda67757
(6) State = 0x99ee34c09ce821606abcbf8df3266bc7
(6) Message-Authenticator = 0x98d250a4613b2c499cf8de10d2bb2229
(6) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(6) Trust-Router-COI = "apc.test.assent"
(6) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(6) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(6) NAS-IP-Address = 127.0.0.1
(6) Proxy-State = 0x30
(6) session-state: No cached attributes
(6) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(6) authorize {
(6) policy psk_authorize {
(6) if (&TLS-PSK-Identity) {
(6) if (&TLS-PSK-Identity) -> TRUE
(6) if (&TLS-PSK-Identity) {
(6) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (2)
(6) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (2)
(6) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(6) --> key-4e72e5
(6) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(6) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(6) ... skipping else: Preceding "if" was taken
(6) } # if (&TLS-PSK-Identity) = notfound
(6) } # policy psk_authorize = notfound
(6) policy abfab_client_check {
(6) if ("%{client:gss_acceptor_host_name}") {
(6) EXPAND %{client:gss_acceptor_host_name}
(6) -->
(6) if ("%{client:gss_acceptor_host_name}") -> FALSE
(6) if ("%{client:trust_router_coi}") {
(6) EXPAND %{client:trust_router_coi}
(6) --> apc.test.assent
(6) if ("%{client:trust_router_coi}") -> TRUE
(6) if ("%{client:trust_router_coi}") {
(6) update request {
(6) EXPAND %{client:trust_router_coi}
(6) --> apc.test.assent
(6) Trust-Router-COI := apc.test.assent
(6) } # update request = noop
(6) } # if ("%{client:trust_router_coi}") = noop
(6) if ("%{client:gss_acceptor_realm_name}") {
(6) EXPAND %{client:gss_acceptor_realm_name}
(6) --> assent-fr-idp.test.assent
(6) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(6) if ("%{client:gss_acceptor_realm_name}") {
(6) update request {
(6) EXPAND %{client:gss_acceptor_realm_name}
(6) --> assent-fr-idp.test.assent
(6) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(6) } # update request = noop
(6) } # if ("%{client:gss_acceptor_realm_name}") = noop
(6) if ("%{client:gss_acceptor_service_name}") {
(6) EXPAND %{client:gss_acceptor_service_name}
(6) -->
(6) if ("%{client:gss_acceptor_service_name}") -> FALSE
(6) } # policy abfab_client_check = noop
(6) policy filter_username {
(6) if (&User-Name) {
(6) if (&User-Name) -> TRUE
(6) if (&User-Name) {
(6) if (&User-Name =~ / /) {
(6) if (&User-Name =~ / /) -> FALSE
(6) if (&User-Name =~ /@[^@]*@/ ) {
(6) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(6) if (&User-Name =~ /\.\./ ) {
(6) if (&User-Name =~ /\.\./ ) -> FALSE
(6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(6) if (&User-Name =~ /\.$/) {
(6) if (&User-Name =~ /\.$/) -> FALSE
(6) if (&User-Name =~ /@\./) {
(6) if (&User-Name =~ /@\./) -> FALSE
(6) } # if (&User-Name) = noop
(6) } # policy filter_username = noop
(6) [preprocess] = ok
(6) suffix: Checking for suffix after "@"
(6) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(6) suffix: No trust router configured, skipping dynamic realm lookup
(6) suffix: Found realm "idp.test.assent"
(6) suffix: Adding Stripped-User-Name = ""
(6) suffix: Adding Realm = "idp.test.assent"
(6) suffix: Authentication realm is LOCAL
(6) [suffix] = ok
(6) eap: Peer sent EAP Response (code 2) ID 6 length 127
(6) eap: Continuing tunnel setup
(6) [eap] = ok
(6) } # authorize = ok
(6) Found Auth-Type = eap
(6) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(6) authenticate {
(6) eap: Expiring EAP session with state 0x3c80b67c3c81b298
(6) eap: Finished EAP session with state 0x99ee34c09ce82160
(6) eap: Previous EAP request found for state 0x99ee34c09ce82160, released from the list
(6) eap: Peer sent packet with method EAP TTLS (21)
(6) eap: Calling submodule eap_ttls to process data
(6) eap_ttls: Authenticate
(6) eap_ttls: Continuing EAP-TLS
(6) eap_ttls: [eaptls verify] = ok
(6) eap_ttls: Done initial handshake
(6) eap_ttls: [eaptls process] = ok
(6) eap_ttls: Session established. Proceeding to decode tunneled attributes
(6) eap_ttls: Got tunneled request
(6) eap_ttls: EAP-Channel-Binding-Message = 0x01002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(6) eap_ttls: EAP-Message = 0x020100160410f198c98646992dab6e556338cc256901
(6) eap_ttls: FreeRADIUS-Proxied-To = 127.0.0.1
(6) eap_ttls: Sending tunneled request
(6) eap_ttls: received chbind request
(6) Virtual server channel_bindings received request
(6) FreeRADIUS-Proxied-To = 127.0.0.1
(6) User-Name = "bob at idp.test.assent"
(6) GSS-Acceptor-Service-Name = "HTTP"
(6) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(6) server channel_bindings {
(6) # Executing section authorize from file /etc/raddb/sites-enabled/channel_bindings
(6) authorize {
(6) policy abfab_channel_bindings {
(6) if (&GSS-Acceptor-Service-Name && (&outer.request:GSS-Acceptor-Service-Name != &GSS-Acceptor-Service-Name)) {
(6) ERROR: Failed retrieving values required to evaluate condition
(6) if (&GSS-Acceptor-Host-Name && &outer.request:GSS-Acceptor-Host-Name != &GSS-Acceptor-Host-Name ) {
(6) if (&GSS-Acceptor-Host-Name && &outer.request:GSS-Acceptor-Host-Name != &GSS-Acceptor-Host-Name ) -> FALSE
(6) if (&GSS-Acceptor-Realm-Name && &outer.request:GSS-Acceptor-Realm-Name != &GSS-Acceptor-Realm-Name ) {
(6) if (&GSS-Acceptor-Realm-Name && &outer.request:GSS-Acceptor-Realm-Name != &GSS-Acceptor-Realm-Name ) -> FALSE
(6) if (&GSS-Acceptor-Service-Name || &GSS-Acceptor-Realm-Name || &GSS-Acceptor-Host-Name) {
(6) if (&GSS-Acceptor-Service-Name || &GSS-Acceptor-Realm-Name || &GSS-Acceptor-Host-Name) -> TRUE
(6) if (&GSS-Acceptor-Service-Name || &GSS-Acceptor-Realm-Name || &GSS-Acceptor-Host-Name) {
(6) update control {
(6) &Chbind-Response-Code := success
(6) } # update control = noop
(6) update reply {
(6) &GSS-Acceptor-Service-Name = &GSS-Acceptor-Service-Name -> 'HTTP'
(6) &GSS-Acceptor-Host-Name = &GSS-Acceptor-Host-Name -> 'service.moonshot-playpen.ti.ja.net'
(6) No attributes updated
(6) } # update reply = noop
(6) } # if (&GSS-Acceptor-Service-Name || &GSS-Acceptor-Realm-Name || &GSS-Acceptor-Host-Name) = noop
(6) [handled] = handled
(6) } # policy abfab_channel_bindings = handled
(6) } # authorize = handled
(6) } # server channel_bindings
(6) Virtual server sending reply
(6) GSS-Acceptor-Service-Name = "HTTP"
(6) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(6) Sending chbind response: code 2
(6) GSS-Acceptor-Service-Name = "HTTP"
(6) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(6) eap_ttls: sending chbind response
(6) Virtual server inner-tunnel received request
(6) EAP-Channel-Binding-Message = 0x01002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(6) EAP-Message = 0x020100160410f198c98646992dab6e556338cc256901
(6) FreeRADIUS-Proxied-To = 127.0.0.1
(6) User-Name = "bob at idp.test.assent"
(6) State = 0x3c80b67c3c81b298e3175f119958de79
(6) server inner-tunnel {
(6) session-state: No cached attributes
(6) # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel
(6) authorize {
(6) policy filter_username {
(6) if (&User-Name) {
(6) if (&User-Name) -> TRUE
(6) if (&User-Name) {
(6) if (&User-Name =~ / /) {
(6) if (&User-Name =~ / /) -> FALSE
(6) if (&User-Name =~ /@[^@]*@/ ) {
(6) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(6) if (&User-Name =~ /\.\./ ) {
(6) if (&User-Name =~ /\.\./ ) -> FALSE
(6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(6) if (&User-Name =~ /\.$/) {
(6) if (&User-Name =~ /\.$/) -> FALSE
(6) if (&User-Name =~ /@\./) {
(6) if (&User-Name =~ /@\./) -> FALSE
(6) } # if (&User-Name) = notfound
(6) } # policy filter_username = notfound
(6) [chap] = noop
(6) [mschap] = noop
(6) suffix: Checking for suffix after "@"
(6) suffix: Looking up realm "idp.test.assent" for User-Name = "bob at idp.test.assent"
(6) suffix: No trust router configured, skipping dynamic realm lookup
(6) suffix: Found realm "idp.test.assent"
(6) suffix: Adding Stripped-User-Name = "bob"
(6) suffix: Adding Realm = "idp.test.assent"
(6) suffix: Authentication realm is LOCAL
(6) [suffix] = ok
(6) update control {
(6) &Proxy-To-Realm := LOCAL
(6) } # update control = noop
(6) eap: Peer sent EAP Response (code 2) ID 1 length 22
(6) eap: No EAP Start, assuming it's an on-going EAP conversation
(6) [eap] = updated
(6) files: users: Matched entry bob at line 80
(6) [files] = ok
(6) [expiration] = noop
(6) [logintime] = noop
(6) pap: WARNING: Auth-Type already set. Not setting to PAP
(6) [pap] = noop
(6) } # authorize = updated
(6) Found Auth-Type = eap
(6) # Executing group from file /etc/raddb/sites-enabled/inner-tunnel
(6) authenticate {
(6) eap: Expiring EAP session with state 0x3c80b67c3c81b298
(6) eap: Finished EAP session with state 0x3c80b67c3c81b298
(6) eap: Previous EAP request found for state 0x3c80b67c3c81b298, released from the list
(6) eap: Peer sent packet with method EAP MD5 (4)
(6) eap: Calling submodule eap_md5 to process data
(6) eap: Sending EAP Success (code 3) ID 1 length 4
(6) eap: Freeing handler
(6) [eap] = ok
(6) } # authenticate = ok
(6) # Executing section post-auth from file /etc/raddb/sites-enabled/inner-tunnel
(6) post-auth {
(6) policy moonshot_host_tid.post-auth {
(6) if (&outer.request:GSS-Acceptor-Host-Name) {
(6) if (&outer.request:GSS-Acceptor-Host-Name) -> TRUE
(6) if (&outer.request:GSS-Acceptor-Host-Name) {
(6) update control {
(6) EXPAND %{tolower:%{outer.request:GSS-Acceptor-Host-Name}}
(6) --> service.moonshot-playpen.ti.ja.net
(6) Moonshot-MSTID-GSS-Acceptor := service.moonshot-playpen.ti.ja.net
(6) Moonshot-MSTID-Namespace := "a574a04e-b7ff-4850-aa24-a8599c7de1c6"
(6) } # update control = noop
(6) if (!&control:Moonshot-MSTID-TargetedId) {
(6) if (!&control:Moonshot-MSTID-TargetedId) -> TRUE
(6) if (!&control:Moonshot-MSTID-TargetedId) {
(6) policy moonshot_make_targeted_id.post-auth {
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) {
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) -> TRUE
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) {
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) {
(6) Executing: /usr/bin/uuid -v 5 a574a04e-b7ff-4850-aa24-a8599c7de1c6 bob at idp.test.assentt[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zdservice.moonshot-playpen.ti.ja.net:
(6) Program returned code (0) and output '33127397-1bb6-5e95-8859-dfe76acfba67'
(6) EXPAND %{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}
(6) --> 33127397-1bb6-5e95-8859-dfe76acfba67
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) -> TRUE
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) {
(6) update control {
(6) EXPAND %{1}@%{tolower:%{request:Realm}}
(6) --> 33127397-1bb6-5e95-8859-dfe76acfba67 at idp.test.assent
(6) Moonshot-MSTID-TargetedId := 33127397-1bb6-5e95-8859-dfe76acfba67 at idp.test.assent
(6) } # update control = noop
(6) if (&control:Moonshot-MSTID-TargetedId =~ /([\%\{\}]+)/) {
(6) EXPAND ([\%\{\}]+)
(6) --> ([\%\{\}]+)
(6) if (&control:Moonshot-MSTID-TargetedId =~ /([\%\{\}]+)/) -> FALSE
(6) } # if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) = noop
(6) ... skipping else: Preceding "if" was taken
(6) } # if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) = noop
(6) ... skipping else: Preceding "if" was taken
(6) } # policy moonshot_make_targeted_id.post-auth = noop
(6) } # if (!&control:Moonshot-MSTID-TargetedId) = noop
(6) if (&control:Moonshot-MSTID-TargetedId) {
(6) if (&control:Moonshot-MSTID-TargetedId) -> TRUE
(6) if (&control:Moonshot-MSTID-TargetedId) {
(6) update outer.session-state {
(6) Moonshot-Host-TargetedId := &control:Moonshot-MSTID-TargetedId -> '33127397-1bb6-5e95-8859-dfe76acfba67 at idp.test.assent'
(6) } # update outer.session-state = noop
(6) update control {
(6) Moonshot-MSTID-TargetedId !* ANY
(6) } # update control = noop
(6) } # if (&control:Moonshot-MSTID-TargetedId) = noop
(6) } # if (&outer.request:GSS-Acceptor-Host-Name) = noop
(6) } # policy moonshot_host_tid.post-auth = noop
(6) policy moonshot_realm_tid.post-auth {
(6) if (&outer.request:GSS-Acceptor-Realm-Name) {
(6) if (&outer.request:GSS-Acceptor-Realm-Name) -> TRUE
(6) if (&outer.request:GSS-Acceptor-Realm-Name) {
(6) update control {
(6) EXPAND %{tolower:%{outer.request:GSS-Acceptor-Realm-Name}}
(6) --> assent-fr-idp.test.assent
(6) Moonshot-MSTID-GSS-Acceptor := assent-fr-idp.test.assent
(6) Moonshot-MSTID-Namespace := "dea5f26d-a013-4444-977d-d09fc990d2e6"
(6) } # update control = noop
(6) if (!&control:Moonshot-MSTID-TargetedId) {
(6) if (!&control:Moonshot-MSTID-TargetedId) -> TRUE
(6) if (!&control:Moonshot-MSTID-TargetedId) {
(6) policy moonshot_make_targeted_id.post-auth {
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) {
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) -> TRUE
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) {
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) {
(6) Executing: /usr/bin/uuid -v 5 dea5f26d-a013-4444-977d-d09fc990d2e6 bob at idp.test.assentt[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zdassent-fr-idp.test.assent:
(6) Program returned code (0) and output 'abd0d71b-7294-5423-86b1-3fae0bd7b33a'
(6) EXPAND %{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}
(6) --> abd0d71b-7294-5423-86b1-3fae0bd7b33a
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) -> TRUE
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) {
(6) update control {
(6) EXPAND %{1}@%{tolower:%{request:Realm}}
(6) --> abd0d71b-7294-5423-86b1-3fae0bd7b33a at idp.test.assent
(6) Moonshot-MSTID-TargetedId := abd0d71b-7294-5423-86b1-3fae0bd7b33a at idp.test.assent
(6) } # update control = noop
(6) if (&control:Moonshot-MSTID-TargetedId =~ /([\%\{\}]+)/) {
(6) EXPAND ([\%\{\}]+)
(6) --> ([\%\{\}]+)
(6) if (&control:Moonshot-MSTID-TargetedId =~ /([\%\{\}]+)/) -> FALSE
(6) } # if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) = noop
(6) ... skipping else: Preceding "if" was taken
(6) } # if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) = noop
(6) ... skipping else: Preceding "if" was taken
(6) } # policy moonshot_make_targeted_id.post-auth = noop
(6) } # if (!&control:Moonshot-MSTID-TargetedId) = noop
(6) if (&control:Moonshot-MSTID-TargetedId) {
(6) if (&control:Moonshot-MSTID-TargetedId) -> TRUE
(6) if (&control:Moonshot-MSTID-TargetedId) {
(6) update outer.session-state {
(6) Moonshot-Realm-TargetedId := &control:Moonshot-MSTID-TargetedId -> 'abd0d71b-7294-5423-86b1-3fae0bd7b33a at idp.test.assent'
(6) } # update outer.session-state = noop
(6) update control {
(6) Moonshot-MSTID-TargetedId !* ANY
(6) } # update control = noop
(6) } # if (&control:Moonshot-MSTID-TargetedId) = noop
(6) } # if (&outer.request:GSS-Acceptor-Realm-Name) = noop
(6) } # policy moonshot_realm_tid.post-auth = noop
(6) policy moonshot_coi_tid.post-auth {
(6) if (&outer.request:Trust-Router-COI) {
(6) if (&outer.request:Trust-Router-COI) -> TRUE
(6) if (&outer.request:Trust-Router-COI) {
(6) update control {
(6) EXPAND %{tolower:%{outer.request:Trust-Router-COI}}
(6) --> apc.test.assent
(6) Moonshot-MSTID-GSS-Acceptor := apc.test.assent
(6) Moonshot-MSTID-Namespace := "145d7e7e-7d54-43ee-bbcb-3c6ad9428247"
(6) } # update control = noop
(6) if (!&control:Moonshot-MSTID-TargetedId) {
(6) if (!&control:Moonshot-MSTID-TargetedId) -> TRUE
(6) if (!&control:Moonshot-MSTID-TargetedId) {
(6) policy moonshot_make_targeted_id.post-auth {
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) {
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) -> TRUE
(6) if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) {
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) {
(6) Executing: /usr/bin/uuid -v 5 145d7e7e-7d54-43ee-bbcb-3c6ad9428247 bob at idp.test.assentt[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zdapc.test.assent:
(6) Program returned code (0) and output 'b40d0def-5b25-52bd-8d13-e6d22fa24648'
(6) EXPAND %{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}
(6) --> b40d0def-5b25-52bd-8d13-e6d22fa24648
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) -> TRUE
(6) if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) {
(6) update control {
(6) EXPAND %{1}@%{tolower:%{request:Realm}}
(6) --> b40d0def-5b25-52bd-8d13-e6d22fa24648 at idp.test.assent
(6) Moonshot-MSTID-TargetedId := b40d0def-5b25-52bd-8d13-e6d22fa24648 at idp.test.assent
(6) } # update control = noop
(6) if (&control:Moonshot-MSTID-TargetedId =~ /([\%\{\}]+)/) {
(6) EXPAND ([\%\{\}]+)
(6) --> ([\%\{\}]+)
(6) if (&control:Moonshot-MSTID-TargetedId =~ /([\%\{\}]+)/) -> FALSE
(6) } # if ("%{echo:/usr/bin/uuid -v 5 %{control:Moonshot-MSTID-Namespace} %{tolower:%{User-Name}}t[?.V)Are7gQmFCYK\{!T*JdWqD\{\{Zd%{control:Moonshot-MSTID-GSS-Acceptor}}" =~ /^([^ ]+)([ ]*)$/) = noop
(6) ... skipping else: Preceding "if" was taken
(6) } # if (&control:Moonshot-MSTID-Namespace && &control:Moonshot-MSTID-GSS-Acceptor) = noop
(6) ... skipping else: Preceding "if" was taken
(6) } # policy moonshot_make_targeted_id.post-auth = noop
(6) } # if (!&control:Moonshot-MSTID-TargetedId) = noop
(6) if (&control:Moonshot-MSTID-TargetedId) {
(6) if (&control:Moonshot-MSTID-TargetedId) -> TRUE
(6) if (&control:Moonshot-MSTID-TargetedId) {
(6) update outer.session-state {
(6) Moonshot-TR-COI-TargetedId := &control:Moonshot-MSTID-TargetedId -> 'b40d0def-5b25-52bd-8d13-e6d22fa24648 at idp.test.assent'
(6) } # update outer.session-state = noop
(6) update control {
(6) Moonshot-MSTID-TargetedId !* ANY
(6) } # update control = noop
(6) } # if (&control:Moonshot-MSTID-TargetedId) = noop
(6) } # if (&outer.request:Trust-Router-COI) = noop
(6) } # policy moonshot_coi_tid.post-auth = noop
(6) if (1) {
(6) if (1) -> TRUE
(6) if (1) {
(6) update reply {
(6) Message-Authenticator !* ANY
(6) EAP-Message !* ANY
(6) Proxy-State !* ANY
(6) MS-MPPE-Encryption-Types !* ANY
(6) MS-MPPE-Encryption-Policy !* ANY
(6) MS-MPPE-Send-Key !* ANY
(6) MS-MPPE-Recv-Key !* ANY
(6) } # update reply = noop
(6) update {
(6) &outer.session-state::EAP-Channel-Binding-Message += &reply:EAP-Channel-Binding-Message[*] -> 0x02002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(6) &outer.session-state::Reply-Message += &reply:Reply-Message[*] -> 'Bob has authenticated'
(6) &outer.session-state::User-Name += &reply:User-Name[*] -> 'root'
(6) } # update = noop
(6) } # if (1) = noop
(6) } # post-auth = noop
(6) } # server inner-tunnel
(6) Virtual server sending reply
(6) EAP-Channel-Binding-Message = 0x02002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(6) Reply-Message = "Bob has authenticated"
(6) User-Name = "root"
(6) eap_ttls: Got tunneled Access-Accept
(6) eap_ttls: Sending tunneled reply attributes
(6) eap_ttls: EAP-Channel-Binding-Message = 0x02002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(6) eap: Sending EAP Request (code 1) ID 7 length 99
(6) eap: EAP session adding &reply:State = 0x99ee34c09fe92160
(6) [eap] = handled
(6) } # authenticate = handled
(6) Using Post-Auth-Type Challenge
(6) Post-Auth-Type sub-section not found. Ignoring.
(6) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(6) session-state: Saving cached attributes
(6) Moonshot-Host-TargetedId := "33127397-1bb6-5e95-8859-dfe76acfba67 at idp.test.assent"
(6) Moonshot-Realm-TargetedId := "abd0d71b-7294-5423-86b1-3fae0bd7b33a at idp.test.assent"
(6) Moonshot-TR-COI-TargetedId := "b40d0def-5b25-52bd-8d13-e6d22fa24648 at idp.test.assent"
(6) EAP-Channel-Binding-Message += 0x02002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(6) Reply-Message += "Bob has authenticated"
(6) User-Name += "root"
(6) Sent Access-Challenge Id 189 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(6) EAP-Message = 0x01070063158000000059170303005496caae9b220ab067aecc7766fafc738318bbd56dcf3f59b7dd26e4a7e77c2fdac72c555890bb6886eb6cf1d317cd9726d06259d3573d6068a5b77b30f78ec840a5c103390937fd16d61ad67c3ef762da375219fc
(6) Message-Authenticator = 0x00000000000000000000000000000000
(6) State = 0x99ee34c09fe921606abcbf8df3266bc7
(6) Proxy-State = 0x30
(6) Finished request
Thread 4 waiting to be assigned a request
(0) Application data status 7
(0) tls_recv: Access-Request packet from host 13.94.115.212 port 48186, id=83, length=189
Thread 3 got semaphore
Thread 3 handling request 7, (2 handled so far)
(7) Retrieved psk identity: key-4e72e5
(7) Received Access-Request Id 83 from 13.94.115.212:48186 to 0.0.0.0:2083 length 189
(7) TLS-PSK-Identity := "key-4e72e5"
(7) User-Name = "@idp.test.assent"
(7) EAP-Message = 0x020700061500
(7) State = 0x99ee34c09fe921606abcbf8df3266bc7
(7) Message-Authenticator = 0x8a936d20e611d1380195029de5055114
(7) GSS-Acceptor-Host-Name = "service.moonshot-playpen.ti.ja.net"
(7) Trust-Router-COI = "apc.test.assent"
(7) GSS-Acceptor-Realm-Name = "assent-test-service.test.assent"
(7) Event-Timestamp = "Apr 23 2018 15:36:17 UTC"
(7) NAS-IP-Address = 127.0.0.1
(7) Proxy-State = 0x30
(7) Restoring &session-state
(7) &session-state:Moonshot-Host-TargetedId := "33127397-1bb6-5e95-8859-dfe76acfba67 at idp.test.assent"
(7) &session-state:Moonshot-Realm-TargetedId := "abd0d71b-7294-5423-86b1-3fae0bd7b33a at idp.test.assent"
(7) &session-state:Moonshot-TR-COI-TargetedId := "b40d0def-5b25-52bd-8d13-e6d22fa24648 at idp.test.assent"
(7) &session-state:EAP-Channel-Binding-Message += 0x02002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(7) &session-state:Reply-Message += "Bob has authenticated"
(7) &session-state:User-Name += "root"
(7) # Executing section authorize from file /etc/raddb/sites-enabled/abfab-tr-idp
(7) authorize {
(7) policy psk_authorize {
(7) if (&TLS-PSK-Identity) {
(7) if (&TLS-PSK-Identity) -> TRUE
(7) if (&TLS-PSK-Identity) {
(7) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") {
rlm_sql (psksql): Reserved connection (3)
(7) Executing select query: select distinct keyid from authorizations_keys where keyid = 'key-4e72e5' and 'apc.test.assent' like coi and 'assent-test-service.test.assent' like acceptor_realm and 'service.moonshot-playpen.ti.ja.net' like hostname;
rlm_sql (psksql): Released connection (3)
(7) EXPAND %{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}
(7) --> key-4e72e5
(7) if ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") -> TRUE
(7) ("%{psksql:select distinct keyid from authorizations_keys where keyid = '%{tls-psk-identity}' and '%{trust-router-coi}' like coi and '%{gss-acceptor-realm-name}' like acceptor_realm and '%{gss-acceptor-host-name}' like hostname;}") { ... } # empty sub-section is ignored
(7) ... skipping else: Preceding "if" was taken
(7) } # if (&TLS-PSK-Identity) = notfound
(7) } # policy psk_authorize = notfound
(7) policy abfab_client_check {
(7) if ("%{client:gss_acceptor_host_name}") {
(7) EXPAND %{client:gss_acceptor_host_name}
(7) -->
(7) if ("%{client:gss_acceptor_host_name}") -> FALSE
(7) if ("%{client:trust_router_coi}") {
(7) EXPAND %{client:trust_router_coi}
(7) --> apc.test.assent
(7) if ("%{client:trust_router_coi}") -> TRUE
(7) if ("%{client:trust_router_coi}") {
(7) update request {
(7) EXPAND %{client:trust_router_coi}
(7) --> apc.test.assent
(7) Trust-Router-COI := apc.test.assent
(7) } # update request = noop
(7) } # if ("%{client:trust_router_coi}") = noop
(7) if ("%{client:gss_acceptor_realm_name}") {
(7) EXPAND %{client:gss_acceptor_realm_name}
(7) --> assent-fr-idp.test.assent
(7) if ("%{client:gss_acceptor_realm_name}") -> TRUE
(7) if ("%{client:gss_acceptor_realm_name}") {
(7) update request {
(7) EXPAND %{client:gss_acceptor_realm_name}
(7) --> assent-fr-idp.test.assent
(7) GSS-Acceptor-Realm-Name := assent-fr-idp.test.assent
(7) } # update request = noop
(7) } # if ("%{client:gss_acceptor_realm_name}") = noop
(7) if ("%{client:gss_acceptor_service_name}") {
(7) EXPAND %{client:gss_acceptor_service_name}
(7) -->
(7) if ("%{client:gss_acceptor_service_name}") -> FALSE
(7) } # policy abfab_client_check = noop
(7) policy filter_username {
(7) if (&User-Name) {
(7) if (&User-Name) -> TRUE
(7) if (&User-Name) {
(7) if (&User-Name =~ / /) {
(7) if (&User-Name =~ / /) -> FALSE
(7) if (&User-Name =~ /@[^@]*@/ ) {
(7) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(7) if (&User-Name =~ /\.\./ ) {
(7) if (&User-Name =~ /\.\./ ) -> FALSE
(7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(7) if (&User-Name =~ /\.$/) {
(7) if (&User-Name =~ /\.$/) -> FALSE
(7) if (&User-Name =~ /@\./) {
(7) if (&User-Name =~ /@\./) -> FALSE
(7) } # if (&User-Name) = noop
(7) } # policy filter_username = noop
(7) [preprocess] = ok
(7) suffix: Checking for suffix after "@"
(7) suffix: Looking up realm "idp.test.assent" for User-Name = "@idp.test.assent"
(7) suffix: No trust router configured, skipping dynamic realm lookup
(7) suffix: Found realm "idp.test.assent"
(7) suffix: Adding Stripped-User-Name = ""
(7) suffix: Adding Realm = "idp.test.assent"
(7) suffix: Authentication realm is LOCAL
(7) [suffix] = ok
(7) eap: Peer sent EAP Response (code 2) ID 7 length 6
(7) eap: Continuing tunnel setup
(7) [eap] = ok
(7) } # authorize = ok
(7) Found Auth-Type = eap
(7) # Executing group from file /etc/raddb/sites-enabled/abfab-tr-idp
(7) authenticate {
(7) eap: Expiring EAP session with state 0x99ee34c09fe92160
(7) eap: Finished EAP session with state 0x99ee34c09fe92160
(7) eap: Previous EAP request found for state 0x99ee34c09fe92160, released from the list
(7) eap: Peer sent packet with method EAP TTLS (21)
(7) eap: Calling submodule eap_ttls to process data
(7) eap_ttls: Authenticate
(7) eap_ttls: Continuing EAP-TLS
(7) eap_ttls: Peer ACKed our handshake fragment. handshake is finished
(7) eap_ttls: [eaptls verify] = success
(7) eap_ttls: [eaptls process] = success
(7) eap: Sending EAP Success (code 3) ID 7 length 4
(7) eap: Freeing handler
(7) [eap] = ok
(7) } # authenticate = ok
(7) # Executing section post-auth from file /etc/raddb/sites-enabled/abfab-tr-idp
(7) post-auth {
(7) update {
(7) &reply::Moonshot-Host-TargetedId += &session-state:Moonshot-Host-TargetedId[*] -> '33127397-1bb6-5e95-8859-dfe76acfba67 at idp.test.assent'
(7) &reply::Moonshot-Realm-TargetedId += &session-state:Moonshot-Realm-TargetedId[*] -> 'abd0d71b-7294-5423-86b1-3fae0bd7b33a at idp.test.assent'
(7) &reply::Moonshot-TR-COI-TargetedId += &session-state:Moonshot-TR-COI-TargetedId[*] -> 'b40d0def-5b25-52bd-8d13-e6d22fa24648 at idp.test.assent'
(7) &reply::EAP-Channel-Binding-Message += &session-state:EAP-Channel-Binding-Message[*] -> 0x02002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(7) &reply::Reply-Message += &session-state:Reply-Message[*] -> 'Bob has authenticated'
(7) &reply::User-Name += &session-state:User-Name[*] -> 'root'
(7) } # update = noop
(7) [exec] = noop
(7) policy remove_reply_message_if_eap {
(7) if (&reply:EAP-Message && &reply:Reply-Message) {
(7) if (&reply:EAP-Message && &reply:Reply-Message) -> TRUE
(7) if (&reply:EAP-Message && &reply:Reply-Message) {
(7) update reply {
(7) &Reply-Message !* ANY
(7) } # update reply = noop
(7) } # if (&reply:EAP-Message && &reply:Reply-Message) = noop
(7) ... skipping else: Preceding "if" was taken
(7) } # policy remove_reply_message_if_eap = noop
(7) } # post-auth = noop
(7) Sent Access-Accept Id 83 from 0.0.0.0:2083 to 13.94.115.212:48186 length 0
(7) MS-MPPE-Recv-Key = 0x1ee8bbd31cd79fd4e98d946e946e1f976b7aaebd6e5412b4bab51b2e2d784c9c
(7) MS-MPPE-Send-Key = 0x4de6d0ddcf7a725afc0a7e4b7fb2478b5c59a76ac5689342d33fbcdb4787f2c7
(7) EAP-Message = 0x03070004
(7) Message-Authenticator = 0x00000000000000000000000000000000
(7) User-Name = "@idp.test.assent"
(7) Proxy-State = 0x30
(7) Moonshot-Host-TargetedId += "33127397-1bb6-5e95-8859-dfe76acfba67 at idp.test.assent"
(7) Moonshot-Realm-TargetedId += "abd0d71b-7294-5423-86b1-3fae0bd7b33a at idp.test.assent"
(7) Moonshot-TR-COI-TargetedId += "b40d0def-5b25-52bd-8d13-e6d22fa24648 at idp.test.assent"
(7) EAP-Channel-Binding-Message += 0x02002a01a40648545450a524736572766963652e6d6f6f6e73686f742d706c617970656e2e74692e6a612e6e6574
(7) User-Name += "root"
(7) Finished request
Thread 3 waiting to be assigned a request
Waking up in 4.2 seconds.
(0) Cleaning up request packet ID 222 with timestamp +5
(1) Cleaning up request packet ID 207 with timestamp +5
(2) Cleaning up request packet ID 84 with timestamp +5
(3) Cleaning up request packet ID 66 with timestamp +5
(4) Cleaning up request packet ID 35 with timestamp +5
Closing TLS socket from client port 48186
(0) >>> send TLS 1.2 [length 0002]
Client has closed connection
(5) Cleaning up request packet ID 183 with timestamp +5
(6) Cleaning up request packet ID 189 with timestamp +5
... shutting down socket auth from client (13.94.115.212, 48186) -> (*, 2083, virtual-server=abfab-idp)
(7) Cleaning up request packet ID 83 with timestamp +5
Waking up in 2.9 seconds.
... cleaning up socket auth from client (13.94.115.212, 48186) -> (*, 2083, virtual-server=abfab-idp)
Ready to process requests
-- log ends --
:-/
Stefan Paetow
Consultant, Trust and Identity
t: +44 (0)1235 822 125
gpg: 0x3FCE5142
xmpp: stefanp at jabber.dev.ja.net
skype: stefan.paetow.janet
jisc.ac.uk
Jisc is a registered charity (number 1149740) and a company limited by guarantee which is registered in England under Company No. 5747339, VAT No. GB 197 0632 86. Jisc’s registered office is: One Castlepark, Tower Hill, Bristol, BS2 0JA. T 0203 697 5800.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 529 bytes
Desc: Message signed with OpenPGP
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20180423/742c4ce8/attachment-0001.sig>
More information about the Freeradius-Users
mailing list