ntlm_auth authentication results logging messages

19 May 2011

      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.

ntlm_auth authentication results logging messages

John Douglass