Reset Search
 

 

Article

KB12046 - How to follow an EAP authentication through the radius log file

« Go Back

Information

 
Last Modified Date10/24/2018 8:16 PM
Synopsis
Methods for following an EAP authentication through the SBR date log file via the RADIUS State attribute
Problem or Goal
Users attempting to login via 802.1X using the EAP-TTLS, EAP-PEAP, EAP-FAST or LEAP protocols are failing for some unknown reason
Cause
Solution
In the event where users are failing to authenticate when using any of the multi-part EAP protocols such as EAP-TTLS, the Pulse Secure TAC engineers will examine the radius log to attempt to determine the cause of the failure. One method, used by JTAC, is following the authentication process through logs via the RADIUS State attribute. This document will attempt to demonstrate a method for doing this.
 

Basics:

  1. What is meant by a multi-part authentication?
  2. What is the RADIUS State attribute and what is it used for?
  3. What tools can / should be used for this process?
 
What is meant by a multi-part authentication?
A multi-part authentication is any RADIUS authentication that requires multiple requests and responses between the RADIUS server and the client. EAP protocols such as EAP-TTLS, EAP-PEAP, EAP-TLS, EAP-Fast and LEAP all require the RADIUS server and client to exchange numerous RADIUS packets to complete the authentication.
 
What is the RADIUS State attribute and what is it used for?
Excerpt from RFC 2865, defining what the State Attribute is:
5.24 State

Description
This Attribute is available to be sent by the server to the client in an Access-Challenge and MUST be sent unmodified from the client to the server in the new Access-Request reply to that challenge, if any.

This Attribute is available to be sent by the server to the client in an Access-Accept that also includes a Termination-Action Attribute with the value of RADIUS-Request. If the NAS performs the Termination-Action by sending a new Access-Request upon termination of the current session, it MUST include the State attribute unchanged in that Access-Request.

In either usage, the client MUST NOT interpret the attribute locally. A packet must have only zero or one State Attribute. Usage of the State Attribute is implementation dependent.

So, what does this mean in English? Basically, the RFC is telling us that the State Attribute can be sent in an Access-Challenge packet and must be sent back unmodified in a subsequent Access-Request packet. 

SBR formats its State attribute as follows:
SBR-CH xxxx|y

Where:
xxxxx is a number that is incremented for each unique authentication process. It will start at 0 and increment for each new authentication
y is the step within the authentication. This number is incremented by SBR starting at 1.

Example of a simple flow:
  1. Authentication request form client
  2. SBR issues challenge and sets the State attribute value to SBR-CH 0|1
  3. Client replies to challenge and sends State attribute with value of SBR-CH 0|1
  4. SBR processes response and issues another challenge and sets the State attribute to SBR-CH 0|2
  5. Client replies to challenge and sends State attribute with value of SBR-CH 0|2
This process continues until the authentication has completed.
 
What tools can / should be used for this process?
While Pulse Secure is not officially recommending any utility, the SBR TAC engineers use several different text editing and manipulation tools. The Unix ‘grep’ command is very useful when searching through larger log files. Programs such as TextPad or UltraEdit are also used. Select the tools you feel most comfortable with.
 

What steps should be taken to analyze the logs to determine the cause of the failure?

Now the fun begins. The following are only suggestions and are not the only methods you can use to follow an authentication through a SBR log file.

note: Attached are two log files that contain very simple authentications using the EAP-TTLS protocol with MS-CHAPv2 as the inner authentication protocol. These log files are extremely easy to follow. Servers that are handing several concurrent authentications can create logs that are trickier to follow, but using the techniques described here should help limit the confusion you may encounter.

Sample Log file ( right-click to download and save each file)
20080801.log
20080804.log
 
step1  Enable full debug logging. To do this, edit the RADIUS.INI file located in the install directory.  Locate the ‘LogLevel’ and ‘TraceLevel’ entries and set the values to 2. See the example below from the RADIUS.INI file
[Configuration]
LogLevel      = 2
TraceLevel    = 2


If you had to edit the RADIUS.INI file, you will need to stop and restart the SBR service before the setting will take effect.

note: If you have the Global Enterprise Edition of Steel-Belted RADIUS, you can “hup” the radius process.
  • On Windows, you can run the radhup.exe utility located in the install directory.
  • On Solaris and Linux, you can hup the SBR daemon.
 
step2 Locate the user who is experiencing a problem authenticating. There are a few different ways to do this.
  1. Search for the user name in the log file. If you are using a tunneled protocol such as EAP-TTLS, this will be a bit tricky and may not necessarily work if the authentication is not reaching the point where the inner authentication has started. Remember, that with a tunneled protocol, most 802.1X supplicants will hide the actual user name from the outer portion of the authentication, instead, they will use the user name of ‘anonymous’. The Microsoft 802.1X supplicant is the exception to this; it will send the actual user name. 

    In the sample log, search for ‘testuser’. When you find this user, take note that the user name falls with then “Tunneled Authentication” portion of authentication. This tells us that the authentication has gotten to the inner authentication portion of the negotiation. There are times that this may not be the case
 
  • An alternate way to locate a user authentication is based on their PC’s MAC address.  On most systems, the MAC address can be obtained by issuing the IPCONFIG or IFCONFIG utility. Once you know the MAC address of the station, you will need to search for it in the following format: xx-xx-xx-xx-xx-xx. Note that SBR uses the DASH to separate the HEX digits in the MAC address. 

    In the sample log, the MAC address of the workstation that the user is authenticating from is ‘ 00-19-E2-EC-CF-08.   When searching the sample log file, you will see that the MAC address is associated with a RADIUS attribute known as the “Calling-Station-ID” attribute. 
 
step3 Now that we have located an authentication containing something of interest, we need to find the State Attribute so that we can now follow the authentication through the logs.   We will talk about how to locate the State attribute based on our three examples from Step 2.
  • Still another, less specific way, is to search for the IP Address of the NAS device the user is accessing whether it is a wireless access point or a wired switch. If a group of users is failing to authenticate and they are all on the same access device, this can be the fastest way to locate an authentication.

    In our sample log file, the NAS device IP address is 172.28.81.101
    1. If you were able to locate the user name as described in Step 2 part 1, you would have noted that the user name is INSIDE of the Tunneled Authentication section. What we need to do now is scroll up in the log and find the first instance of the State Attribute. This should be located in the “Authentication Request” section above the Tunneled Authentication section.
      In our sample log, the State Attribute is :
      08/01/2008 13:14:16 State : String Value = SBR-CH 0|4
 
  • If you were able to find the MAC address of the user’s workstation in our sample log, you would see that the “Calling-Station-ID” attribute is in the very first request from the user for authentication. You will need to scroll down in the log to the “Authentication Response” section. This is where SBR is sending a challenge back to the client. This will be where we also set the State Attribute. 
    In our sample log, you’d see State Attribute as :
    08/01/2008 13:14:16 State : String Value = SBR-CH 0|1
 
 
step4 Now that we have located the State Attribute, we can begin the final step. The first thing we want to analyze is whether there is an even or odd number of matching State Attributes. In our sample log, is the value :
08/01/2008 13:14:16 State : String Value = SBR-CH 0|1
 
As stated in a previous section, SBR’s State Attribute contains an authentication / conversation number and a step number.  In our example, we have SBR-CH-0|1.  Where 0 is the conversation number and 1 is the step within that conversation. What we need to do is search ONLY for the conversation number. The search would look like this:
State : String Value = SBR-CH 0|

note: The step number was omitted
 
The EVEN / ODD State Attribute Count
Running the grep command on "Sample Log 20080801",  the log file will display:
grep "State : String Value = SBR-CH 0|" 20080801.log

08/01/2008 13:14:16 State : String Value = SBR-CH 0|1
08/01/2008 13:14:16 State : String Value = SBR-CH 0|1
08/01/2008 13:14:16 State : String Value = SBR-CH 0|2
08/01/2008 13:14:16 State : String Value = SBR-CH 0|2
08/01/2008 13:14:16 State : String Value = SBR-CH 0|3
08/01/2008 13:14:16 State : String Value = SBR-CH 0|3
08/01/2008 13:14:16 State : String Value = SBR-CH 0|4
08/01/2008 13:14:16 State : String Value = SBR-CH 0|4
08/01/2008 13:14:16 State : String Value = SBR-CH 0|5
08/01/2008 13:14:16 State : String Value = SBR-CH 0|5
08/01/2008 13:14:16 State : String Value = SBR-CH 0|6
08/01/2008 13:14:16 State : String Value = SBR-CH 0|6

Note that the above output is showing that there is an even number of occurrences of our specific State Attribute. This tells us that the SBR server and RADIUS client are successfully exchanging challenges and responses. If there were an odd number of occurrences, this would imply that a challenge from SBR either did not arrive at the client or the client did not respond. At this point, we would need to review logs from the RADIUS client (if they are available) to determine where the dropped challenge occurred. Here is an example of how the grep output would look:
08/01/2008 13:14:16 State : String Value = SBR-CH 0|1
08/01/2008 13:14:16 State : String Value = SBR-CH 0|1
08/01/2008 13:14:16 State : String Value = SBR-CH 0|2
08/01/2008 13:14:16 State : String Value = SBR-CH 0|2
08/01/2008 13:14:16 State : String Value = SBR-CH 0|3

Notice that SBR-CH 0|3 does not have a corresponding client response and that there are no additional occurrences of our desired State Attribute.

If your State Attribute count is even, it is possible that the EAP negotiation will still fail. In that event, you will need to closely review the logs and look for the reason that the user is being rejected. SBR logs are actually very verbose when recording at LogLevel 2 / TraceLevel 2. You should see a failure or reject reason in the log at the end of the authentication.
 

Using Log Time Stamps along with the State Attribute
(Use "Sample Log 20080804" for this section)
Another scenario that is common to failed authentications is a timeout scenario. During a normal EAP negotiation, the process can take anywhere from a couple hundred milliseconds to a few seconds depending on the client side configuration. The problem that extended authentication times can introduce is an EAP TIMER being exceeded. The NAS device is the “man in the middle”. It is taking the layer 2 802.1x authentication packets and converting it to layer 3 RADIUS packets. Most devices have a configurable “EAP TIMER” setting.  This tells the device how long to let a single EAP transaction last. It can range from 1 second up to 2 minutes depending on the device. We have provided a sample log were the user was prompted for their password. We intentionally delayed entering the password to cause the EAP TIMER on the NAS device to be exceeded. You will see that in the SBR log, the first authentication attempt fails, but a second attempt succeeds. 
 
The easiest way to identify this scenario is to search for the State attributes and then look at the time stamps associated with them. You will see a large gap at some point. This is the indication that after SBR issued a challenge, the client did not respond for some time.
Sample of a grep search for the State attributes associated with the ‘testuser’
 
grep State 20080804.log
08/04/2008 14:58:14 State : String Value = SBR-CH 6|1
08/04/2008 14:58:14 State : String Value = SBR-CH 6|1
08/04/2008 14:58:14 State : String Value = SBR-CH 6|2
08/04/2008 14:58:14 State : String Value = SBR-CH 6|2
08/04/2008 14:58:14 State : String Value = SBR-CH 6|3
08/04/2008 14:58:14 State : String Value = SBR-CH 6|3
08/04/2008 14:58:14 State : String Value = SBR-CH 6|4
08/04/2008 14:58:14 State : String Value = SBR-CH 6|4
08/04/2008 14:58:14 State : String Value = SBR-CH 7|1
08/04/2008 14:58:14 State : String Value = SBR-CH 6|5
08/04/2008 14:59:27 State : String Value = SBR-CH 8|1
08/04/2008 14:59:27 State : String Value = SBR-CH 8|1
08/04/2008 14:59:27 State : String Value = SBR-CH 8|2
08/04/2008 14:59:28 State : String Value = SBR-CH 8|2
08/04/2008 14:59:28 State : String Value = SBR-CH 8|3
08/04/2008 14:59:28 State : String Value = SBR-CH 8|3
08/04/2008 14:59:28 State : String Value = SBR-CH 8|4
08/04/2008 14:59:28 State : String Value = SBR-CH 8|4
08/04/2008 14:59:28 State : String Value = SBR-CH 9|1
08/04/2008 14:59:28 State : String Value = SBR-CH 8|5
08/04/2008 14:59:28 State : String Value = SBR-CH 8|5
08/04/2008 14:59:28 State : String Value = SBR-CH 9|1
08/04/2008 14:59:28 State : String Value = SBR-CH 9|2
08/04/2008 14:59:28 State : String Value = SBR-CH 8|6
08/04/2008 14:59:28 State : String Value = SBR-CH 8|6
08/04/2008 14:59:28 State : String Value = SBR-CH 9|2
Notice
  • At 14:58:14, SBR sends two challenges back to the client. SBR-CH 7|1 is the Tunneled challenge and SBR-CH 6|5 is the outer EAP challenge. Note that we never get an answer back to either challenge. This is the point at which the 802.1x client was prompting for the user password.
  • At 14:59:27, the authentication starts over and completes within two seconds.
If the EAP TIMERS on the NAS device are set too low, this can cause a client to fail authentication, especially, when interactive logins are in use (such as RSA SecurID). If you are experiencing this scenario, investigate the possibility of increasing the EAP TIMERS on the NAS device. You will need to refer to your device documentation for details
  • If you searched for the NAS IP Address of the NAS device, you should search for the first instance of the State Attribute that we send back in the “Authentication Response” just below the “Authentication Request”.
    Again, in our sample log, the State Attribute is :
    08/01/2008 13:14:16 State : String Value = SBR-CH 0|1
Related Links
Attachment 1 
Created ByData Deployment

Feedback

 

Was this article helpful?


   

Feedback

Please tell us how we can make this article more useful.

Characters Remaining: 255