I am running freeradius-2.1.10 and ntlm_auth Version 3.0.33-3.29.el5_6.2. Because our AD is managed by a different area (and we rely upon this for user authentication), I am looking for ways to assist our customer support area with appropriate logs to help debug AD issues. Sometimes, due to bad processes, things don't always stay in sync across the domain. What I have found is that ntlm_auth can return a variety of states like the following (I am sure there is more): [root@dvlana ~]# ntlm_auth --request-nt-key --domain=AD --username=douglass --password=CORRECTPASSWORD NT_STATUS_OK: Success (0x0) [root@dvlana ~]# ntlm_auth --request-nt-key --domain=AD --username=douglass --password=BADPASSWORDHERE NT_STATUS_WRONG_PASSWORD: Wrong Password (0xc000006a) [root@dvlana ~]# ntlm_auth --request-nt-key --domain=AD --username=douglass --password=CORRECTPASSWORD NT_STATUS_ACCOUNT_DISABLED: Account disabled (0xc0000072) [root@dvlana ~]# ntlm_auth --request-nt-key --domain=AD --username=douglass12 --password=PASSWORD NT_STATUS_NO_SUCH_USER: No such user (0xc0000064) Now, the actual ntlm_auth command within the $RADIUS/modules/mschap does read: ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --username=%{%{Stripped-User-Name}:-%{User-Name:-None}} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}" So it's not doing necessarily the same kind of authentication command as I was doing above but I have no idea how to simulate a challege request on command line to verify :) I found a similar user in an old thread who submitted a patch: (http://freeradius.1045715.n5.nabble.com/Capturing-ntlm-auth-failure-reasons-...) And it appears that this patch made it into the rlm_mschap.c module code: if (result != 0) { char *p; VALUE_PAIR *vp = NULL; RDEBUG2("External script failed."); vp = pairmake("Module-Failure-Message", "", T_OP_EQ); if (!vp) { radlog_request(L_ERR, 0, request, "No memory to allocate Module-Failure-Message"); return RLM_MODULE_FAIL; } p = strchr(buffer, '\n'); if (p) *p = '\0'; snprintf(vp->vp_strvalue, sizeof(vp->vp_strvalue), "%s: External script says %s", inst->xlat_name, buffer); vp->length = strlen(vp->vp_strvalue); pairadd(&request->packet->vps, vp); return -1; } However, when I view my debug for freeradius: mschap] FAILED: MS-CHAP2-Response is incorrect ++[mschap] returns reject [eap] Freeing handler ++[eap] returns reject Failed to authenticate the user. Login incorrect (mschap: External script says Logon failure (0xc000006d)): [asdf/<via Auth-Type = EAP>] (from client LAWN-WiSM port 29 cli 00-25-00-f5-a3-2b via TLS tunnel) However, "Logon failure" is nebulous when it could be either "bad password", "account disabled", or "no such user" that comes out of the "ntlm_auth" command (at least when I run it by hand). Is this the fault of the results of ntlm_auth being vague or is something else at play? I also see that there may be a pair added with "Module-Failure-Message". No where do I see that in a debug session when I force a failure to occur (debug is below). Would that pair show up if it were available? If so, any suggestions on how to get the output of ntlm_auth logged correctly? Am I missing a logging option or configuration option to enable me to get additional information out of the ntlm_auth failure or is this code not functioning correctly? Below is a full debug of a failed authentication with a non-existent user "asdf": rad_recv: Access-Request packet from host 10.80.10.42 port 32769, id=54, length=180 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" EAP-Message = 0x020200090161736466 Message-Authenticator = 0xbeb78b0b65e4a5537d6a1e14f56a93ac server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 2 length 9 [eap] No EAP Start, assuming it's an on-going EAP conversation ++[eap] returns updated [sqlwpa] expand: %{Stripped-User-Name} -> [sqlwpa] ... expanding second conditional [sqlwpa] expand: %{User-Name} -> asdf [sqlwpa] expand: %{%{User-Name}:-DEFAULT} -> asdf [sqlwpa] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> asdf [sqlwpa] sql_set_user escaped user --> 'asdf' rlm_sql (sqlwpa): Reserving sql socket id: 63 [sqlwpa] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'asdf' ORDER BY id [sqlwpa] expand: SELECT determineGroup('%{Calling-Station-Id}','%{SQL-User-Name}','%{Called-Station-Id}') as groupname -> SELECT determineGroup('00-25-00-f5-a3-2b','asdf','00-25-45-37-5c-60:GTtestwpa') as groupname [sqlwpa] expand: SELECT id, groupname, attribute, value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupcheck WHERE groupname = 'NOTAUTHORIZED' ORDER BY id [sqlwpa] User found in group NOTAUTHORIZED [sqlwpa] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'NOTAUTHORIZED' ORDER BY id rlm_sql (sqlwpa): Released sql socket id: 63 ++[sqlwpa] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] EAP Identity [eap] processing type tls [tls] Initiate [tls] Start returned 1 ++[eap] returns handled } # server wpa Sending Access-Challenge of id 54 to 10.80.10.42 port 32769 Tunnel-Private-Group-Id:0 = "1296" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 EAP-Message = 0x010300061920 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x31b2f23b31b1eb74b6745cb38a442dac Finished request 0. Going to the next request Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 10.80.10.42 port 32769, id=55, length=353 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" EAP-Message = 0x020300a419800000009a16030100950100009103014dd565aa6f9f79a7fcdb3709b02977dec9ebd8d8aeb7a7bdf7058c390773fbf2000056c00ac009c007c008c013c014c011c012c004c005c002c003c00ec00fc00cc00d002f000500040035000a000900030008000600320033003800390016001500140013001200110034003a0018001b001a00170019000101000012000a00080006001700180019000b00020100 State = 0x31b2f23b31b1eb74b6745cb38a442dac Message-Authenticator = 0xdf3024ad1da5df56ca9df7671138d5cf server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 3 length 164 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS TLS Length 154 [peap] Length Included [peap] eaptls_verify returned 11 [peap] (other): before/accept initialization [peap] TLS_accept: before/accept initialization [peap] <<< TLS 1.0 Handshake [length 0095], ClientHello [peap] TLS_accept: SSLv3 read client hello A [peap] >>> TLS 1.0 Handshake [length 002a], ServerHello [peap] TLS_accept: SSLv3 write server hello A [peap] >>> TLS 1.0 Handshake [length 0377], Certificate [peap] TLS_accept: SSLv3 write certificate A [peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone [peap] TLS_accept: SSLv3 write server done A [peap] TLS_accept: SSLv3 flush data [peap] TLS_accept: Need to read more data: SSLv3 read client certificate A In SSL Handshake Phase In SSL Accept mode [peap] eaptls_process returned 13 [peap] EAPTLS_HANDLED ++[eap] returns handled } # server wpa Sending Access-Challenge of id 55 to 10.80.10.42 port 32769 EAP-Message = 0x010403ba1900160301002a0200002603014dd565a8ca1007fb5fafe0ddb0d92a0d821d77a8cf126a16b64b6452926bda3900002f0016030103770b00037300037000036d30820369308202d2a003020102020312c13e300d06092a864886f70d0101050500304e310b30090603550406130255533110300e060355040a130745717569666178312d302b060355040b1324457175696661782053656375726520436572746966696361746520417574686f72697479301e170d3130303530393035343732315a170d3132303531313034323731325a3081d13129302706035504051320704c4234414d775646504c43546d2d337651486e62686934324a EAP-Message = 0x753746687961310b30090603550406130255533110300e0603550408130747656f726769613110300e0603550407130741746c616e746131283026060355040a131f47656f7267696120496e73746974757465206f6620546563686e6f6c6f677931293027060355040b13204f6666696365206f6620496e666f726d6174696f6e20546563686e6f6c6f6779311e301c0603550403131567747770612e6c61776e2e6761746563682e65647530819f300d06092a864886f70d010101050003818d0030818902818100d345aabc73a7777a683c06f6b359843b2b59523670ab0bce78ea74759290de2f8765a959fc7e197ba6829ef3da7fd6ea538dd98e EAP-Message = 0xbfa46c8d26d724fee83a3eeb378a64410d9d92994f07208a0e90468a34af8d7d77e14aaa1d78b24f6a95af7034d8482d4e43626cc74c2bb5331b09dc59ba38b1fa60c6b9cfe841b2411089cf0203010001a381d03081cd301f0603551d2304183016801448e668f92bd2b295d747d82320104f3398909fd4300e0603551d0f0101ff0404030204f0301d0603551d250416301406082b0601050507030106082b0601050507030230200603551d1104193017821567747770612e6c61776e2e6761746563682e656475303a0603551d1f04333031302fa02da02b8629687474703a2f2f63726c2e67656f74727573742e636f6d2f63726c732f73656375 EAP-Message = 0x726563612e63726c301d0603551d0e041604146bd1c091faa8c9499db94ce449259017b097ecb2300d06092a864886f70d01010505000381810025a28346aaa5901f60d6e5004331971e1352103836c33a9845bfa928307a0472c7c87fe6eab5c81faecfca6b2d23af4496e70ef6a1ad775746a6329fef7e960eb8e06274c161accca9277c94b25bc03cdec5ed92b059ea5bd6fbb2668fe5a3d6da4454579368de2c4a583576a1ffae45c7e89c5ce8164572c5af1272ac0042ae16030100040e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x31b2f23b30b6eb74b6745cb38a442dac Finished request 1. Going to the next request Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 10.80.10.42 port 32769, id=56, length=397 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" EAP-Message = 0x020400d01980000000c61603010086100000820080824a1517cc81fa0cde571f1c83147f0123f0ef6edf77a5db2c0ef03549a153c52f52c9d79e264c32cd37c8dc2155296528d2e9c7c66dcf6e6f638f11ffbdd7b932ed59299291db2f03e0830a15c7ec73bc8d42e19dc072f1a8bbbcf76df8a5cd02f7539a38c738242efdfc44fc232c20453886259ef36a33e7efd7aee22ca9d91403010001011603010030699d7d6451132470124ce6ea5e09507ec2504300d2e58010c2bfbcce1f50706a8689bfcc0287372fbf62cd49d04d974f State = 0x31b2f23b30b6eb74b6745cb38a442dac Message-Authenticator = 0x862f8d931f012e27f3a8d078d66e228f server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 4 length 208 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS TLS Length 198 [peap] Length Included [peap] eaptls_verify returned 11 [peap] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange [peap] TLS_accept: SSLv3 read client key exchange A [peap] <<< TLS 1.0 ChangeCipherSpec [length 0001] [peap] <<< TLS 1.0 Handshake [length 0010], Finished [peap] TLS_accept: SSLv3 read finished A [peap] >>> TLS 1.0 ChangeCipherSpec [length 0001] [peap] TLS_accept: SSLv3 write change cipher spec A [peap] >>> TLS 1.0 Handshake [length 0010], Finished [peap] TLS_accept: SSLv3 write finished A [peap] TLS_accept: SSLv3 flush data [peap] (other): SSL negotiation finished successfully SSL Connection Established [peap] eaptls_process returned 13 [peap] EAPTLS_HANDLED ++[eap] returns handled } # server wpa Sending Access-Challenge of id 56 to 10.80.10.42 port 32769 EAP-Message = 0x0105004119001403010001011603010030bf952c90cdb0d1bcdaacff835f16d35972e70d499f19ece0e99d9245d4fb5c6fea2d3006fa95d3318e3e653b09cc52e4 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x31b2f23b33b7eb74b6745cb38a442dac Finished request 2. Going to the next request Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 10.80.10.42 port 32769, id=57, length=195 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" EAP-Message = 0x020500061900 State = 0x31b2f23b33b7eb74b6745cb38a442dac Message-Authenticator = 0x58658f27fe9295794b51b5a904ee64d8 server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 5 length 6 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS [peap] Received TLS ACK [peap] ACK handshake is finished [peap] eaptls_verify returned 3 [peap] eaptls_process returned 3 [peap] EAPTLS_SUCCESS [peap] Session established. Decoding tunneled attributes. [peap] Peap state TUNNEL ESTABLISHED ++[eap] returns handled } # server wpa Sending Access-Challenge of id 57 to 10.80.10.42 port 32769 EAP-Message = 0x0106002b19001703010020972a004adb0dbb0c23c5cca84018c922ee11b6a5541026a93f86adac05dfadc1 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x31b2f23b32b4eb74b6745cb38a442dac Finished request 3. Going to the next request Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 10.80.10.42 port 32769, id=58, length=232 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" EAP-Message = 0x0206002b19001703010020fe91dead08f0cc02d9d4581c8ccc77178098fd94a677579d72445bf14cde899f State = 0x31b2f23b32b4eb74b6745cb38a442dac Message-Authenticator = 0x331fbbeecc815c337c717573976b7da2 server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 6 length 43 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS [peap] eaptls_verify returned 7 [peap] Done initial handshake [peap] eaptls_process returned 7 [peap] EAPTLS_OK [peap] Session established. Decoding tunneled attributes. [peap] Peap state WAITING FOR INNER IDENTITY [peap] Identity - asdf [peap] Got inner identity 'asdf' [peap] Setting default EAP type for tunneled EAP session. [peap] Got tunneled request EAP-Message = 0x020600090161736466 server wpa { PEAP: Setting User-Name to asdf Sending tunneled request EAP-Message = 0x020600090161736466 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 6 length 9 [eap] No EAP Start, assuming it's an on-going EAP conversation ++[eap] returns updated [sqlwpa] expand: %{Stripped-User-Name} -> [sqlwpa] ... expanding second conditional [sqlwpa] expand: %{User-Name} -> asdf [sqlwpa] expand: %{%{User-Name}:-DEFAULT} -> asdf [sqlwpa] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> asdf [sqlwpa] sql_set_user escaped user --> 'asdf' rlm_sql (sqlwpa): Reserving sql socket id: 62 [sqlwpa] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'asdf' ORDER BY id [sqlwpa] expand: SELECT determineGroup('%{Calling-Station-Id}','%{SQL-User-Name}','%{Called-Station-Id}') as groupname -> SELECT determineGroup('00-25-00-f5-a3-2b','asdf','00-25-45-37-5c-60:GTtestwpa') as groupname [sqlwpa] expand: SELECT id, groupname, attribute, value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupcheck WHERE groupname = 'NOTAUTHORIZED' ORDER BY id [sqlwpa] User found in group NOTAUTHORIZED [sqlwpa] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'NOTAUTHORIZED' ORDER BY id rlm_sql (sqlwpa): Released sql socket id: 62 ++[sqlwpa] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] EAP Identity [eap] processing type mschapv2 rlm_eap_mschapv2: Issuing Challenge ++[eap] returns handled } # server wpa [peap] Got tunneled reply code 11 Tunnel-Private-Group-Id:0 = "1296" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 EAP-Message = 0x0107001e1a0107001910bf7d536f84202f25bf5f17b9e50ce30061736466 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x33f674ce33f16e76ae35e5f2efd87279 [peap] Got tunneled reply RADIUS code 11 Tunnel-Private-Group-Id:0 = "1296" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 EAP-Message = 0x0107001e1a0107001910bf7d536f84202f25bf5f17b9e50ce30061736466 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x33f674ce33f16e76ae35e5f2efd87279 [peap] Got tunneled Access-Challenge ++[eap] returns handled } # server wpa Sending Access-Challenge of id 58 to 10.80.10.42 port 32769 EAP-Message = 0x0107003b19001703010030797656bba21df6dbff25f4fb69fa506584cb492a8ff148c2068733a4f1cdab3427c0180871bd822a0f03e227d5bce95d Message-Authenticator = 0x00000000000000000000000000000000 State = 0x31b2f23b35b5eb74b6745cb38a442dac Finished request 4. Going to the next request Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 10.80.10.42 port 32769, id=59, length=280 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" EAP-Message = 0x0207005b19001703010050e600f6973e85bcc2bcfecb03493bb4c70c4dc5e360fec76f2e8d5820fab9a8d904d2a9fd583dd02717f2b9ad8d1a390d263da98901eca94d4f6b35b065737f522e377b97661bb14d21c129b16bc0c650 State = 0x31b2f23b35b5eb74b6745cb38a442dac Message-Authenticator = 0x57fc4a631ecb4d869888d51d38dd52a6 server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 7 length 91 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS [peap] eaptls_verify returned 7 [peap] Done initial handshake [peap] eaptls_process returned 7 [peap] EAPTLS_OK [peap] Session established. Decoding tunneled attributes. [peap] Peap state phase2 [peap] EAP type mschapv2 [peap] Got tunneled request EAP-Message = 0x0207003f1a0207003a31c3fc9644677023c2240c42be8ebcc26000000000000000001d977e4d0232ca801f0e20dde8767c7004d4ca2197cdf39b0061736466 server wpa { PEAP: Setting User-Name to asdf Sending tunneled request EAP-Message = 0x0207003f1a0207003a31c3fc9644677023c2240c42be8ebcc26000000000000000001d977e4d0232ca801f0e20dde8767c7004d4ca2197cdf39b0061736466 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "asdf" State = 0x33f674ce33f16e76ae35e5f2efd87279 Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 7 length 63 [eap] No EAP Start, assuming it's an on-going EAP conversation ++[eap] returns updated [sqlwpa] expand: %{Stripped-User-Name} -> [sqlwpa] ... expanding second conditional [sqlwpa] expand: %{User-Name} -> asdf [sqlwpa] expand: %{%{User-Name}:-DEFAULT} -> asdf [sqlwpa] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> asdf [sqlwpa] sql_set_user escaped user --> 'asdf' rlm_sql (sqlwpa): Reserving sql socket id: 61 [sqlwpa] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'asdf' ORDER BY id [sqlwpa] expand: SELECT determineGroup('%{Calling-Station-Id}','%{SQL-User-Name}','%{Called-Station-Id}') as groupname -> SELECT determineGroup('00-25-00-f5-a3-2b','asdf','00-25-45-37-5c-60:GTtestwpa') as groupname [sqlwpa] expand: SELECT id, groupname, attribute, value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupcheck WHERE groupname = 'NOTAUTHORIZED' ORDER BY id [sqlwpa] User found in group NOTAUTHORIZED [sqlwpa] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'NOTAUTHORIZED' ORDER BY id rlm_sql (sqlwpa): Released sql socket id: 61 ++[sqlwpa] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/mschapv2 [eap] processing type mschapv2 [mschapv2] # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa [mschapv2] +- entering group MS-CHAP {...} [mschap] Creating challenge hash with username: asdf [mschap] Told to do MS-CHAPv2 for asdf with NT-Password [mschap] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details [mschap] ... expanding second conditional [mschap] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details [mschap] expand: %{User-Name:-None} -> asdf [mschap] expand: --username=%{Stripped-User-Name:-%{User-Name:-None}} -> --username=asdf [mschap] mschap2: bf [mschap] Creating challenge hash with username: asdf [mschap] expand: --challenge=%{mschap:Challenge:-00} -> --challenge=0a7a21bf18732797 [mschap] expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=1d977e4d0232ca801f0e20dde8767c7004d4ca2197cdf39b Exec-Program output: Logon failure (0xc000006d) Exec-Program-Wait: plaintext: Logon failure (0xc000006d) Exec-Program: returned: 1 [mschap] External script failed. [mschap] FAILED: MS-CHAP2-Response is incorrect ++[mschap] returns reject [eap] Freeing handler ++[eap] returns reject Failed to authenticate the user. Login incorrect (mschap: External script says Logon failure (0xc000006d)): [asdf/<via Auth-Type = EAP>] (from client LAWN-WiSM port 29 cli 00-25-00-f5-a3-2b via TLS tunnel) } # server wpa [peap] Got tunneled reply code 3 Tunnel-Private-Group-Id:0 = "1296" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 MS-CHAP-Error = "\007E=691 R=1" EAP-Message = 0x04070004 Message-Authenticator = 0x00000000000000000000000000000000 [peap] Got tunneled reply RADIUS code 3 Tunnel-Private-Group-Id:0 = "1296" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 MS-CHAP-Error = "\007E=691 R=1" EAP-Message = 0x04070004 Message-Authenticator = 0x00000000000000000000000000000000 [peap] Tunneled authentication was rejected. [peap] FAILURE ++[eap] returns handled } # server wpa Sending Access-Challenge of id 59 to 10.80.10.42 port 32769 EAP-Message = 0x0108002b190017030100206e20a4a57f13f51e3edc4d3cdda2a7e64d8d8dde84c0cd825af17de0b236bbdc Message-Authenticator = 0x00000000000000000000000000000000 State = 0x31b2f23b34baeb74b6745cb38a442dac Finished request 5. Going to the next request Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 10.80.10.42 port 32769, id=60, length=232 User-Name = "asdf" Calling-Station-Id = "00-25-00-f5-a3-2b" Called-Station-Id = "00-25-45-37-5c-60:GTtestwpa" NAS-Port = 29 NAS-IP-Address = 10.80.10.42 NAS-Identifier = "Rich-core-WiSM-E" Airespace-Wlan-Id = 7 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "809" EAP-Message = 0x0208002b1900170301002022152bb0e74b3277ae1b8711d62a966e885e9b7d5beb26f9fc716b74cadea38e State = 0x31b2f23b34baeb74b6745cb38a442dac Message-Authenticator = 0x14d7bb55cd857f2216d2addb790a6291 server wpa { # Executing section authorize from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authorize {...} ++[preprocess] returns ok [eap] EAP packet type response id 8 length 43 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS [peap] eaptls_verify returned 7 [peap] Done initial handshake [peap] eaptls_process returned 7 [peap] EAPTLS_OK [peap] Session established. Decoding tunneled attributes. [peap] Peap state send tlv failure [peap] Received EAP-TLV response. [peap] The users session was previously rejected: returning reject (again.) [peap] *** This means you need to read the PREVIOUS messages in the debug output [peap] *** to find out the reason why the user was rejected. [peap] *** Look for "reject" or "fail". Those earlier messages will tell you. [peap] *** what went wrong, and how to fix the problem. [eap] Handler failed in EAP/peap [eap] Failed in EAP select ++[eap] returns invalid Failed to authenticate the user. Login incorrect: [asdf/<via Auth-Type = EAP>] (from client LAWN-WiSM port 29 cli 00-25-00-f5-a3-2b) } # server wpa Using Post-Auth-Type Reject # Executing group from file /services/freeradius/etc/raddb//sites-enabled/dvlan-wpa +- entering group REJECT {...} [attr_filter.access_reject] expand: %{User-Name} -> asdf attr_filter: Matched entry DEFAULT at line 11 ++[attr_filter.access_reject] returns updated Delaying reject of request 6 for 1 seconds Going to the next request Waking up in 0.9 seconds. Sending delayed reject for request 6 Sending Access-Reject of id 60 to 10.80.10.42 port 32769 EAP-Message = 0x04080004 Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 3.8 seconds. Cleaning up request 0 ID 54 with timestamp +26 Cleaning up request 1 ID 55 with timestamp +26 Cleaning up request 2 ID 56 with timestamp +26 Cleaning up request 3 ID 57 with timestamp +26 Cleaning up request 4 ID 58 with timestamp +26 Cleaning up request 5 ID 59 with timestamp +26 Waking up in 1.0 seconds. Cleaning up request 6 ID 60 with timestamp +26 Ready to process requests.