eap-mschapv
近期都在处理网关产品的radius mschapv2认证过程，有些东西还是记录一下吧！
freeradius的架构还是相当有意思；
- * 每个method 都有对应的authorize 、authenticate、post_auth 等相关函数。
- * 每个module 都有一个method，没有module都有一个instantiate
- * 每个module都会编译成一个动态库，入口函数为config等, * 所有的module都会根据name 挂在到rbtree里面， 查找module以及method时需要根据name来查找
extern module_t rlm_test; module_t rlm_test = { .magic = RLM_MODULE_INIT, .name = "test", .type = RLM_TYPE_THREAD_SAFE, .inst_size = sizeof(rlm_test_t), .config = module_config, .instantiate = mod_instantiate, .detach = mod_detach, .methods = { [MOD_AUTHENTICATE] = mod_authenticate, [MOD_AUTHORIZE] = mod_authorize, #ifdef WITH_ACCOUNTING [MOD_PREACCT] = mod_preacct, [MOD_ACCOUNTING] = mod_accounting, [MOD_SESSION] = mod_checksimul #endif }, };
每个request 默认入口server为default server， 根据default server 里面的authorize里面的配置依次调用 eap/pap等方法的authorize会掉接口。如果匹配则返回ok，然后走authenticate逻辑。 同样的逻辑 根据default server里面的authenticate配置，调用eap等方法，如果eap报文中有eap_peap则根据逻辑 调用eap_peap,eap_eap根据逻辑会调用mschap逻辑，此时需要使用inner-tunnel server 作为入口， 在inner-tunnel server 里面查找module(比如 mschap 或者pam 或者ladp)。 然后完后调用post_auth来继续验证相关信息。
认证报文的log如下：
[debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 223 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]EAP-Message = 0x0201002e017465726d5f64643762626362612d316131612d346238302d613963322d653634336430623539386231 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]Message-Authenticator = 0xb1c5d20665611c535d65abf65bf8fc7e 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:03 (0) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 1 length 46 [eap_start@853]EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eap_method_select@374]Peer sent packet with method EAP Identity (1) [eap_module_call@177]Calling submodule eap_md5 to process data [mod_session_init@73]Issuing MD5 Challenge [eap_compose@631]Sending EAP Request (code 1) ID 2 length 22 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392aef1d7ce [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 80 2023-04-17 15:03:03 (0) [rdebug_proto_pair_list@814]EAP-Message = 0x0102001604109db9adbadfd07dd9c884c4036c8a60a0 2023-04-17 15:03:03 (0) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:03 (0) [rdebug_proto_pair_list@814]State = 0xaef3d392aef1d7ce143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +27 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 201 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]EAP-Message = 0x020200060319 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]Message-Authenticator = 0x09a37821b511f2042bf1ef7da6b036d7 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]State = 0xaef3d392aef1d7ce143ff2f753916e7e [fr_state_get_vps@625]session-state: No cached attributes [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 2 length 6 [eap_start@864]No EAP Start, assuming it's an on-going EAP conversation [modcall_recurse@586][eap] = updated [modcall_recurse@586][files] = noop [mod_authorize@521]Not doing PAP as Auth-Type is already set. [modcall_recurse@586][pap] = noop [modcall_recurse@798]} # authorize = updated [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0xaef3d392aef1d7ce [eaplist_delete@189]Finished EAP session with state 0xaef3d392aef1d7ce [eaplist_find@493]Previous EAP request found for state 0xaef3d392aef1d7ce, released from the list [eap_method_select@374]Peer sent packet with method EAP NAK (3) [eap_process_nak@314]Found mutually acceptable type PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [tls_new_session@669](TLS) Initiating new session [mod_session_init@240][eaptls start] = request [eap_compose@631]Sending EAP Request (code 1) ID 3 length 6 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392aff0cace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:03 (1) [rdebug_pair_list@781]Framed-MTU = 994 [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 64 2023-04-17 15:03:03 (1) [rdebug_proto_pair_list@814]EAP-Message = 0x010300061920 2023-04-17 15:03:03 (1) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:03 (1) [rdebug_proto_pair_list@814]State = 0xaef3d392aff0cace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +27 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 367 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]EAP-Message = 0x020300ac1980000000a2160303009d010000990303643cef2873b03fa019c5f1fac656d0151be728d25eb202576ccf4dbbc2c3845500002ac02cc02bc030c02f009f009ec024c023c028c027c00ac009c014c013009d009c003d003c0035002f000a01000046000500050100000000000a00080006001d00170018000b00020100000d001a00180804080508060401050102010403050302030202060106030023000000170000ff01000100 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]Message-Authenticator = 0x10e1ec6b17aa860b6d95c567ca25775d 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]State = 0xaef3d392aff0cace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 3 length 172 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0xaef3d392aff0cace [eaplist_delete@189]Finished EAP session with state 0xaef3d392aff0cace [eaplist_find@493]Previous EAP request found for state 0xaef3d392aff0cace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --L [eaptls_verify@435](TLS) EAP Peer says that the final record size will be 162 bytes [eaptls_verify@492](TLS) EAP Got all data (162 bytes) [eaptls_process@871](TLS) EAP Verification says length included [cbtls_info@95](TLS) Handshake state - before/accept initialization [cbtls_info@95](TLS) Handshake state - Server before/accept initialization [tls_session_information@1594](TLS) recv TLS 1.2 Handshake, ClientHello [cbtls_info@95](TLS) Handshake state - Server SSLv3 read client hello A [tls_session_information@1594](TLS) send TLS 1.2 Handshake, ServerHello [cbtls_info@95](TLS) Handshake state - Server SSLv3 write server hello A [tls_session_information@1594](TLS) send TLS 1.2 Handshake, Certificate [cbtls_info@95](TLS) Handshake state - Server SSLv3 write certificate A [tls_session_information@1594](TLS) send TLS 1.2 Handshake, ServerKeyExchange [cbtls_info@95](TLS) Handshake state - Server SSLv3 write key exchange A [tls_session_information@1594](TLS) send TLS 1.2 Handshake, ServerHelloDone [cbtls_info@95](TLS) Handshake state - Server SSLv3 write server done A [cbtls_info@95](TLS) Handshake state - Server SSLv3 flush data [cbtls_info@95](TLS) Handshake state - Server SSLv3 read client certificate A [cbtls_info@116](TLS) Server : Need to read more data: SSLv3 read client key exchange A [cbtls_info@116](TLS) Server : Need to read more data: SSLv3 read client key exchange A [tls_handshake_recv@1040](TLS) In Handshake Phase [mod_process@284][eaptls process] = handled [eap_compose@631]Sending EAP Request (code 1) ID 4 length 1004 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392acf7cace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]Framed-MTU = 994 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:03 (2) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 1068 2023-04-17 15:03:03 (2) [rdebug_proto_pair_list@814]EAP-Message = 0x010403ec19c0000005a716030300390200003503037f235aea39de8d69e46f19209edeacb1b382261c8a566b3f28f7b20d94e931d000c03000000dff01000100000b00040300010216030304090b0004050004020003ff308203fb308202e3a003020102021100a70ed1817b7f778061e124356ed97f03300d06092a864886f70d01010b0500308190310b300906035504061302434e3111300f060355040813085a68656a69616e673111300f0603550407130848616e677a686f75312a3028060355040a0c21e69dade5b79ee4babfe6a0bce4ba91e7a791e68a80e69c89e99990e585ace58fb831123010060355040b0c09e4babfe6a0bce4ba91311b3019060355040313124561676c65436c6f756420526f6f74204341301e170d3233303332333033333933345a170d3333303332303033333933345a3057310b300906035504061302434e312a3028060355040a0c21e69dade5b79ee4babfe6a0bce4ba91e7a791e68a80e69c89e99990e585ace58fb8311c30 2023-04-17 15:03:03 (2) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:03 (2) [rdebug_proto_pair_list@814]State = 0xaef3d392acf7cace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +27 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 201 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]EAP-Message = 0x020400061900 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]Message-Authenticator = 0x8f938c5bad54dc58ea09f0ac82df6a92 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]State = 0xaef3d392acf7cace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 4 length 6 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0xaef3d392acf7cace [eaplist_delete@189]Finished EAP session with state 0xaef3d392acf7cace [eaplist_find@493]Previous EAP request found for state 0xaef3d392acf7cace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --- [tls_ack_handler@5299](TLS) Peer ACKed our handshake fragment [eaptls_process@871](TLS) EAP Verification says request [mod_process@284][eaptls process] = handled [eap_compose@631]Sending EAP Request (code 1) ID 5 length 459 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392adf6cace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]Framed-MTU = 994 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:03 (3) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 519 2023-04-17 15:03:03 (3) [rdebug_proto_pair_list@814]EAP-Message = 0x010501cb1900cabf58fb5b64e36eba3509af7c2a4efe3d4d800e0020967cc818752748873f634011c6c6fd4e3149b03cb0245238c2d38ee9badad741054c63ef7a0d4ba3b085e17f1e5c517b677fd2f06856ffd377f6a5cee962d2af92546243cff1529dba48dab988e81af24d0b4a52160303014d0c0001490300174104bb1b7976a8f915885556faeadc7318e01da364a8eac4758633cd30c0e9fdbf6daf4832b71e20eaf98abc77f90eb02e892aef93c09d4812f22034dc51850a060604010100298f5e6b8bf94023edf654b5d45adc09d3acaa7da55a8adb79d755c9e5b7f3873c26a3746184dcca8abdebd8c6c5a1598b6066de50928ded2052986987ad6cc243c665a4f445f7140147fc4bc777705d31cf8a3e5b71893992f12347382a82615bcb6c9f889a7a6d4816a14c8066695cf3ad951ef7451ac54827dac1b4236a9171f092e50cffeb67666c926ef2cbbde23d3579c3b932fb67aff917b822adc2afa4e5b645e01890cff0832bb3864977a7c1c14ae74b 2023-04-17 15:03:03 (3) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:03 (3) [rdebug_proto_pair_list@814]State = 0xaef3d392adf6cace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +27 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 331 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]EAP-Message = 0x0205008819800000007e1603030046100000424104e46adba9836d4c47785244a2e3a868a5c446bdfc3cde3d748b9bd23d432fd2cefb7c9eb7a46762457f5553f227c2f1b43ef336d7dec94b430ee193d9959e4dc014030300010116030300280000000000000000a391d4126985ad2be0bd8e8dc94aa85c533e00ad9ddbc743670f1777bf8bb54e 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]Message-Authenticator = 0x44cfe7c91d8210b5d6c08ff2e04c6f01 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]State = 0xaef3d392adf6cace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 5 length 136 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0xaef3d392adf6cace [eaplist_delete@189]Finished EAP session with state 0xaef3d392adf6cace [eaplist_find@493]Previous EAP request found for state 0xaef3d392adf6cace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --L [eaptls_verify@435](TLS) EAP Peer says that the final record size will be 126 bytes [eaptls_verify@492](TLS) EAP Got all data (126 bytes) [eaptls_process@871](TLS) EAP Verification says length included [tls_session_information@1594](TLS) recv TLS 1.2 Handshake, ClientKeyExchange [cbtls_info@95](TLS) Handshake state - Server SSLv3 read client key exchange A [cbtls_info@95](TLS) Handshake state - Server SSLv3 read certificate verify A [tls_session_information@1594](TLS) recv TLS 1.2 ChangeCipherSpec [tls_session_information@1594](TLS) recv TLS 1.2 Handshake, Finished [cbtls_info@95](TLS) Handshake state - Server SSLv3 read finished A [tls_session_information@1594](TLS) send TLS 1.2 ChangeCipherSpec [cbtls_info@95](TLS) Handshake state - Server SSLv3 write change cipher spec A [tls_session_information@1594](TLS) send TLS 1.2 Handshake, Finished [cbtls_info@95](TLS) Handshake state - Server SSLv3 write finished A [cbtls_info@95](TLS) Handshake state - Server SSLv3 flush data [cbtls_info@95](TLS) Handshake state - SSL negotiation finished successfully [tls_handshake_recv@989](TLS) Connection Established 2023-04-17 15:03:03 (4) eap_peap: [rdebug_pair@751]TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:03 (4) eap_peap: [rdebug_pair@751]TLS-Session-Version = "TLS 1.2" [mod_process@284][eaptls process] = handled [eap_compose@631]Sending EAP Request (code 1) ID 6 length 57 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392aaf5cace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]Framed-MTU = 994 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:03 (4) [rdebug_pair_list@781]TLS-Session-Version = "TLS 1.2" [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 115 2023-04-17 15:03:03 (4) [rdebug_proto_pair_list@814]EAP-Message = 0x01060039190014030300010116030300289314abe0ff19504712d9cde880b28955f43106e4a6cbe781db9bc062e316dcc0b1c031335b9926f3 2023-04-17 15:03:03 (4) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:03 (4) [rdebug_proto_pair_list@814]State = 0xaef3d392aaf5cace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +27 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 201 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]EAP-Message = 0x020600061900 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]Message-Authenticator = 0x6f13c83e049ac2ba919f198232a5fcb3 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]State = 0xaef3d392aaf5cace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]&session-state:TLS-Session-Version = "TLS 1.2" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 6 length 6 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0xaef3d392aaf5cace [eaplist_delete@189]Finished EAP session with state 0xaef3d392aaf5cace [eaplist_find@493]Previous EAP request found for state 0xaef3d392aaf5cace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --- [tls_ack_handler@5288](TLS) Peer ACKed our handshake fragment. handshake is finished [eaptls_process@871](TLS) EAP Verification says success [mod_process@284][eaptls process] = success [mod_process@339]Session established. Decoding tunneled attributes [eappeap_process@762]PEAP state TUNNEL ESTABLISHED [eap_compose@631]Sending EAP Request (code 1) ID 7 length 40 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392abf4cace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]Framed-MTU = 994 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:03 (5) [rdebug_pair_list@781]TLS-Session-Version = "TLS 1.2" [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 98 2023-04-17 15:03:03 (5) [rdebug_proto_pair_list@814]EAP-Message = 0x010700281900170303001d9314abe0ff1950481d7e24c201c9944adb9b3ce4bc8dfcb6aa1237dd9a 2023-04-17 15:03:03 (5) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:03 (5) [rdebug_proto_pair_list@814]State = 0xaef3d392abf4cace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +27 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 241 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]EAP-Message = 0x0207002e19001703030023000000000000000194a61dde9741b79ad5c64eb465ca9170da6b4cf48a435018687fa3 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]Message-Authenticator = 0xb79f8f85b1224971d7ed95837ce24329 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]State = 0xaef3d392abf4cace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]&session-state:TLS-Session-Version = "TLS 1.2" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 7 length 46 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0xaef3d392abf4cace [eaplist_delete@189]Finished EAP session with state 0xaef3d392abf4cace [eaplist_find@493]Previous EAP request found for state 0xaef3d392abf4cace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --- [eaptls_process@871](TLS) EAP Verification says ok [eaptls_process@902](TLS) EAP Done initial handshake [mod_process@284][eaptls process] = ok [mod_process@339]Session established. Decoding tunneled attributes [eappeap_process@762]PEAP state WAITING FOR INNER IDENTITY [eapmessage_verify@236]Identity - QT2ZXX1S7F [eappeap_process@814]Got inner identity 'QT2ZXX1S7F' [eappeap_process@952]Setting default EAP type for tunneled EAP session [eappeap_process@973]Got tunneled request 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x0207000f015154325a585831533746 [setup_fake_request@1229]Setting User-Name to QT2ZXX1S7F [eappeap_process@1016]Sending tunneled request to inner-tunnel 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x0207000f015154325a585831533746 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]FreeRADIUS-Proxied-To = 127.0.0.1 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" [rad_virtual_server@731]Virtual server inner-tunnel received request 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]EAP-Message = 0x0207000f015154325a585831533746 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]FreeRADIUS-Proxied-To = 127.0.0.1 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (6) WARNING: [rad_virtual_server@776]Outer User-Name is not anonymized. User privacy is compromised. [rad_virtual_server@826]server inner-tunnel { [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]authorize { [modcall_recurse@586][mschap] = noop [eap_start@778]Peer sent EAP Response (code 2) ID 7 length 15 [eap_start@853]EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]authenticate { [eap_method_select@374]Peer sent packet with method EAP Identity (1) [eap_module_call@177]Calling submodule eap_mschapv2 to process data [mod_session_init@254]Issuing Challenge [eap_compose@631]Sending EAP Request (code 1) ID 8 length 44 [eaplist_add@406]EAP session adding &reply:State = 0x8316158f831e0f3e [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_virtual_server@886]} # server inner-tunnel [rad_virtual_server@888]Virtual server sending reply 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]EAP-Message = 0x0108002c1a0108002710852dfdf32104356d710e12b4bab694d8667265657261646975732d332e322e302e32 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]State = 0x8316158f831e0f3e021e5d5095ded832 [eappeap_process@1032]Got tunneled reply code 11 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x0108002c1a0108002710852dfdf32104356d710e12b4bab694d8667265657261646975732d332e322e302e32 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]State = 0x8316158f831e0f3e021e5d5095ded832 [process_reply@438]Got tunneled reply RADIUS code 11 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x0108002c1a0108002710852dfdf32104356d710e12b4bab694d8667265657261646975732d332e322e302e32 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (6) eap_peap: [rdebug_pair_list@781]State = 0x8316158f831e0f3e021e5d5095ded832 [process_reply@490]Got tunneled Access-Challenge [eap_compose@631]Sending EAP Request (code 1) ID 8 length 75 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392a8fbcace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]Framed-MTU = 994 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:04 (6) [rdebug_pair_list@781]TLS-Session-Version = "TLS 1.2" [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 133 2023-04-17 15:03:04 (6) [rdebug_proto_pair_list@814]EAP-Message = 0x0108004b190017030300409314abe0ff19504912a030f1e3141aca302ee97866c30c880dbfa2ac9f0fbba8a4fcbdbb6e996c14cf310f1a26e6a72cca80485e9f1f4c9e33655de3eb103578 2023-04-17 15:03:04 (6) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (6) [rdebug_proto_pair_list@814]State = 0xaef3d392a8fbcace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +28 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 295 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]EAP-Message = 0x02080064190017030300590000000000000002c52c499da5a24a4ed2827bc4dcef9a6fce3552be04724c4da1a81a7cd9354ceca25fceba28bb6ad4e102d269d05399315848d5e2130b0237ce65f96b66c3b8f99d841c60ae1f8f849ca1760762d9ee02b7 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Message-Authenticator = 0x6bb5984c37a59e390116661627952d01 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]State = 0xaef3d392a8fbcace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]&session-state:TLS-Session-Version = "TLS 1.2" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 8 length 100 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0x8316158f831e0f3e [eaplist_delete@189]Finished EAP session with state 0xaef3d392a8fbcace [eaplist_find@493]Previous EAP request found for state 0xaef3d392a8fbcace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --- [eaptls_process@871](TLS) EAP Verification says ok [eaptls_process@902](TLS) EAP Done initial handshake [mod_process@284][eaptls process] = ok [mod_process@339]Session established. Decoding tunneled attributes [eappeap_process@762]PEAP state phase2 [eapmessage_verify@260]EAP method MSCHAPv2 (26) [eappeap_process@973]Got tunneled request 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x020800451a0208004031d954eb2435ef7b4aed4f846339083f3b00000000000000004e91c3f3b20e61c154231b2acfe89d287881d5f7be514d1b005154325a585831533746 [setup_fake_request@1229]Setting User-Name to QT2ZXX1S7F [eappeap_process@1016]Sending tunneled request to inner-tunnel 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x020800451a0208004031d954eb2435ef7b4aed4f846339083f3b00000000000000004e91c3f3b20e61c154231b2acfe89d287881d5f7be514d1b005154325a585831533746 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]FreeRADIUS-Proxied-To = 127.0.0.1 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]State = 0x8316158f831e0f3e021e5d5095ded832 [rad_virtual_server@731]Virtual server inner-tunnel received request 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]EAP-Message = 0x020800451a0208004031d954eb2435ef7b4aed4f846339083f3b00000000000000004e91c3f3b20e61c154231b2acfe89d287881d5f7be514d1b005154325a585831533746 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]FreeRADIUS-Proxied-To = 127.0.0.1 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]State = 0x8316158f831e0f3e021e5d5095ded832 2023-04-17 15:03:04 (7) WARNING: [rad_virtual_server@776]Outer User-Name is not anonymized. User privacy is compromised. [rad_virtual_server@826]server inner-tunnel { [fr_state_get_vps@625]session-state: No cached attributes [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]authorize { [modcall_recurse@586][mschap] = noop [eap_start@778]Peer sent EAP Response (code 2) ID 8 length 69 [eap_start@864]No EAP Start, assuming it's an on-going EAP conversation [modcall_recurse@586][eap] = updated [file_common@435]users: Matched entry QT2ZXX1S7F at line 1 [xlat_expand@2622]EXPAND Hello, %{User-Name} [xlat_expand@2623] --> Hello, QT2ZXX1S7F [modcall_recurse@586][files] = ok 2023-04-17 15:03:04 (7) pap: WARNING: [mod_authorize@546]Auth-Type already set. Not setting to PAP [modcall_recurse@586][pap] = noop [modcall_recurse@798]} # authorize = updated [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0x8316158f831e0f3e [eaplist_delete@189]Finished EAP session with state 0x8316158f831e0f3e [eaplist_find@493]Previous EAP request found for state 0x8316158f831e0f3e, released from the list [eap_method_select@374]Peer sent packet with method EAP MSCHAPv2 (26) [eap_module_call@177]Calling submodule eap_mschapv2 to process data [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]authenticate { [mod_authenticate@1769]Found Cleartext-Password, hashing to create NT-Password [mod_authenticate@2093]Creating challenge hash with username: QT2ZXX1S7F [mod_authenticate@2099]Client is using MS-CHAPv2 [mod_authenticate@2159]Adding MS-CHAPv2 MPPE keys [modcall_recurse@586][mschap] = ok [modcall_recurse@798]} # authenticate = ok [eapmschapv2_compose@171]MSCHAP Success [eap_compose@631]Sending EAP Request (code 1) ID 9 length 51 [eaplist_add@406]EAP session adding &reply:State = 0x8316158f821f0f3e [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_virtual_server@886]} # server inner-tunnel [rad_virtual_server@888]Virtual server sending reply 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Reply-Message = "Hello, QT2ZXX1S7F" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]EAP-Message = 0x010900331a0308002e533d31323037323344454630324444453339324544334341333137384346434135443535314531303542 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]State = 0x8316158f821f0f3e021e5d5095ded832 [eappeap_process@1032]Got tunneled reply code 11 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]Reply-Message = "Hello, QT2ZXX1S7F" 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x010900331a0308002e533d31323037323344454630324444453339324544334341333137384346434135443535314531303542 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]State = 0x8316158f821f0f3e021e5d5095ded832 [process_reply@438]Got tunneled reply RADIUS code 11 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]Reply-Message = "Hello, QT2ZXX1S7F" 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x010900331a0308002e533d31323037323344454630324444453339324544334341333137384346434135443535314531303542 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (7) eap_peap: [rdebug_pair_list@781]State = 0x8316158f821f0f3e021e5d5095ded832 [process_reply@490]Got tunneled Access-Challenge [eap_compose@631]Sending EAP Request (code 1) ID 9 length 82 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392a9facace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]Framed-MTU = 994 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:04 (7) [rdebug_pair_list@781]TLS-Session-Version = "TLS 1.2" [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 140 2023-04-17 15:03:04 (7) [rdebug_proto_pair_list@814]EAP-Message = 0x01090052190017030300479314abe0ff19504abb31ad012dcd0111fd2d41f8bcf29f498823f38496ea3e12b19b0d106ce4ece2e1933f4a96dbea0bb96d4bd67dc9512adfc8f38b3bc2c5d50c0fbffef2f8ca 2023-04-17 15:03:04 (7) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (7) [rdebug_proto_pair_list@814]State = 0xaef3d392a9facace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +28 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 232 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]EAP-Message = 0x020900251900170303001a00000000000000038d087f5ca69f3d187d7ceb93650a5007c9e6 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Message-Authenticator = 0x3dad4ad1f4e45abd5cfbc87695c950b4 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]State = 0xaef3d392a9facace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]&session-state:TLS-Session-Version = "TLS 1.2" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 9 length 37 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0x8316158f821f0f3e [eaplist_delete@189]Finished EAP session with state 0xaef3d392a9facace [eaplist_find@493]Previous EAP request found for state 0xaef3d392a9facace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --- [eaptls_process@871](TLS) EAP Verification says ok [eaptls_process@902](TLS) EAP Done initial handshake [mod_process@284][eaptls process] = ok [mod_process@339]Session established. Decoding tunneled attributes [eappeap_process@762]PEAP state phase2 [eapmessage_verify@260]EAP method MSCHAPv2 (26) [eappeap_process@973]Got tunneled request 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x020900061a03 [setup_fake_request@1229]Setting User-Name to QT2ZXX1S7F [eappeap_process@1016]Sending tunneled request to inner-tunnel 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x020900061a03 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]FreeRADIUS-Proxied-To = 127.0.0.1 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]State = 0x8316158f821f0f3e021e5d5095ded832 [rad_virtual_server@731]Virtual server inner-tunnel received request 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]EAP-Message = 0x020900061a03 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]FreeRADIUS-Proxied-To = 127.0.0.1 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]State = 0x8316158f821f0f3e021e5d5095ded832 2023-04-17 15:03:04 (8) WARNING: [rad_virtual_server@776]Outer User-Name is not anonymized. User privacy is compromised. [rad_virtual_server@826]server inner-tunnel { [fr_state_get_vps@625]session-state: No cached attributes [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]authorize { [modcall_recurse@586][mschap] = noop [eap_start@778]Peer sent EAP Response (code 2) ID 9 length 6 [eap_start@864]No EAP Start, assuming it's an on-going EAP conversation [modcall_recurse@586][eap] = updated [file_common@435]users: Matched entry QT2ZXX1S7F at line 1 [xlat_expand@2622]EXPAND Hello, %{User-Name} [xlat_expand@2623] --> Hello, QT2ZXX1S7F [modcall_recurse@586][files] = ok 2023-04-17 15:03:04 (8) pap: WARNING: [mod_authorize@546]Auth-Type already set. Not setting to PAP [modcall_recurse@586][pap] = noop [modcall_recurse@798]} # authorize = updated [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0x8316158f821f0f3e [eaplist_delete@189]Finished EAP session with state 0x8316158f821f0f3e [eaplist_find@493]Previous EAP request found for state 0x8316158f821f0f3e, released from the list [eap_method_select@374]Peer sent packet with method EAP MSCHAPv2 (26) [eap_module_call@177]Calling submodule eap_mschapv2 to process data [eap_compose@631]Sending EAP Success (code 3) ID 9 length 4 [mod_authenticate@431]Freeing handler [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authenticate = ok [rad_virtual_server@880]Virtual server(inner-tunnel) sending post_auth [indexed_modcall@1018]# Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel [modcall_recurse@794]post-auth { [modcall_recurse@483]if ( ! &FreeRADIUS-Stats-Error) { [modcall_recurse@496]if ( ! &FreeRADIUS-Stats-Error) -> TRUE [modcall_recurse@794]if ( ! &FreeRADIUS-Stats-Error) { [modcall_recurse@599]update request { [map_debug_log@1703]&FreeRADIUS-Stats-Error = "accept" [modcall_recurse@612]} # update request = noop [modcall_recurse@798]} # if ( ! &FreeRADIUS-Stats-Error) = noop [fr_connection_get_internal@906]rlm_rest (rest): Reserved connection (0) [rlm_rest_perform@107]Expanding URI components [xlat_expand@2622]EXPAND https://sp.pre.eagleyun.cn [xlat_expand@2623] --> https://sp.pre.eagleyun.cn [xlat_expand@2622]EXPAND /api/inner/nac/v1/radius/auth?ins_id=spa_e61b1178-631f-44f4-8dc0-23153118569e&radius_id=server_def2fcc2-03ba-4ceb-a5df-506db4d2fbe5 [xlat_expand@2623] --> /api/inner/nac/v1/radius/auth?ins_id=spa_e61b1178-631f-44f4-8dc0-23153118569e&radius_id=server_def2fcc2-03ba-4ceb-a5df-506db4d2fbe5 [rlm_rest_perform@116]Sending HTTP POST to "https://sp.pre.eagleyun.cn/api/inner/nac/v1/radius/auth?ins_id=spa_e61b1178-631f-44f4-8dc0-23153118569e&radius_id=server_def2fcc2-03ba-4ceb-a5df-506db4d2fbe5" [xlat_expand@2622]EXPAND {"te_id": "%{outer.request:User-Name}", "identity_id":"%{outer.request:User-Name}", "user_name": "%{User-Name}", "CHAP-Password": "%{CHAP-Password}","CHAP-Challenge": "%{CHAP-Challenge}", "user_password": "%{User-Password}", "radius_auth_result": "%{FreeRADIUS-Stats-Error}", "client_ip":"%{Framed-IP-Address}", "nas_ip": "%{NAS-IP-Address}","client_mac": "%{Calling-Station-Id}", "nas_mac": "%{Called-Station-Id}", "access_type": "%{NAS-Port-Type}", "eap_type": "%{EAP-Type}", "module_fail_msg": "%{Module-Failure-Message}", "nas_identifier": "%{NAS-Identifier}", "auth_type": "%{request:Auth-Type}", "aruba_ssid": "%{Aruba-Essid-Name}"} [xlat_expand@2623] --> {"te_id": "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1", "identity_id":"term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1", "user_name": "QT2ZXX1S7F", "CHAP-Password": "","CHAP-Challenge": "", "user_password": "", "radius_auth_result": "accept", "client_ip":"", "nas_ip": "","client_mac": "", "nas_mac": "", "access_type": "", "eap_type": "MSCHAPv2", "module_fail_msg": "", "nas_identifier": "", "auth_type": "", "aruba_ssid": ""} [rest_response_header@1632]Processing response header [rest_response_header@1698]Status : 200 (OK) [rest_response_header@1729]Type : json (application/json) [rest_request_perform@2426]Adding reply:REST-HTTP-Status-Code = "200" [json_pair_make@1404]Parsing attribute "request_id" 2023-04-17 15:03:04 (8) rest: WARNING: [json_pair_make@1407]Failed parsing attribute: Invalid vendor name in attribute name "request_id", skipping... [json_pair_make@1404]Parsing attribute "code" 2023-04-17 15:03:04 (8) rest: WARNING: [json_pair_make@1407]Failed parsing attribute: Invalid vendor name in attribute name "code", skipping... [json_pair_make@1404]Parsing attribute "message" 2023-04-17 15:03:04 (8) rest: WARNING: [json_pair_make@1407]Failed parsing attribute: Invalid vendor name in attribute name "message", skipping... [json_pair_make@1404]Parsing attribute "data" 2023-04-17 15:03:04 (8) rest: WARNING: [json_pair_make@1407]Failed parsing attribute: Invalid vendor name in attribute name "data", skipping... [json_pair_make@1404]Parsing attribute "data_not_changed" 2023-04-17 15:03:04 (8) rest: WARNING: [json_pair_make@1407]Failed parsing attribute: Invalid vendor name in attribute name "data_not_changed", skipping... [fr_connection_release@1397]rlm_rest (rest): Released connection (0) Need 1 more connections to reach min connections (3) Need more connections to reach 1 spares rlm_rest (rest): Opening additional connection (2), 1 of 2 pending slots used [mod_conn_create@418]rlm_rest (rest): Connecting to "https://sp.pre.eagleyun.cn" [New Thread 0x7ffff290d700 (LWP 30316)] [Thread 0x7ffff290d700 (LWP 30316) exited] [modcall_recurse@586][rest.authorize] = ok [modcall_recurse@483]if (ok || updated) { [modcall_recurse@496]if (ok || updated) -> TRUE [modcall_recurse@794]if (ok || updated) { [modcall_recurse@599]update control { [map_debug_log@1703]&Auth-Type := Accept [modcall_recurse@612]} # update control = noop [modcall_recurse@798]} # if (ok || updated) = noop [modcall_recurse@553]... skipping else: Preceding "if" was taken [modcall_recurse@483]if (0) { [modcall_recurse@496]if (0) -> FALSE [modcall_recurse@798]} # post-auth = ok [rad_virtual_server@886]} # server inner-tunnel [rad_virtual_server@888]Virtual server sending reply 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Reply-Message = "Hello, QT2ZXX1S7F" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]MS-MPPE-Encryption-Policy = Encryption-Allowed 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]MS-MPPE-Send-Key = 0x20a7b83cdd8363a365e7c74cf3dafeed 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]MS-MPPE-Recv-Key = 0x27f5ace2792fe90669987a3419a11e52 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]EAP-Message = 0x03090004 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]REST-HTTP-Status-Code := 200 [eappeap_process@1032]Got tunneled reply code 2 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]Reply-Message = "Hello, QT2ZXX1S7F" 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Encryption-Policy = Encryption-Allowed 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Send-Key = 0x20a7b83cdd8363a365e7c74cf3dafeed 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Recv-Key = 0x27f5ace2792fe90669987a3419a11e52 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x03090004 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]REST-HTTP-Status-Code := 200 [process_reply@438]Got tunneled reply RADIUS code 2 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]Reply-Message = "Hello, QT2ZXX1S7F" 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Encryption-Policy = Encryption-Allowed 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Send-Key = 0x20a7b83cdd8363a365e7c74cf3dafeed 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]MS-MPPE-Recv-Key = 0x27f5ace2792fe90669987a3419a11e52 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]EAP-Message = 0x03090004 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (8) eap_peap: [rdebug_pair_list@781]REST-HTTP-Status-Code := 200 [process_reply@444]Tunneled authentication was successful [eappeap_success@76]SUCCESS [process_reply@458]Saving tunneled attributes for later [eap_compose@631]Sending EAP Request (code 1) ID 10 length 46 [eaplist_add@406]EAP session adding &reply:State = 0xaef3d392a6f9cace [modcall_recurse@586][eap] = handled [modcall_recurse@798]} # authenticate = handled [rad_postauth@320]Using Post-Auth-Type Challenge [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@790]Challenge { ... } # empty sub-section is ignored [fr_state_put_vps@679]session-state: Saving cached attributes 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]Framed-MTU = 994 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:04 (8) [rdebug_pair_list@781]TLS-Session-Version = "TLS 1.2" [debug_packet@490]Sent Access-Challenge Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 104 2023-04-17 15:03:04 (8) [rdebug_proto_pair_list@814]EAP-Message = 0x010a002e190017030300239314abe0ff19504b4e73dc781b0fc27175b956bb90866f35f9e9357e587f52616df7a4 2023-04-17 15:03:04 (8) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (8) [rdebug_proto_pair_list@814]State = 0xaef3d392a6f9cace143ff2f753916e7e [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [request_done@900]Cleaning up request packet ID 0 with timestamp +28 due to conflicting packet was received [debug_packet@490]Received Access-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1812 length 241 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]Framed-MTU = 1450 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]EAP-Message = 0x020a002e1900170303002300000000000000044f7077b5834d68a2b3eae37086313c6740e7d92e5b13cedfb73c32 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]Message-Authenticator = 0xb4ca96e32c93c7cc184e185e03d7a6fd 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]Service-Type = Framed-User 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]Framed-Protocol = PPP 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]State = 0xaef3d392a6f9cace143ff2f753916e7e [fr_state_get_vps@612]Restoring &session-state 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:Framed-MTU = 994 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientHello" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, ClientKeyExchange" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) recv TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 ChangeCipherSpec" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Finished" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" 2023-04-17 15:03:04 (9) [rdebug_pair_list@781]&session-state:TLS-Session-Version = "TLS 1.2" [indexed_modcall@1018]# Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authorize { [eap_start@778]Peer sent EAP Response (code 2) ID 10 length 46 [eap_start@837]Continuing tunnel setup [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authorize = ok [rad_check_password@192]Found Auth-Type = eap [indexed_modcall@1021]# Executing group from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]authenticate { [eaplist_expire@235]Expiring EAP session with state 0xaef3d392a6f9cace [eaplist_delete@189]Finished EAP session with state 0xaef3d392a6f9cace [eaplist_find@493]Previous EAP request found for state 0xaef3d392a6f9cace, released from the list [eap_method_select@374]Peer sent packet with method EAP PEAP (25) [eap_module_call@177]Calling submodule eap_peap to process data [eaptls_process@856](TLS) EAP Continuing ... [eaptls_verify@377](TLS) EAP Peer sent flags --- [eaptls_process@871](TLS) EAP Verification says ok [eaptls_process@902](TLS) EAP Done initial handshake [mod_process@284][eaptls process] = ok [mod_process@339]Session established. Decoding tunneled attributes [eappeap_process@762]PEAP state send tlv success [eapmessage_verify@246]Received EAP-TLV response [eappeap_process@866]Success [mod_process@378]Using saved attributes from the original Access-Accept 2023-04-17 15:03:04 (9) eap_peap: [rdebug_pair_list@781]Reply-Message = "Hello, QT2ZXX1S7F" 2023-04-17 15:03:04 (9) eap_peap: [rdebug_pair_list@781]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (9) eap_peap: [rdebug_pair_list@781]REST-HTTP-Status-Code := 200 [eap_compose@631]Sending EAP Success (code 3) ID 10 length 4 [mod_authenticate@431]Freeing handler [modcall_recurse@586][eap] = ok [modcall_recurse@798]} # authenticate = ok [indexed_modcall@1018]# Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]post-auth { [modcall_recurse@483]if (session-state:User-Name && reply:User-Name && request:User-Name && (reply:User-Name == request:User-Name)) { [modcall_recurse@496]if (session-state:User-Name && reply:User-Name && request:User-Name && (reply:User-Name == request:User-Name)) -> FALSE [modcall_recurse@599]update { [map_debug_log@1698]&reply::Framed-MTU += &session-state:Framed-MTU[*] -> 994 [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) recv TLS 1.2 Handshake, ClientHello' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) send TLS 1.2 Handshake, ServerHello' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) send TLS 1.2 Handshake, Certificate' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) send TLS 1.2 Handshake, ServerKeyExchange' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) send TLS 1.2 Handshake, ServerHelloDone' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) recv TLS 1.2 Handshake, ClientKeyExchange' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) recv TLS 1.2 ChangeCipherSpec' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) recv TLS 1.2 Handshake, Finished' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) send TLS 1.2 ChangeCipherSpec' [map_debug_log@1698]&reply::TLS-Session-Information += &session-state:TLS-Session-Information[*] -> '(TLS) send TLS 1.2 Handshake, Finished' [map_debug_log@1698]&reply::TLS-Session-Cipher-Suite += &session-state:TLS-Session-Cipher-Suite[*] -> 'ECDHE-RSA-AES256-GCM-SHA384' [map_debug_log@1698]&reply::TLS-Session-Version += &session-state:TLS-Session-Version[*] -> 'TLS 1.2' [modcall_recurse@612]} # update = noop [modcall_recurse@794]policy remove_reply_message_if_eap { [modcall_recurse@483]if (&reply:EAP-Message && &reply:Reply-Message) { [modcall_recurse@496]if (&reply:EAP-Message && &reply:Reply-Message) -> TRUE [modcall_recurse@794]if (&reply:EAP-Message && &reply:Reply-Message) { [modcall_recurse@599]update reply { [map_debug_log@1703]&Reply-Message !* ANY [modcall_recurse@612]} # update reply = noop [modcall_recurse@798]} # if (&reply:EAP-Message && &reply:Reply-Message) = noop [modcall_recurse@553]... skipping else: Preceding "if" was taken [modcall_recurse@798]} # policy remove_reply_message_if_eap = noop [modcall_recurse@483]if (EAP-Key-Name && &reply:EAP-Session-Id) { [modcall_recurse@496]if (EAP-Key-Name && &reply:EAP-Session-Id) -> FALSE [modcall_recurse@798]} # post-auth = noop [debug_packet@490]Sent Access-Accept Id 0 from 10.30.0.147:1812 to 171.43.249.97:6745 length 178 2023-04-17 15:03:04 (9) [rdebug_proto_pair_list@814]User-Name = "QT2ZXX1S7F" 2023-04-17 15:03:04 (9) [rdebug_proto_pair_list@814]MS-MPPE-Recv-Key = 0x7932949431898a1f38d2b06adab6e605ba4f40f7c28f9a2846935a4106ae5f27 2023-04-17 15:03:04 (9) [rdebug_proto_pair_list@814]MS-MPPE-Send-Key = 0x17291dae23c1ae3c7d7ffca1fad7bf85c96c39767e8eb4b97bec63e21eaba4a6 2023-04-17 15:03:04 (9) [rdebug_proto_pair_list@814]EAP-Message = 0x030a0004 2023-04-17 15:03:04 (9) [rdebug_proto_pair_list@814]Message-Authenticator = 0x00000000000000000000000000000000 2023-04-17 15:03:04 (9) [rdebug_proto_pair_list@814]Framed-MTU += 994 [request_finish@1584]Finished request [event_status@5207]Waking up in 4.9 seconds. [debug_packet@490]Received Accounting-Request Id 0 from 171.43.249.97:6745 to 10.30.0.147:1813 length 174 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]User-Name = "term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1" 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]NAS-Identifier = "H3C" 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]NAS-Port = 16789505 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]NAS-Port-Id = "slot=1;subslot=0;port=3;vlanid=1" 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]NAS-Port-Type = Ethernet 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]Calling-Station-Id = "88-A4-C2-95-3E-B3" 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]Acct-Status-Type = Start 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]Acct-Authentic = RADIUS 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]Acct-Session-Id = "100032910159010" 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]NAS-IP-Address = 192.168.1.140 2023-04-17 15:03:04 (10) [rdebug_pair_list@781]Event-Timestamp = "Apr 29 2000 18:15:56 CST" [indexed_modcall@1018]# Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]preacct { [modcall_recurse@794]policy acct_unique { [modcall_recurse@599]update request { [map_debug_log@1703]&Tmp-String-9 := "ai:" [modcall_recurse@612]} # update request = noop [modcall_recurse@483]if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { [tmpl_aexpand@1620]EXPAND %{hex:&Class} [tmpl_aexpand@1621] --> [tmpl_aexpand@1620]EXPAND ^%{hex:&Tmp-String-9} [tmpl_aexpand@1621] --> ^61693a [modcall_recurse@496]if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE [modcall_recurse@794]else { [modcall_recurse@599]update request { [map_to_vp@835]EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} [map_to_vp@836] --> 1e2d1fa6c022f6cc76805f8d747cc193 [map_debug_log@1703]&Acct-Unique-Session-Id := 1e2d1fa6c022f6cc76805f8d747cc193 [modcall_recurse@612]} # update request = noop [modcall_recurse@798]} # else = noop [modcall_recurse@599]update request { [map_debug_log@1703]&Tmp-String-9 !* ANY [modcall_recurse@612]} # update request = noop [modcall_recurse@798]} # policy acct_unique = noop [modcall_recurse@586][files] = noop [modcall_recurse@798]} # preacct = noop [indexed_modcall@1018]# Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default [modcall_recurse@794]accounting { [modcall_recurse@586][exec] = noop [xlat_expand@2622]EXPAND %{User-Name} [xlat_expand@2623] --> term_dd7bbcba-1a1a-4b80-a9c2-e643d0b598b1 [attr_filter_common@209]Matched entry DEFAULT at line 12 [modcall_recurse@586][attr_filter.accounting_response] = updated [modcall_recurse@798]} # accounting = updated [debug_packet@490]Sent Accounting-Response Id 0 from 10.30.0.147:1813 to 171.43.249.97:6745 length 20 [request_finish@1584]Finished request [request_done@900]Cleaning up request packet ID 0 with timestamp +28 due to done [event_status@5207]Waking up in 4.9 seconds.
Detailed Sequence of the EAP-PEAP-Active Directory Handshake Exchange
|
Extensible Authentication Protocol over LAN (EAPOL) Start
|
||
|---|---|---|
|
1 |
The authenticator sends an EAP-Request for the identity of the connecting supplicant (client device). |
|
|
2 |
The supplicant responds to the authenticator with an EAP Identity Response that contains the identity (username) used for authentication. This is referred to as the "Outer Identity." |
|
|
3 |
The authenticator forwards the EAP Identity Response with the identity of the user to the authentication server (ClearPass Policy Manager). |
|
|
Active Directory
|
||
|---|---|---|
|
4 |
The authentication server performs an LDAP lookup against its configured Active Directory authentication sources to try to find the user's name in the directory, along with some basic LDAP attributes, such as sAMAccountName. |
|
|
5 |
The LDAP server responds to the authentication server's LDAP search request with the appropriate answers to the LDAP lookup. |
|
|
EAPOL
|
||
|---|---|---|
|
6
|
The authentication server responds to the supplicant through the authenticator with an EAP-Request message indicating that it would like to initiate EAP-PEAP. |
|
|
7 |
The authenticator passes the EAP-Request message to the supplicant. |
|
|
Transport Layer Security (TLS) Tunnel Setup
|
|
|---|---|
|
8 |
The supplicant sends a Transport Layer Security (TLS) "Client Hello" message within an EAP-response message through the authenticator to the authentication server. |
|
9 |
The authenticator passes the EAP-Response message containing the TLS Client Hello message to the authentication server. |
|
10 |
The authentication server responds with a TLS Handshake message of types "Server Hello," "Certificate," "Server Key Exchange," and "Server Hello Done" to the authenticator. |
|
11 |
The authenticator forwards the TLS handshake messages between the authentication server and the supplicant inside of EAP Request (server) and EAP Response (supplicant) messages. |
|
12 |
Steps 10 and 11 repeat until the authentication server has transmitted all of its handshake messages. This may take several steps due to having to dismantle the certificates into fragments that fit within the size limits of an EAP message. |
|
13 |
The supplicant sends another TLS Handshake message inside an EAP-Response message of types "Client Key Exchange," "Change Cipher Spec," "Handshake," and "Client Finished" to the authenticator. |
|
14 |
The authenticator sends this EAP-Response to the authentication server. |
|
14 |
The authentication server responds to the authenticator with an EAP-Request for the supplicant that contains the message types "Change Cipher Spec" and "Server Finished." |
|
16 |
The authenticator passes the EAP message to the supplicant. |
|
17 |
The supplicant sends an EAP-Response for the authentication server to the authenticator. |
|
18 |
The authenticator sends the EAP-Response to the authentication server. |
|
Inner EAP MSCHAPv2
|
|
|---|---|
|
19 |
Inside the TLS tunnel, the EAP process starts again with the authentication server sending an EAP Identity Request to the supplicant requesting the client's identity. |
|
20 |
The authenticator sends the EAP Identity Request message to the supplicant requesting the client's identity. |
|
21 |
The supplicant responds with an EAP Identity Response containing its identity to the authenticator. |
|
22 |
The authenticator forwards this EAP Identity Response to the authentication server. |
|
Active Directory
|
||
|---|---|---|
|
23 |
The authentication server performs an LDAP lookup against its configured Active Directory authentication sources to try to find the user's name in the directory, along with some basic LDAP attributes, such as sAMAccountName. |
|
|
24 |
The LDAP server responds to the LDAP search request with the appropriate answers to the query. |
|
|
Inner EAP MSCHAPv2
|
|
|---|---|
|
25 |
The authentication server sends an EAP request to the supplicant containing an MS-CHAPv2 challenge. |
|
26 |
The authenticator forwards the EAP request to the supplicant. |
|
27 |
The supplicant responds with an EAP Identity Response containing its identity to the authenticator. |
|
28 |
The authenticator forwards this EAP Identity Response to the authentication server. |
|
Active Directory
|
||
|---|---|---|
|
29 |
The authentication server takes the username and the MSCHAPv2 response from the supplicant and combines it with the MSCHAPv2 challenge and the NetBIOS name of the Active Directory domain and submits this set of information to the Active Directory domain controller for authentication. This is done via NT LAN Manager (NTLM). |
|
|
30 |
The Active Directory domain controller lets the authentication server know that the authentication was successful. |
|
|
Inner EAP MSCHAPv2
|
|
|---|---|
|
31 |
The authentication server sends an EAP-Request message for the supplicant with an MSCHAPv2 success message and an authenticator response string from the Active Directory Domain Controller to the authenticator. |
|
32 |
The authenticator passes the EAP-Request with an MSCHAPv2 success message and the authenticator response to the supplicant. |
|
33 |
The supplicant sends an EAP-Response message for the authentication server with an MSCHAPv2 success message to the authenticator. |
|
34 |
The authenticator sends the EAP-Response message from the supplicant with the MSCHAPv2 success message to the authentication server. |
|
35 |
The authentication server sends an EAP-Request message to the authenticator indicating that the Inner EAP method was successful. |
|
36 |
The authenticator forwards this EAP-Request to the supplicant. |
|
37
|
The supplicant sends an EAP-Response to the authentication server, acknowledging that the Inner EAP method was successful. |
|
38 |
The authenticator forwards the EAP-Response from the the supplicant to the authentication server. |
|
EAPOL
|
||
|---|---|---|
|
39 |
The authentication server sends a RADIUS access-accept message to the authenticator with an EAPOL success message along with the key material. |
|
|
40 |
The authenticator sends an EAPOL success message to the supplicant. |
|
|
41 |
The authenticator and supplicant complete a four-way handshake to start the flow of encrypted wireless traffic. |
|
MSCHAP方式是,首先服务器发一个challenge给用户,用户向RADIUS发一个用MD4加密的(password,challenge)给RADIUS(叫response),
radius的MSCHAP模块向LDAP询问NTPASSWORD,然后自己再用challenge和NTPASSWORD,来计算一个response,两个response相比较完成验证.
如果LDAP无法给出NTPASSWORD或送出SHA加密的NTPASSWORD,MS-CHAP就无法验证了.
唯一可行的办法是把LDAP的SCHEMA中加入NTPASSWORD域,并明文存放,才能满足MS-CHAP的要求.
PEAP-MSCHAPV2流程：
1、创建一个连接后，AP发送一个EAP-Request/Identity消息给客户端。
2、客户端回复一个EAP-Response/Identity消息，包含客户端的标识，通常是名字。
3、AP把这个消息传递给Radius服务器。从现在开始，逻辑通信就从Radius服务器到无线客户端了，AP,AC是一个中介设备。
4、Radius服务器发送一个EAP-Request/Start PEAP消息给客户端。
5、无线客户端和Radius服务器发送一系列的TLS消息通过协商建立的隧道。Raiuds服务器发送一个证书链让客户端认证。最后，Radius服务器已经认证了无线客户端。两端都决定使用的加密信息。在PEAP TLS隧道创建后，采用MS-CHAPV2认证。
6、Radius服务器发送一个EAP-Request/Identity消息。
7、无线客户端发送一个EAP-Response/Identity 消息，消息包用户名。
8、Radius服务器发送一个EAP-Request/EAP-MS-CHAP-V2挑战消息，包含挑战字符串。
9、无线客户端回复一个EAP-Response/EAP-MS-CHAPV2回复消息，包含对这个挑战的应答和一个自己的挑战。
(用户向RADIUS发一个用MD4加密的(password,challenge)给RADIUS(叫response))
10、Radius服务器发送一个EAP-Request/EAP-MS-CHAPV2成功的消息，指出无线客户端的回应是正确的，且包含无线客户端的挑战字符串。
11、无线客户端回应一个EAP-Response/EAP-MS-CHAPV2的ACK消息，指示Radius服务器的回应消息是正确的。
12、Radius服务器发送一个EAP-Success消息。
10、Radius服务器发送一个EAP-Request/EAP-MS-CHAPV2成功的消息，指出无线客户端的回应是正确的，且包含无线客户端的挑战字符串。
11、无线客户端回应一个EAP-Response/EAP-MS-CHAPV2的ACK消息，指示Radius服务器的回应消息是正确的。
12、Radius服务器发送一个EAP-Success消息。
mschapv2-authentication-and-evil-twin-attack
此过程遵循以下步骤：
- 客户端以“ hello”消息启动协议。
- 身份验证服务器使用16字节ServerChallenge进行回答。
- 客户端将ServerChallenge，16字节随机ClientChallenge和用户名结合起来以创建ChallengeHash。
- 然后，客户端计算NTHash（即用户密码的MD4哈希），并将其填充为0到21个字节。
- 客户端将21字节长的NTHash拆分为三个7字节长的DES密钥。将奇偶校验位添加到每7位，以创建一个8字节长的DES密钥。
- 每个密钥用于加密ChallengeHash。这三个ChallengeHashes的串联构成了ChallengeResponse。
- 24字节的ChallengeResponse，16字节的ChallengeHash和UserName发送到AS。
- AS必须使用AuthenticationResponse进行回答，该认证使用用户密码的md4哈希值的md4哈希值与用户发送的ChallengeResponse相结合，两个常量语句和ChallengeHash。发送此消息是为了验证服务器也知道密码。
NTLM 协议的认证过程分为三步：
- 协商 : 主要用于确认双方协议版本
- 质询 : 就是挑战（Challenge）/响应（Response）认证机制起作用的范畴
- 验证 : 验证主要是在质询完成后，验证结果，是认证的最后一步。
NTLMv2
NTLMv1 和 NTLMv2 的加密因素都是 NTLM Hash，而最显著的区别就是 Challenge 和加密算法不同,共同点就是加密的原料都是 NTLM Hash。
- Challage： NTLMv1 的 Challenge 有 8 位，NTLMv2 的 Challenge 为 16 位。
- Net-NTLM Hash：NTLMv1 的主要加密算法是 DES，NTLMv2 的主要加密算法是 HMAC-MD5。
设置系统使用 LM 还是 NTLM 还是 NTLMv2，需要修改 Local Security Policy 中的 LmCompatibilityLevel 选项
- 深刻理解windows安全认证机制
- Windows用户密码的加密方法与破解
- Windows下的密码hash——NTLM hash和Net-NTLM hash介绍
- 浅学Windows认证
- 技术干货 | Windows认证体系解读
- 彻底理解Windows认证 - 议题解读
- NT LAN Manager - Wikipedia
- LAN Manager - Wikipedia
- Windows内网协议学习NTLM篇之NTLM基础介绍
NTLM（NT LAN Manager）是一种Windows系统中用于认证的协议，NTHash 和 LMHash 则是 NTLM 协议中用于存储密码散列（hash）的两种不同算法。
NTHash（NTLM Hash）
- 安全性更高：
NTHash是一种更安全的密码散列算法，它使用的是 MD4（Message Digest 4）哈希算法。 - 大部分情况下使用： 在现代 Windows 系统中，默认情况下，密码存储和验证使用
NTHash。 - 长度固定：
NTHash生成的哈希长度固定为 128 位（16字节）。
LMHash（LAN Manager Hash）
- 较弱的安全性：
LMHash是比较老旧且不够安全的密码散列算法，它将密码分为小写字符，然后将其转换为大写，并使用 DES 算法进行哈希。 - 在较老的系统中使用： 在更早期的 Windows 系统中，默认情况下会使用
LMHash存储密码。但从安全性角度考虑，现代 Windows 系统已经越来越少使用它，并且有一些配置可以禁用它。 - 较短的长度：
LMHash生成的哈希长度为 64 位（8字节），相对较短。
区别总结
主要区别在于安全性和算法：
- 安全性：
NTHash比LMHash更安全，因为它使用了更复杂的哈希算法（MD4），相比之下，LMHash在今天的标准下被认为是不够安全的。 - 算法：
NTHash使用 MD4 哈希算法，而LMHash使用的是更弱的 DES 算法。
现代的 Windows 系统更倾向于使用 NTHash 存储密码散列，并且在安全性要求高的环境中，LMHash 已经被禁用或者被弃用。
http代理服务器（3-4-7层代理）-网络事件库公共组件、内核kernel驱动 摄像头驱动 tcpip网络协议栈、netfilter、bridge 好像看过！！！！
但行好事 莫问前程
--身高体重180的胖子
