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@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@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@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@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@hoge.t.eduroam.jp ★Thu Jul 25 19:48:22 2019 : Auth: (9) Login OK: [hoge-test@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@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@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@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@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@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@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@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@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@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@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@hoge.ac.jp