Debugging Cisco Device Authentication to a Microsoft NPS Server

You have configured a Microsoft Network Policy Server to use as a RADIUS server for your Cisco devices. But for some reason your logins aren't successful. Use the following to trouble shoot the NPS Server:

Enable Logging on the NPS Server

Open a cmd window and enter:

netsh ras diagnostics set rastracing * enabled


Be sure to disable afterward (netsh ras diagnostics set rastracing * disabled).

These logs are saved to %windir%\tracing. You can find more detailed infromation on logging at Enabling RAS Tracing in Vista/Longhorn Server 

Accounting logs are saved to C:\Windows\system32\LogFiles by default. You can change this by clicking on “Accounting” in the NPS console.

Click Start, Run and enter GPEDIT.MSC

Enable both success/failure at Computer Configuration -> Windows Settings -> Security Settings -> Advanced Audit Policy Configuration -> System Audit Policies -> Logon/Logoff -> Audit Network Policy Server.

In the command window  run “netsh nps show eventlog” and “netsh nps show filelog” on the NPS server, check that the results are:

C:\Windows\system32>netsh nps show filelog

File log configuration:

---------------------------------------------------------

Accounting                     = Enabled

Authentication                 = Enabled

Periodic accounting status     = Enabled

Periodic authentication status = Enabled

Directory                      = C:\Windows\system32\LogFiles

Format                         = ODBC formatting

Delete old logs                = Enabled

Frequency                      = Monthly logs

Max size                       = 10 MB

C:\Windows\system32>netsh nps show eventlog

Event log configuration:

---------------------------------------------------------

Accepted authentication requests = Enabled

Rejected authentication requests = Enabled

Viewing NPS logs

Open Server Manager and expand Diagnostics, Event Viewer, Custom Views, Server Roles, Network Policy and Access Server

Request Not Matching the Network Policy

If you see the following on the client you are using to log in 'Line has invalid autocommand " ppp negotiate  "' it probably means that the request isn't matching the network policy you created. Putty will close the session before you can see the message. If you try to log in and it looks successful but the session immediately closes try using a different client.

You can verify by looking at the NPS logs. Find the failed attempt, double click, and select the Detail tab. Scroll down until you can see the ProxyPolicyName. Right below that will be the Network Policy name that was matched. You can see in the example below that it's blank.

The reason this causes the " ppp negotiate " is that the default policy in NPS has a service-type of PPP.

From the "Details" tab of the NPS server log viewer:
ProxyPolicyName CISCO-Radius
NetworkPolicyName -
AuthenticationProvider Windows
AuthenticationServer NPS.LAB.PRI
AuthenticationType PAP

In this example I had moved the NPS server to a new AD domain and the policy just wouldn't match. I deleted it, created a new one and all was good.

Invalid Radius Client

It’s possible the client is using a different interface to communicate with the NPS server than the one you configured. The event log entry for an invalid client is 13. You can filter the log to see if your device is using the address you expected.

You can use "ip radius source-interface InterfaceName" to force radius to use a specific interface. For example, if the management interface is vlan 18 use:

ip radius source-interface Vlan18

Invalid Username/Password

If the user entered an invalid username or password event ID 6273 will be recorded. Filter the log on 6273 to find the details. The log records the “friendly Client name”, the Client IP address and message about the failed credentials.

Note: If the RADIUS keys don't match between the device and the client entry in the NPS server you will also get the same message in the log!

NPS Logs show "Access Granted" but the switch doesn't get a response

This was probably a fluke but in one instance I had changed the hostname AND IP address of a switch. The NPS server showed Access Granted but when I looked at the detail in the log the NASIPv4Address was correct but the ClientName and ClientIPAddress were the old values so NPS was sending the response to the wrong IP. I reloaded the switch and it worked correctly.

No Log Entries

There are a few reasons that the log doesn’t contain any entries from the device. The device will accept the first method that has a successful username/password match. I once entered the “Local” keyword before the RADIUS group in the authentication string. I had a local username that was the same as my AD username but with a different password.

The device would see the local username and incorrect password and terminate the login attempt. No log entries were recorded because the device stopped the login attempt as soon as the “Local” method failed.

You may also have put in the wrong IP address of the NPS server in your RADIUS definition. The commands below will help you trouble shoot that.

Finally, if you don't authorize the NPS server in AD it won't show any log entries.

Verifying IOS RADIUS configuration

sh aaa servers – lists the IP of the server and the ports it is using. Make sure that you used the same ports on the NPS server and the device.

#sh aaa server

RADIUS: id 1, priority 1, host 10.140.47.205, auth-port 1645, acct-port 1646

test aaa group NPS server 10.140.47.205 auth-port 1645 vector 123456 new-code

User successfully authenticated

USER ATTRIBUTES

service-type         0   1 [Login]

priv-lvl             0   15 (0xF)

There are many debugs you can enable for trouble shooting RADIUS. The six listed below seem to be enough to solve most issues.

debug aaa authentication

debug aaa sg-server-selection

debug aaa protocol radius

debug aaa author

debug radius elog

debug radius verbose

With these enabled, you will see the following for a wrong password and a successful login:

*******************************************

User entered wrong password

024847: Sep 29 21:03:57.710 PDT: AAA/BIND(00001047): Bind i/f
024848: Sep 29 21:03:57.711 PDT: AAA/AUTHEN/LOGIN (00001047): Pick method list 'UseRadius'
024849: Sep 29 21:03:57.711 PDT: RADIUS/ENCODE(00001047): ask "Please enter your username:"
024850: Sep 29 21:03:57.711 PDT: RADIUS/ENCODE(00001047): send packet; GET_USER
024851: Sep 29 21:04:01.992 PDT: RADIUS/ENCODE(00001047): ask "Please enter your password:"
024852: Sep 29 21:04:01.992 PDT: RADIUS/ENCODE(00001047): send packet; GET_PASSWORD
024853: Sep 29 21:04:06.781 PDT: RADIUS/ENCODE(00001047):Orig. component type = Exec
024854: Sep 29 21:04:06.781 PDT: RADIUS(00001047): Config NAS IP: 0.0.0.0
024855: Sep 29 21:04:06.781 PDT: RADIUS(00001047): Config NAS IPv6: ::
024856: Sep 29 21:04:06.781 PDT: RADIUS/ENCODE: Best Local IP-Address 10.140.119.207 for Radius-Server 10.140.47.205
024857: Sep 29 21:04:06.781 PDT: RADIUS(00001047): Sending a IPv4 Radius Packet
024858: Sep 29 21:04:06.782 PDT: RADIUS(00001047): Started 5 sec timeout
024859: Sep 29 21:04:06.877 PDT: RADIUS: Received from id 1645/10 10.140.47.205:1645, Access-Reject, len 20

User entered correct password

024865: Sep 29 21:06:12.137 PDT: AAA/BIND(00001048): Bind i/f
024866: Sep 29 21:06:12.137 PDT: AAA/AUTHEN/LOGIN (00001048): Pick method list 'UseRadius'
024867: Sep 29 21:06:12.138 PDT: RADIUS/ENCODE(00001048): ask "Please enter your username:"
024868: Sep 29 21:06:12.138 PDT: RADIUS/ENCODE(00001048): send packet; GET_USER
024869: Sep 29 21:06:14.844 PDT: RADIUS/ENCODE(00001048): ask "Please enter your pasword:"
024870: Sep 29 21:06:14.844 PDT: RADIUS/ENCODE(00001048): send packet; GET_PASSWORD
024871: Sep 29 21:06:19.677 PDT: RADIUS/ENCODE(00001048):Orig. component type = Exec
024872: Sep 29 21:06:19.677 PDT: RADIUS(00001048): Config NAS IP: 0.0.0.0
024873: Sep 29 21:06:19.677 PDT: RADIUS(00001048): Config NAS IPv6: ::
024874: Sep 29 21:06:19.678 PDT: RADIUS/ENCODE: Best Local IP-Address 10.140.119.207 for Radius-Server 10.140.47.205
024875: Sep 29 21:06:19.678 PDT: RADIUS(00001048): Sending a IPv4 Radius Packet
024876: Sep 29 21:06:19.678 PDT: RADIUS(00001048): Started 5 sec timeout
024877: Sep 29 21:06:19.692 PDT: RADIUS: Received from id 1645/11 10.140.47.205:1645, Access-Accept, len 152
024878: Sep 29 21:06:19.692 PDT: AAA/AUTHOR/EXEC(00001048): processing AV priv-lvl=15
024879: Sep 29 21:06:19.692 PDT: AAA/AUTHOR/EXEC(00001048): processing AV priv-lvl=15
024880: Sep 29 21:06:19.692 PDT: AAA/AUTHOR/EXEC(00001048): processing AV service-type=1
024881: Sep 29 21:06:19.693 PDT: AAA/AUTHOR/EXEC(00001048): Authorization successful

In this debug I forgot to enter the key in the RADIUS section

001939: Sep 24 13:04:48 PST: RADIUS/ENCODE(00000040):Orig. component type = Exec
001940: Sep 24 13:04:48 PST: RADIUS:  AAA Unsupported Attr: interface         [221] 4   125716940
001941: Sep 24 13:04:48 PST: RADIUS/ENCODE(00000040): Unsupported AAA attribute clid
001942: Sep 24 13:04:48 PST: RADIUS/ENCODE(00000040): dropping service type, "radius-server attribute 6 on-for-login-auth" is off
001943: Sep 24 13:04:48 PST: RADIUS(00000040): Config NAS IP: 10.200.18.36
001944: Sep 24 13:04:48 PST: RADIUS(00000040): Config NAS IPv6: ::
001945: Sep 24 13:04:48 PST: RADIUS/ENCODE(00000040): acct_session_id: 54
001946: Sep 24 13:04:48 PST: RADIUS(00000040): sending
001947: Sep 24 13:04:48 PST: RADIUS: No secret to encode request (rctx:0x7A46DCC)
001948: Sep 24 13:04:48 PST: RADIUS: Unable to encrypt (rctx:0x7A46DCC)
001949: Sep 24 13:04:48 PST: RADIUS: No secret to encode request (rctx:0x7A46DCC)
001950: Sep 24 13:04:48 PST: RADIUS: Unable to encrypt (rctx:0x7A46DCC)
001951: Sep 24 13:04:48 PST: %RADIUS-4-RADIUS_DEAD: RADIUS server 10.1.52.59:1645,1646 is not responding.
001952: Sep 24 13:04:48 PST: %RADIUS-4-RADIUS_ALIVE: RADIUS server 10.1.52.59:1645,1646 is being marked alive.
001953: Sep 24 13:04:48 PST: RADIUS: No secret to encode request (rctx:0x7A46DCC)
001954: Sep 24 13:04:48 PST: RADIUS: Unable to encrypt (rctx:0x7A46DCC)
001955: Sep 24 13:04:48 PST: RADIUS: No secret to encode request (rctx:0x7A46DCC)
001956: Sep 24 13:04:48 PST: RADIUS: Unable to encrypt (rctx:0x7A46DCC)
001957: Sep 24 13:04:48 PST: RADIUS: No secret to encode request (rctx:0x7A46DCC)
001958: Sep 24 13:04:48 PST: RADIUS: Unable to encrypt (rctx:0x7A46DCC)
001959: Sep 24 13:04:48 PST: RADIUS/DECODE: No response from radius-server; parse response; FAIL

001960: Sep 24 13:04:48 PST: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL