I have a question with radius proxy
Yuya Yanagi
peacefull64 at gmail.com
Fri Jul 26 07:45:36 CEST 2019
Hi,Alan and All
I have a question with radius proxy
It is decided to use eduroam as well as the certification of one's own base
in Radius under construction.
If you set proxy.conf and start radius, eduroam can authenticate without
problems.
If you try to authenticate on the internal side (local side), it is
transferred to the home_server side, and proxy.conf
We are troubled because we do not branch in the realm.
The specifications for connection are as follows.
1. An AP connected to eduroam is shared with campus and eduroam
2. If the realm of the connecting user ID is your own site, connect to
LOCAL RADIUS without Proxy, if eduroam, proxy to eduroam
I have been debugging a lot, but I understood that if I do not use a proxy,
I can authenticate my own base with or without a realm.
I am really in trouble as the system release is approaching. Can you ask
for help in problem solving?
y.y
-----------------------<proxy.conf>--------------------------
realm "~^(.+\.)?hoge\.ac\.jp$" {
authhost = LOCAL
accthost = LOCAL
}
realm NULL {
type = radius
authhost = LOCAL
accthost = LOCAL
}
# JP primary server
home_server jp-top-nii {
type = auth+acct
ipaddr = <<jp-top-nii IP>>
port = 1812
secret = <<secret>>
}
# JP secondary server
home_server jp-top-tohoku {
type = auth+acct
ipaddr = <<jp-top-tohoku IP>>
port = 1812
secret = <<secret>>
}
#JP servers pool
home_server_pool jp-top {
type = fail-over
home_server = jp-top-nii
home_server = jp-top-tohoku
}
realm DEFAULT {
pool = jp-top
nostrip
}
-----------------------<debug log>--------------------------
<成功している場合>
Thu Jul 25 19:48:22 2019 : Debug: (9) Received Access-Request Id 1 from
xxx.15.xxx.241:50692 to xxx15.xxx.14:1812 length 277
Thu Jul 25 19:48:22 2019 : Debug: (9) User-Name = "
hoge-test at hoge.t.eduroam.jp"
Thu Jul 25 19:48:22 2019 : Debug: (9) NAS-IP-Address = 10.254.0.241
Thu Jul 25 19:48:22 2019 : Debug: (9) NAS-Port = 12289
Thu Jul 25 19:48:22 2019 : Debug: (9) Called-Station-Id =
"08-35-71-F2-CE-05:authtest"
Thu Jul 25 19:48:22 2019 : Debug: (9) Calling-Station-Id =
"50-3E-AA-6D-ED-7E"
Thu Jul 25 19:48:22 2019 : Debug: (9) Framed-MTU = 1250
Thu Jul 25 19:48:22 2019 : Debug: (9) NAS-Port-Type = Wireless-802.11
Thu Jul 25 19:48:22 2019 : Debug: (9) Framed-Compression = None
Thu Jul 25 19:48:22 2019 : Debug: (9) Connect-Info = "CONNECT 802.11g"
Thu Jul 25 19:48:22 2019 : Debug: (9) Chargeable-User-Identity = 0x00
Thu Jul 25 19:48:22 2019 : Debug: (9) EAP-Message =
0x0209005f1580000000551703010050cb3dbe374456b00027a14910cb8c3f3b1f76e3cc15237055d85c2eb80a03e647e45af10d10ec9087f5da992567e67fd53fa1d5c9a4397cfbc89939fff9f74993024a4ceb1ebec6f786749a3d758f6732
Thu Jul 25 19:48:22 2019 : Debug: (9) State =
0x40e0a98c47e9bc7fc4ecba1b8bf4d9d2
Thu Jul 25 19:48:22 2019 : Debug: (9) Message-Authenticator =
0xcaa2f5b3f06d1fc44413ddd7a734a8db
Thu Jul 25 19:48:22 2019 : Debug: (9) session-state: No cached attributes
Thu Jul 25 19:48:22 2019 : Debug: (9) # Executing section authorize from
file /etc/raddb/sites-enabled/default
Thu Jul 25 19:48:22 2019 : Debug: (9) authorize {
Thu Jul 25 19:48:22 2019 : Debug: (9) policy rewrite_called_station_id {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
{
Thu Jul 25 19:48:22 2019 : Debug: No matches
Thu Jul 25 19:48:22 2019 : Debug: Adding 9 matches
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
-> TRUE
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
{
Thu Jul 25 19:48:22 2019 : Debug: (9) update request {
Thu Jul 25 19:48:22 2019 : Debug: (9) 1/9 Found: 08 (3)
Thu Jul 25 19:48:22 2019 : Debug: (9) 2/9 Found: 35 (3)
Thu Jul 25 19:48:22 2019 : Debug: (9) 3/9 Found: 71 (3)
Thu Jul 25 19:48:22 2019 : Debug: (9) 4/9 Found: F2 (3)
Thu Jul 25 19:48:22 2019 : Debug: (9) 5/9 Found: CE (3)
Thu Jul 25 19:48:22 2019 : Debug: (9) 6/9 Found: 05 (3)
Thu Jul 25 19:48:22 2019 : Debug: (9) EXPAND
%{toupper:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}}
Thu Jul 25 19:48:22 2019 : Debug: (9) --> 08-35-71-F2-CE-05
Thu Jul 25 19:48:22 2019 : Debug: (9) &Called-Station-Id :=
08-35-71-F2-CE-05
Thu Jul 25 19:48:22 2019 : Debug: (9) Overwriting value
"08-35-71-F2-CE-05:authtest" with "08-35-71-F2-CE-05"
Thu Jul 25 19:48:22 2019 : Debug: (9) } # update request = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) if ("%{8}") {
Thu Jul 25 19:48:22 2019 : Debug: (9) EXPAND TMPL XLAT STRUCT
Thu Jul 25 19:48:22 2019 : Debug: (9) 8/9 Found: authtest (9)
Thu Jul 25 19:48:22 2019 : Debug: (9) EXPAND %{8}
Thu Jul 25 19:48:22 2019 : Debug: (9) --> authtest
Thu Jul 25 19:48:22 2019 : Debug: (9) if ("%{8}") -> TRUE
Thu Jul 25 19:48:22 2019 : Debug: (9) if ("%{8}") {
Thu Jul 25 19:48:22 2019 : Debug: (9) update request {
Thu Jul 25 19:48:22 2019 : Debug: (9) 8/9 Found: authtest (9)
Thu Jul 25 19:48:22 2019 : Debug: (9) EXPAND %{8}
Thu Jul 25 19:48:22 2019 : Debug: (9) --> authtest
Thu Jul 25 19:48:22 2019 : Debug: (9) &Called-Station-SSID :=
authtest
Thu Jul 25 19:48:22 2019 : Debug: (9) } # update request = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) } # if ("%{8}") = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling
updated (rlm_always)
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]:
returned from updated (rlm_always)
Thu Jul 25 19:48:22 2019 : Debug: (9) [updated] = updated
Thu Jul 25 19:48:22 2019 : Debug: (9) } # if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
= updated
Thu Jul 25 19:48:22 2019 : Debug: (9) ... skipping else: Preceding
"if" was taken
Thu Jul 25 19:48:22 2019 : Debug: (9) } # policy
rewrite_called_station_id = updated
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&outer.request) {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&outer.request) -> FALSE
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling
preprocess (rlm_preprocess)
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: returned
from preprocess (rlm_preprocess)
Thu Jul 25 19:48:22 2019 : Debug: (9) [preprocess] = ok
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling
mschap (rlm_mschap)
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: returned
from mschap (rlm_mschap)
Thu Jul 25 19:48:22 2019 : Debug: (9) [mschap] = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling
digest (rlm_digest)
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: returned
from digest (rlm_digest)
Thu Jul 25 19:48:22 2019 : Debug: (9) [digest] = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling
suffix (rlm_realm)
Thu Jul 25 19:48:22 2019 : Debug: (9) suffix: Checking for suffix after "@"
Thu Jul 25 19:48:22 2019 : Debug: (9) suffix: Looking up realm "
hoge.t.eduroam.jp" for User-Name = "hoge-test at hoge.t.eduroam.jp"
Thu Jul 25 19:48:22 2019 : Debug: (9) suffix: Found realm "DEFAULT"
Thu Jul 25 19:48:22 2019 : Debug: (9) suffix: Adding Realm = "DEFAULT"
Thu Jul 25 19:48:22 2019 : Debug: (9) suffix: Proxying request from user
hoge-test at hoge.t.eduroam.jp to realm DEFAULT
Thu Jul 25 19:48:22 2019 : Debug: (9) suffix: Preparing to proxy
authentication request to realm "DEFAULT"
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: returned
from suffix (rlm_realm)
Thu Jul 25 19:48:22 2019 : Debug: (9) [suffix] = updated
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling eap
(rlm_eap)
Thu Jul 25 19:48:22 2019 : Debug: (9) eap: Request is supposed to be
proxied to Realm DEFAULT. Not doing EAP.
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: returned
from eap (rlm_eap)
Thu Jul 25 19:48:22 2019 : Debug: (9) [eap] = noop
......
Thu Jul 25 19:48:22 2019 : Debug: Adding 1 matches
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&NAS-IP-Address =~
/^10\.254\.0\.24[1]{1}$/) -> TRUE
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&NAS-IP-Address =~
/^10\.254\.0\.24[1]{1}$/) {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Called-Station-SSID ==
'authtest') {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Called-Station-SSID ==
'authtest') -> TRUE
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Called-Station-SSID ==
'authtest') {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Realm == "NULL" ||
&Realm == "edu.hoge.ac.jp" || &Realm == "edu.imc.hoge.ac.jp" || &Realm == "
hoge.ac.jp" || &Realm == "hoge.jp") {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&Realm == "NULL" ||
&Realm == "edu.hoge.ac.jp" || &Realm == "edu.imc.hoge.ac.jp" || &Realm == "
hoge.ac.jp" || &Realm == "hoge.jp") -> FALSE
Thu Jul 25 19:48:22 2019 : Debug: (9) } # if (&Called-Station-SSID ==
'authtest') = updated
Thu Jul 25 19:48:22 2019 : Debug: (9) } # if (&NAS-IP-Address =~
/^10\.254\.0\.24[1]{1}$/) = updated
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling
expiration (rlm_expiration)
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: returned
from expiration (rlm_expiration)
Thu Jul 25 19:48:22 2019 : Debug: (9) [expiration] = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: calling
logintime (rlm_logintime)
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[authorize]: returned
from logintime (rlm_logintime)
Thu Jul 25 19:48:22 2019 : Debug: (9) [logintime] = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) } # authorize = updated
Thu Jul 25 19:48:22 2019 : Debug: (9) Starting proxy to home server
210.151.94.186 port 1812
Thu Jul 25 19:48:22 2019 : Debug: (9) Empty pre-proxy section in virtual
server "default". Using default return values.
Thu Jul 25 19:48:22 2019 : Debug: (9) proxy: Trying to allocate ID (0/2)
Thu Jul 25 19:48:22 2019 : Debug: (9) proxy: request is now in proxy hash
Thu Jul 25 19:48:22 2019 : Debug: (9) proxy: allocating destination
210.151.94.186 port 1812 - Id 202
Thu Jul 25 19:48:22 2019 : Debug: (9) Proxying request to home server
210.151.94.186 port 1812 timeout 30.000000
Thu Jul 25 19:48:22 2019 : Debug: (9) Sent Access-Request Id 202 from
0.0.0.0:55501 to 210.151.94.186:1812 length 277
Thu Jul 25 19:48:22 2019 : Debug: (9) User-Name = "
hoge-test at hoge.t.eduroam.jp"
Thu Jul 25 19:48:22 2019 : Debug: (9) NAS-IP-Address = 10.254.0.241
Thu Jul 25 19:48:22 2019 : Debug: (9) NAS-Port = 12289
Thu Jul 25 19:48:22 2019 : Debug: (9) Called-Station-Id :=
"08-35-71-F2-CE-05"
Thu Jul 25 19:48:22 2019 : Debug: (9) Calling-Station-Id =
"50-3E-AA-6D-ED-7E"
Thu Jul 25 19:48:22 2019 : Debug: (9) Framed-MTU = 1250
Thu Jul 25 19:48:22 2019 : Debug: (9) NAS-Port-Type = Wireless-802.11
Thu Jul 25 19:48:22 2019 : Debug: (9) Framed-Compression = None
Thu Jul 25 19:48:22 2019 : Debug: (9) Connect-Info = "CONNECT 802.11g"
Thu Jul 25 19:48:22 2019 : Debug: (9) Chargeable-User-Identity = 0x00
Thu Jul 25 19:48:22 2019 : Debug: (9) EAP-Message =
0x0209005f1580000000551703010050cb3dbe374456b00027a14910cb8c3f3b1f76e3cc15237055d85c2eb80a03e647e45af10d10ec9087f5da992567e67fd53fa1d5c9a4397cfbc89939fff9f74993024a4ceb1ebec6f786749a3d758f6732
Thu Jul 25 19:48:22 2019 : Debug: (9) State =
0x40e0a98c47e9bc7fc4ecba1b8bf4d9d2
Thu Jul 25 19:48:22 2019 : Debug: (9) Message-Authenticator =
0xcaa2f5b3f06d1fc44413ddd7a734a8db
Thu Jul 25 19:48:22 2019 : Debug: (9) Event-Timestamp = "Jul 25 2019
19:48:22 JST"
Thu Jul 25 19:48:22 2019 : Debug: (9) Proxy-State = 0x31
Thu Jul 25 19:48:22 2019 : Debug: Waking up in 0.3 seconds.
Thu Jul 25 19:48:22 2019 : Debug: (9) Clearing existing &reply: attributes
Thu Jul 25 19:48:22 2019 : Debug: (9) Received Access-Accept Id 202 from
210.151.94.186:1812 to xxx15.xxx.14:55501 length 163
Thu Jul 25 19:48:22 2019 : Debug: (9) MS-MPPE-Recv-Key =
0xa7cc9a2165371e3f2a1c102c8c88f1662db0a252368198157cabc2520b14bfef
Thu Jul 25 19:48:22 2019 : Debug: (9) MS-MPPE-Send-Key =
0x10eec8b6b6b83bdb5d32d83fe6289286d5f5ca0d02d4db66db5469bec1b47a58
Thu Jul 25 19:48:22 2019 : Debug: (9) EAP-Message = 0x03090004
Thu Jul 25 19:48:22 2019 : Debug: (9) Message-Authenticator =
0x657ffa391dc40a5dc02417aca8416235
Thu Jul 25 19:48:22 2019 : Debug: (9) Proxy-State = 0x31
Thu Jul 25 19:48:22 2019 : Debug: (9) # Executing section post-proxy from
file /etc/raddb/sites-enabled/default
Thu Jul 25 19:48:22 2019 : Debug: (9) post-proxy {
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[post-proxy]: calling
eap (rlm_eap)
Thu Jul 25 19:48:22 2019 : Debug: (9) eap: No pre-existing handler found
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[post-proxy]: returned
from eap (rlm_eap)
Thu Jul 25 19:48:22 2019 : Debug: (9) [eap] = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) } # post-proxy = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) Found Auth-Type = Accept
Thu Jul 25 19:48:22 2019 : Debug: (9) Auth-Type = Accept, accepting the user
Thu Jul 25 19:48:22 2019 : Debug: (9) # Executing section post-auth from
file /etc/raddb/sites-enabled/default
Thu Jul 25 19:48:22 2019 : Debug: (9) post-auth {
Thu Jul 25 19:48:22 2019 : Debug: (9) update {
Thu Jul 25 19:48:22 2019 : Debug: (9) No attributes updated
Thu Jul 25 19:48:22 2019 : Debug: (9) } # update = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) update reply {
Thu Jul 25 19:48:22 2019 : Debug: (9) &User-Name !* ANY
Thu Jul 25 19:48:22 2019 : Debug: (9) &Tunnel-Type := VLAN
Thu Jul 25 19:48:22 2019 : Debug: (9) &Tunnel-Medium-Type := IEEE-802
Thu Jul 25 19:48:22 2019 : Debug: (9) &Called-Station-SSID !* ANY
Thu Jul 25 19:48:22 2019 : Debug: (9) &Called-Station-id !* ANY
Thu Jul 25 19:48:22 2019 : Debug: (9) } # update reply = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) policy
remove_reply_message_if_eap {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&reply:EAP-Message &&
&reply:Reply-Message) {
Thu Jul 25 19:48:22 2019 : Debug: (9) if (&reply:EAP-Message &&
&reply:Reply-Message) -> FALSE
Thu Jul 25 19:48:22 2019 : Debug: (9) else {
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[post-auth]: calling
noop (rlm_always)
Thu Jul 25 19:48:22 2019 : Debug: (9) modsingle[post-auth]:
returned from noop (rlm_always)
Thu Jul 25 19:48:22 2019 : Debug: (9) [noop] = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) } # else = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) } # policy
remove_reply_message_if_eap = noop
Thu Jul 25 19:48:22 2019 : Debug: (9) } # post-auth = noop
......
Thu Jul 25 19:48:22 2019 : Debug: (9) EXPAND
%{control:Auth-Type};%{%{outer.request:Calling-Station-Id}:-%{Calling-Station-Id}};%{Called-Station-Id};%{Connect-Info};%{Fortinet-Vdom-Name};%{NAS-Identifier};%{Framed-IP-Address};%{request:User-Name}
Thu Jul 25 19:48:22 2019 : Debug: (9) -->
Accept;50-3E-AA-6D-ED-7E;08-35-71-F2-CE-05;CONNECT
802.11g;;;;hoge-test at hoge.t.eduroam.jp
★Thu Jul 25 19:48:22 2019 : Auth: (9) Login OK: [hoge-test at hoge.t.eduroam.jp]
(from client wlctest port 12289 cli 50-3E-AA-6D-ED-7E)
Accept;50-3E-AA-6D-ED-7E;08-35-71-F2-CE-05;CONNECT
802.11g;;;;hoge-test at hoge.t.eduroam.jp
Thu Jul 25 19:48:22 2019 : Debug: (9) Sent Access-Accept Id 1 from
xxx15.xxx.14:1812 to xxx.15.xxx.241:50692 length 0
Thu Jul 25 19:48:22 2019 : Debug: (9) MS-MPPE-Recv-Key =
0xa7cc9a2165371e3f2a1c102c8c88f1662db0a252368198157cabc2520b14bfef
Thu Jul 25 19:48:22 2019 : Debug: (9) MS-MPPE-Send-Key =
0x10eec8b6b6b83bdb5d32d83fe6289286d5f5ca0d02d4db66db5469bec1b47a58
Thu Jul 25 19:48:22 2019 : Debug: (9) EAP-Message = 0x03090004
Thu Jul 25 19:48:22 2019 : Debug: (9) Message-Authenticator =
0x657ffa391dc40a5dc02417aca8416235
Thu Jul 25 19:48:22 2019 : Debug: (9) Tunnel-Type := VLAN
Thu Jul 25 19:48:22 2019 : Debug: (9) Tunnel-Medium-Type := IEEE-802
Thu Jul 25 19:48:22 2019 : Debug: (9) Finished request
Thu Jul 25 19:48:22 2019 : Debug: Waking up in 4.2 seconds.
<失敗している場合>
Thu Jul 25 19:49:50 2019 : Debug: Waking up in 4.7 seconds.
Thu Jul 25 19:49:50 2019 : Debug: (15) Received Access-Request Id 244 from
xxx.15.xxx.241:50692 to xxx.15.xxx.14:1812 length 267
Thu Jul 25 19:49:50 2019 : Debug: (15) User-Name = "rt015 at hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) NAS-IP-Address = 10.254.0.241
Thu Jul 25 19:49:50 2019 : Debug: (15) NAS-Port = 12289
Thu Jul 25 19:49:50 2019 : Debug: (15) Called-Station-Id =
"08-35-71-F2-CE-05:authtest"
Thu Jul 25 19:49:50 2019 : Debug: (15) Calling-Station-Id =
"50-3E-AA-6D-ED-7E"
Thu Jul 25 19:49:50 2019 : Debug: (15) Framed-MTU = 1250
Thu Jul 25 19:49:50 2019 : Debug: (15) NAS-Port-Type = Wireless-802.11
Thu Jul 25 19:49:50 2019 : Debug: (15) Framed-Compression = None
Thu Jul 25 19:49:50 2019 : Debug: (15) Connect-Info = "CONNECT 802.11g"
Thu Jul 25 19:49:50 2019 : Debug: (15) Chargeable-User-Identity = 0x00
Thu Jul 25 19:49:50 2019 : Debug: (15) EAP-Message =
0x0206005f1580000000551703010050ff005ba6796aebc2306257dee2eabb49d15eb605ff09d3433137ee30756350e260ddbbac53bc9f7b691d61337632388d357950c098a212a2d650646f2b6c4bef664b98d320d70799a7304d88d79a5b25
Thu Jul 25 19:49:50 2019 : Debug: (15) State =
0x0973bc8b0d75a983b84b47e28ca6c132
Thu Jul 25 19:49:50 2019 : Debug: (15) Message-Authenticator =
0x004474ef0af1594a1a628592a7bb48cb
Thu Jul 25 19:49:50 2019 : Debug: (15) session-state: No cached attributes
Thu Jul 25 19:49:50 2019 : Debug: (15) # Executing section authorize from
file /etc/raddb/sites-enabled/default
Thu Jul 25 19:49:50 2019 : Debug: (15) authorize {
Thu Jul 25 19:49:50 2019 : Debug: (15) policy rewrite_called_station_id
{
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
{
Thu Jul 25 19:49:50 2019 : Debug: No matches
Thu Jul 25 19:49:50 2019 : Debug: Adding 9 matches
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
-> TRUE
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
{
Thu Jul 25 19:49:50 2019 : Debug: (15) update request {
Thu Jul 25 19:49:50 2019 : Debug: (15) 1/9 Found: 08 (3)
Thu Jul 25 19:49:50 2019 : Debug: (15) 2/9 Found: 35 (3)
Thu Jul 25 19:49:50 2019 : Debug: (15) 3/9 Found: 71 (3)
Thu Jul 25 19:49:50 2019 : Debug: (15) 4/9 Found: F2 (3)
Thu Jul 25 19:49:50 2019 : Debug: (15) 5/9 Found: CE (3)
Thu Jul 25 19:49:50 2019 : Debug: (15) 6/9 Found: 05 (3)
Thu Jul 25 19:49:50 2019 : Debug: (15) EXPAND
%{toupper:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}}
Thu Jul 25 19:49:50 2019 : Debug: (15) --> 08-35-71-F2-CE-05
Thu Jul 25 19:49:50 2019 : Debug: (15) &Called-Station-Id :=
08-35-71-F2-CE-05
Thu Jul 25 19:49:50 2019 : Debug: (15) Overwriting value
"08-35-71-F2-CE-05:authtest" with "08-35-71-F2-CE-05"
Thu Jul 25 19:49:50 2019 : Debug: (15) } # update request = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) if ("%{8}") {
Thu Jul 25 19:49:50 2019 : Debug: (15) EXPAND TMPL XLAT STRUCT
Thu Jul 25 19:49:50 2019 : Debug: (15) 8/9 Found: authtest (9)
Thu Jul 25 19:49:50 2019 : Debug: (15) EXPAND %{8}
Thu Jul 25 19:49:50 2019 : Debug: (15) --> authtest
Thu Jul 25 19:49:50 2019 : Debug: (15) if ("%{8}") -> TRUE
Thu Jul 25 19:49:50 2019 : Debug: (15) if ("%{8}") {
Thu Jul 25 19:49:50 2019 : Debug: (15) update request {
Thu Jul 25 19:49:50 2019 : Debug: (15) 8/9 Found: authtest (9)
Thu Jul 25 19:49:50 2019 : Debug: (15) EXPAND %{8}
Thu Jul 25 19:49:50 2019 : Debug: (15) --> authtest
Thu Jul 25 19:49:50 2019 : Debug: (15) &Called-Station-SSID :=
authtest
Thu Jul 25 19:49:50 2019 : Debug: (15) } # update request = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) } # if ("%{8}") = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]:
calling updated (rlm_always)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]:
returned from updated (rlm_always)
Thu Jul 25 19:49:50 2019 : Debug: (15) [updated] = updated
Thu Jul 25 19:49:50 2019 : Debug: (15) } # if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
= updated
Thu Jul 25 19:49:50 2019 : Debug: (15) ... skipping else: Preceding
"if" was taken
Thu Jul 25 19:49:50 2019 : Debug: (15) } # policy
rewrite_called_station_id = updated
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&outer.request) {
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&outer.request) -> FALSE
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
preprocess (rlm_preprocess)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from preprocess (rlm_preprocess)
Thu Jul 25 19:49:50 2019 : Debug: (15) [preprocess] = ok
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
mschap (rlm_mschap)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from mschap (rlm_mschap)
Thu Jul 25 19:49:50 2019 : Debug: (15) [mschap] = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
digest (rlm_digest)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from digest (rlm_digest)
Thu Jul 25 19:49:50 2019 : Debug: (15) [digest] = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
suffix (rlm_realm)
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Checking for suffix after "@"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Looking up realm "hoge.ac.jp"
for User-Name = "rt015 at hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Found realm
"~^(.+\.)?hoge\.ac\.jp$"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Adding Stripped-User-Name =
"rt015"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Adding Realm = "hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Authentication realm is LOCAL
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from suffix (rlm_realm)
Thu Jul 25 19:49:50 2019 : Debug: (15) [suffix] = ok
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
eap (rlm_eap)
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: Peer sent EAP Response (code 2)
ID 6 length 95
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: Continuing tunnel setup
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from eap (rlm_eap)
Thu Jul 25 19:49:50 2019 : Debug: (15) [eap] = ok
Thu Jul 25 19:49:50 2019 : Debug: (15) } # authorize = ok
Thu Jul 25 19:49:50 2019 : Debug: (15) Found Auth-Type = eap
Thu Jul 25 19:49:50 2019 : Debug: (15) # Executing group from file
/etc/raddb/sites-enabled/default
Thu Jul 25 19:49:50 2019 : Debug: (15) authenticate {
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authenticate]: calling
eap (rlm_eap)
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: Expiring EAP session with state
0x0973bc8b0d75a983
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: Finished EAP session with state
0x0973bc8b0d75a983
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: Previous EAP request found for
state 0x0973bc8b0d75a983, released from the list
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: Peer sent packet with method
EAP TTLS (21)
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: Calling submodule eap_ttls to
process data
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Authenticate
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Continuing EAP-TLS
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Peer sent flags --L
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Peer indicated complete
TLS record size will be 85 bytes
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Got complete TLS record
(85 bytes)
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: [eaptls verify] = length
included
Thu Jul 25 19:49:50 2019 : Debug: Ignoring cbtls_msg call with pseudo
content type 256, version 0
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: [eaptls process] = ok
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Session established.
Proceeding to decode tunneled attributes
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Got tunneled request
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: User-Name = "
rt015 at hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: User-Password =
"password"
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: FreeRADIUS-Proxied-To =
127.0.0.1
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Sending tunneled request
Thu Jul 25 19:49:50 2019 : Debug: (15) Virtual server inner-tunnel received
request
Thu Jul 25 19:49:50 2019 : Debug: (15) User-Name = "rt015 at hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) User-Password = "password"
Thu Jul 25 19:49:50 2019 : Debug: (15) FreeRADIUS-Proxied-To = 127.0.0.1
Thu Jul 25 19:49:50 2019 : WARNING: (15) Outer and inner identities are the
same. User privacy is compromised.
Thu Jul 25 19:49:50 2019 : Debug: (15) server inner-tunnel {
Thu Jul 25 19:49:50 2019 : Debug: (15) session-state: No State attribute
Thu Jul 25 19:49:50 2019 : Debug: (15) # Executing section authorize from
file /etc/raddb/sites-enabled/inner-tunnel
Thu Jul 25 19:49:50 2019 : Debug: (15) authorize {
Thu Jul 25 19:49:50 2019 : Debug: (15) policy
rewrite_called_station_id {
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
{
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Called-Station-Id &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})([^0-9a-f](.+))?$/i))
-> FALSE
Thu Jul 25 19:49:50 2019 : Debug: (15) else {
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]:
calling noop (rlm_always)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]:
returned from noop (rlm_always)
Thu Jul 25 19:49:50 2019 : Debug: (15) [noop] = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) } # else = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) } # policy
rewrite_called_station_id = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
mschap (rlm_mschap)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from mschap (rlm_mschap)
Thu Jul 25 19:49:50 2019 : Debug: (15) [mschap] = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
suffix (rlm_realm)
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Checking for suffix after "@"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Looking up realm "hoge.ac.jp"
for User-Name = "rt015 at hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Found realm
"~^(.+\.)?hoge\.ac\.jp$"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Adding Stripped-User-Name =
"rt015"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Adding Realm = "hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) suffix: Authentication realm is LOCAL
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from suffix (rlm_realm)
Thu Jul 25 19:49:50 2019 : Debug: (15) [suffix] = ok
Thu Jul 25 19:49:50 2019 : Debug: (15) update control {
Thu Jul 25 19:49:50 2019 : Debug: (15) &Proxy-To-Realm := LOCAL
Thu Jul 25 19:49:50 2019 : Debug: (15) } # update control = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
eap (rlm_eap)
Thu Jul 25 19:49:50 2019 : Debug: (15) eap: No EAP-Message, not doing EAP
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from eap (rlm_eap)
Thu Jul 25 19:49:50 2019 : Debug: (15) [eap] = noop
........
Thu Jul 25 19:49:50 2019 : Debug: Adding 1 matches
Thu Jul 25 19:49:50 2019 : Debug: (15) if
(&outer.request:NAS-IP-Address =~ /^10\.254\.0\.24[1]{1}$/) -> TRUE
Thu Jul 25 19:49:50 2019 : Debug: (15) if
(&outer.request:NAS-IP-Address =~ /^10\.254\.0\.24[1]{1}$/) {
Thu Jul 25 19:49:50 2019 : Debug: (15) if
(&outer.request:Called-Station-SSID == 'authtest') {
Thu Jul 25 19:49:50 2019 : Debug: (15) if
(&outer.request:Called-Station-SSID == 'authtest') -> TRUE
Thu Jul 25 19:49:50 2019 : Debug: (15) if
(&outer.request:Called-Station-SSID == 'authtest') {
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Realm == "NULL" ||
&Realm == "edu.hoge.ac.jp" || &Realm == "edu.zzz.hoge.ac.jp" || &Realm == "
hoge.ac.jp" || &Realm == "hoge.jp") {
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Realm == "NULL" ||
&Realm == "edu.hoge.ac.jp" || &Realm == "edu.zzz.hoge.ac.jp" || &Realm == "
hoge.ac.jp" || &Realm == "hoge.jp") -> TRUE
Thu Jul 25 19:49:50 2019 : Debug: (15) if (&Realm == "NULL" ||
&Realm == "edu.hoge.ac.jp" || &Realm == "edu.zzz.hoge.ac.jp" || &Realm == "
hoge.ac.jp" || &Realm == "hoge.jp") {
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]:
calling ldap_regularusers (rlm_ldap)
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: EXPAND TMPL
LITERAL
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: EXPAND TMPL
LITERAL
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: EXPAND TMPL
LITERAL
.........
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Connecting
to ldaps://ldap.edu.hoge.ac.jp:636
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): New libldap
handle 0x55fcc83a76e0
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Waiting for
bind result...
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Bind
successful
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Reserved
connection (5)
......
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: Performing search
in "ou=Users,dc=edu,dc=hoge,dc=ac,dc=jp" with filter
"(&(!(employeeType=participant))(!(employeeType=trainee))(!(zzzPersonAccountStatus=03))(!(zzzPersonAccountStatus=04))(uid=rt015))",
scope "sub"
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: Waiting for
search result...
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: User object found
at DN "uid=rt015,ou=Users,dc=edu,dc=hoge,dc=ac,dc=jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: Processing user
attributes
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: Attribute
"radiusAuthType" not found in LDAP object
.....
Thu Jul 25 19:49:50 2019 : Debug: (15) ldap_regularusers: Attribute
"radiusReplyMessage" not found in LDAP object
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Released
connection (5)
Thu Jul 25 19:49:50 2019 : Info: Need 2 more connections to reach min
connections (3)
Thu Jul 25 19:49:50 2019 : Info: rlm_ldap (ldap_regularusers): Opening
additional connection (6), 1 of 31 pending slots used
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Connecting
to ldaps://ldap.edu.hoge.ac.jp:636
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): New libldap
handle 0x55fcc8484a20
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Waiting for
bind result...
Thu Jul 25 19:49:50 2019 : Debug: rlm_ldap (ldap_regularusers): Bind
successful
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]:
returned from ldap_regularusers (rlm_ldap)
Thu Jul 25 19:49:50 2019 : Debug: (15) [ldap_regularusers] =
updated
Thu Jul 25 19:49:50 2019 : Debug: (15) update control {
Thu Jul 25 19:49:50 2019 : Debug: (15) &Auth-Type := LDAP
Thu Jul 25 19:49:50 2019 : Debug: (15) } # update control = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) update reply {
Thu Jul 25 19:49:50 2019 : Debug: (15) Executing:
/usr/sbin/ldapvlan rt015 at hoge.ac.jp:
Thu Jul 25 19:49:50 2019 : Debug: (15) Program returned code
(0) and output ''
Thu Jul 25 19:49:50 2019 : Debug: (15) EXPAND
%{exec:/usr/sbin/ldapvlan %{User-Name}}
Thu Jul 25 19:49:50 2019 : Debug: (15) -->
Thu Jul 25 19:49:50 2019 : Debug: (15)
&Tunnel-Private-Group-Id :=
Thu Jul 25 19:49:50 2019 : Debug: (15) } # update reply = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) } # if (&Realm == "NULL"
|| &Realm == "edu.hoge.ac.jp" || &Realm == "edu.zzz.hoge.ac.jp" || &Realm
== "hoge.ac.jp" || &Realm == "hoge.jp") = updated
Thu Jul 25 19:49:50 2019 : Debug: (15) } # if
(&outer.request:Called-Station-SSID == 'authtest') = updated
Thu Jul 25 19:49:50 2019 : Debug: (15) } # if
(&outer.request:NAS-IP-Address =~ /^10\.254\.0\.24[1]{1}$/) = updated
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
expiration (rlm_expiration)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from expiration (rlm_expiration)
Thu Jul 25 19:49:50 2019 : Debug: (15) [expiration] = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: calling
logintime (rlm_logintime)
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authorize]: returned
from logintime (rlm_logintime)
Thu Jul 25 19:49:50 2019 : Debug: (15) [logintime] = noop
Thu Jul 25 19:49:50 2019 : Debug: (15) } # authorize = updated
Thu Jul 25 19:49:50 2019 : Debug: (15) } # server inner-tunnel
Thu Jul 25 19:49:50 2019 : Debug: (15) Virtual server sending reply
Thu Jul 25 19:49:50 2019 : Debug: (15) Tunnel-Private-Group-Id := ""
Thu Jul 25 19:49:50 2019 : Debug: (15) eap_ttls: Tunneled authentication
will be proxied to LOCAL
Thu Jul 25 19:49:50 2019 : WARNING: (15) eap: Tunneled session will be
proxied. Not doing EAP
Thu Jul 25 19:49:50 2019 : Debug: (15) modsingle[authenticate]:
returned from eap (rlm_eap)
Thu Jul 25 19:49:50 2019 : Debug: (15) [eap] = handled
Thu Jul 25 19:49:50 2019 : Debug: (15) } # authenticate = handled
Thu Jul 25 19:49:50 2019 : Debug: (15) Starting proxy to home server
210.151.94.186 port 1812
Thu Jul 25 19:49:50 2019 : Debug: (15) Empty pre-proxy section in virtual
server "default". Using default return values.
Thu Jul 25 19:49:50 2019 : Debug: (15) proxy: Trying to allocate ID (0/2)
Thu Jul 25 19:49:50 2019 : Debug: (15) proxy: request is now in proxy hash
Thu Jul 25 19:49:50 2019 : Debug: (15) proxy: allocating destination
210.151.94.186 port 1812 - Id 39
Thu Jul 25 19:49:50 2019 : Debug: (15) Proxying request to home server
210.151.94.186 port 1812 timeout 30.000000
Thu Jul 25 19:49:50 2019 : Debug: (15) Sent Access-Request Id 39 from
0.0.0.0:55501 to 210.151.94.186:1812 length 78
Thu Jul 25 19:49:50 2019 : Debug: (15) User-Name = "rt015 at hoge.ac.jp"
Thu Jul 25 19:49:50 2019 : Debug: (15) User-Password = "password"
Thu Jul 25 19:49:50 2019 : Debug: (15) Message-Authenticator := 0x00
Thu Jul 25 19:49:50 2019 : Debug: (15) Proxy-State = 0x323434
Thu Jul 25 19:49:50 2019 : Debug: Waking up in 0.2 seconds.
Thu Jul 25 19:49:50 2019 : Debug: (15) Expecting proxy response no later
than 29.701569 seconds from now
Thu Jul 25 19:49:50 2019 : Debug: Waking up in 4.3 seconds.
Thu Jul 25 19:49:52 2019 : Debug: (15) Sending duplicate proxied request to
home server 210.151.94.186 port 1812 - ID: 39
Thu Jul 25 19:49:52 2019 : Debug: (15) Sent Access-Request Id 39 from
0.0.0.0:55501 to 210.151.94.186:1812 length 78
Thu Jul 25 19:49:52 2019 : Debug: (15) User-Name = "rt015 at hoge.ac.jp"
Thu Jul 25 19:49:52 2019 : Debug: (15) User-Password = "password"
Thu Jul 25 19:49:52 2019 : Debug: (15) Message-Authenticator := 0x00
Thu Jul 25 19:49:52 2019 : Debug: (15) Proxy-State = 0x323434
Thu Jul 25 19:49:52 2019 : Debug: Waking up in 2.6 seconds.
Thu Jul 25 19:49:52 2019 : Debug: (15) Clearing existing &reply: attributes
Thu Jul 25 19:49:52 2019 : Debug: (15) Received Access-Reject Id 39 from
210.151.94.186:1812 to xxx.15.xxx.14:55501 length 25
Thu Jul 25 19:49:52 2019 : Debug: (15) Proxy-State = 0x323434
Thu Jul 25 19:49:52 2019 : Debug: (15) # Executing section post-proxy from
file /etc/raddb/sites-enabled/default
Thu Jul 25 19:49:52 2019 : Debug: (15) post-proxy {
Thu Jul 25 19:49:52 2019 : Debug: (15) modsingle[post-proxy]: calling
eap (rlm_eap)
Thu Jul 25 19:49:52 2019 : Debug: (15) eap: Doing post-proxy callback
Thu Jul 25 19:49:52 2019 : Debug: (15) eap: Passing reply from proxy back
into the tunnel
Thu Jul 25 19:49:52 2019 : Debug: (15) eap: Got tunneled Access-Reject
Thu Jul 25 19:49:52 2019 : Debug: (15) eap: Reply was rejected
Thu Jul 25 19:49:52 2019 : Debug: (15) eap: Failed in post-proxy callback
Thu Jul 25 19:49:52 2019 : Debug: (15) eap: Sending EAP Failure (code 4) ID
6 length 4
Thu Jul 25 19:49:52 2019 : Debug: (15) modsingle[post-proxy]: returned
from eap (rlm_eap)
Thu Jul 25 19:49:52 2019 : Debug: (15) [eap] = reject
Thu Jul 25 19:49:52 2019 : Debug: (15) } # post-proxy = reject
Thu Jul 25 19:49:52 2019 : Debug:
%{control:Auth-Type};%{%{outer.request:Calling-Station-Id}:-%{Calling-Station-Id}};%{Called-Station-Id};%{Connect-Info};%{Fortinet-Vdom-Name};%{NAS-Identifier};%{Framed-IP-Address};%{request:User-Name}
Thu Jul 25 19:49:52 2019 : Debug: Parsed xlat tree:
Thu Jul 25 19:49:52 2019 : Debug: attribute --> Auth-Type
.....
Thu Jul 25 19:49:52 2019 : Debug: literal --> ;
Thu Jul 25 19:49:52 2019 : Debug: attribute --> User-Name
Thu Jul 25 19:49:52 2019 : Debug: (15) EXPAND
%{control:Auth-Type};%{%{outer.request:Calling-Station-Id}:-%{Calling-Station-Id}};%{Called-Station-Id};%{Connect-Info};%{Fortinet-Vdom-Name};%{NAS-Identifier};%{Framed-IP-Address};%{request:User-Name}
Thu Jul 25 19:49:52 2019 : Debug: (15) -->
eap;50-3E-AA-6D-ED-7E;08-35-71-F2-CE-05;CONNECT 802.11g;;;;rt015 at hoge.ac.jp
★Thu Jul 25 19:49:52 2019 : Auth: (15) Login incorrect (Home Server says
so): [rt015] (from client netwlc01 port 12289 cli 50-3E-AA-6D-ED-7E)
eap;50-3E-AA-6D-ED-7E;08-35-71-F2-CE-05;CONNECT 802.11g;;;;rt015 at hoge.ac.jp
More information about the Freeradius-Users
mailing list