How to debug IAG SP2 KCD

Introduction

Since IAG SP2, Kerberos Constrained Delegation (KCD) it handled at IAG level (not anymore at ISA level). Even if KCD logic remains the same, the approach to trace and troubleshoot is now different. The purpose of this document is to give you the approach and tool to trace the KCD flow.

Tools: We will use 2 ways to deep trace this :

· A protocol analyser : I advise you to use Wireshark since Netmon has some limitation tracing Kerberos authentication in HTTP.

· A registry key to activate logging on IAG’s component named “WhlFilter” in IAG.

Implement KCD

KCD has to be configured :

· On IAG

· In Active Directory, on IAG’s machine account (authorize delegation, authorize HTTP application to request delegation, declare SPNs (applications) authorized for delegation)

· On the application itself : set appropriate parameters to support and handle the Kerberos ticket

Trace with WhlFilter (introduction)

Whlfilter is the component plugged into IIS. This is the one that will act as the entry point in IAG, and do the “reverse proxy” job.

By tracing this discussion, we will see HTTP traffic going through IAG, and also all kind of event that may occur. For KCD, we will be able to see HTTP 401 errors, ticket requests, etc.

To activate whlFilter logs, please follow this procedure :

1. 1. On the IAG machine, open regedit and browse HKEY_LOCAL_MACHINE\SOFTWARE\WhaleCom\e-Gap\von\UrlFilter
   2. Locate the LogFlag value (should be 0 by default, which mean no trace at all) and set it to 4 (maximum).

A few seconds later, the Whlfilter component start to chat, and fill out the log.

Check this directory to see this log :

C:\Whale-Com\e-Gap\von\conf\WebSites\<trunkname>\logs

You should see a file <month><day>_WhlFilter.log (eg. 0701_WhlFilter.log). It can take up to 60 seconds to be created (IAG checks the reg key every minute).

Tip : before activating the registry key, save all the logs in this dectory, and make this directory empty. It is easyer to see only relevant log files.

Here is an example of what you can see in the trace : IAG is trying to get aKerberos TGS for the user but it fails. In fact the IAG machine is not even in the AD domain, which is mandatory to make KCD work (Kerberos constraint) :

---------- KERB.TXT <DATE>06:53:39.845 (tid: 00000698): HTTPAuth::CKerberosHandler::Negotiate - Function starting point (PFC=01182D00) (ExtPFC=072D0D58) (ExtECB=02813DA0) <DATE>06:53:39.845 (tid: 00000698): HTTPAuth::CKerberosHandler::Negotiate - Migrating conversation state to support Kerberos (PFC=01182D00) (ExtPFC=072D0D58) (ExtECB=02813DA0) <DATE>06:53:39.845 (tid: 00000698): HTTPAuth::CKerberosHandler::AuthConverse - Trying to acquire credentials for user: [first.second@emea.yourcompany.intra] (PFC=01182D00) (ExtPFC=072D0D58) (ExtECB=02813DA0) <DATE>06:53:39.845 (tid: 00000698): HTTPAuth::CKerberosHandler::AuthConverse - ERROR: Could not acquire credentials for user: [first.second@emea.yourcompany.intra] - Protocol Transition failed! (PFC=01182D00) (ExtPFC=072D0D58) (ExtECB=02813DA0) <DATE>06:53:39.845 (tid: 00000698): HTTPAuth::CKerberosHandler::Negotiate - conversation failed, reseting state (PFC=01182D00) (ExtPFC=072D0D58) (ExtECB=02813DA0) <DATE>07:01:42.942 (tid: 00000AA8): HTTPAuth::CKerberosHandler::Negotiate - Function starting point (PFC=01182AB0) (ExtPFC=072D0AF0) …

As you can see all traces about kerberos contain the “CKerberosHandler” keyword. Once you have the log file, if you want to quickly extract “kerberos” relevant lines, in command line, you can use the following syntax.: find /I "kerberos" kerbOnly.txt. This Kerbonly.TXT will contain only lines with this keyword.

Example 2 : IAG successfully acquired a TGS from the Kerberos Key Distribution Center (KDC) which is a DC in Microsoft infrastructure. Once it is acquired it will send it to the published application in the HTTP Get command/authorization.

28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CKerberosHandler::Negotiate - Function starting point (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CKerberosHandler::Negotiate - Migrating conversation state to support Kerberos (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CConversationState::Reset: Reseting (basic) conversation state at 03805B10. (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CConversationState::~CConversationState: destroying state at 03805B10 28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CConversationState::Reset: Reseting (basic) conversation state at 03805B10. (PFC=00000000) (ExtPFC=00000000) (ExtECB=00000000) 28/10/2008 17:40:29.961 (tid: 000003C0): CSessionManagerObject::GetSessionParam(A26AA1F8-B74C-411C-8FDC-E8BCB68346B4, 1, CertificateUPN): returned alexandreg@yourOthercompany.com. 28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CUPNExtractor::RetrieveUPN - Updating UPN in SessionContext: [alexandreg@yourOthercompany.com] (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CKerberosHandler::AuthConverse - Trying to acquire credentials for user: [alexandreg@yourOthercompany.com] (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.961 (tid: 000003C0): HTTPAuth::CLSAServerConnection::GetLsaConnectionHandle - Connection to LSA server established successfully. 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CCredentialsExtractor::S4U2Self - User token retrieved successfully (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CCredentialsExtractor::AcquireCredentailsHandle - Credentials acquired successfully (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CKerberosHandler::AuthConverse - Credentials for user: [alexandreg@yourOthercompany.com] acquired successfully (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CSPNExtractor::RetrieveSPN - Retrieved SPN [HTTP/exactwss.yourOthercompany.com] (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CSSPINegStep::ProcessNegStep - QuerySecurityPackageInfo successful - max token size is 12128 bytes (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CSSPINegStep::ProcessNegStep - InitializeSecurityContext successful (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CSSPINegStep::ProcessNegStep - UUEncoding response BLOB -- 40 bytes long (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CSSPINegStep::ProcessNegStep - Negotiation step complete, need more data: yes (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008) 28/10/2008 17:40:29.981 (tid: 000003C0): HTTPAuth::CKerberosHandler::Negotiate - Building authorization header (PFC=010D8460) (ExtPFC=01891D00) (ExtECB=0262B008)

In this example, IAG has the TGS, but it does not mean that it will work. If the application is not supposed to accept Kerberos or does not accept the TGS, it will fail. The only message you get from a user perspective, is “not authorized”.

Step by step process

IAG/KCD involves : a client, IAG, an application, and also a kerberos infrastructure.

It is important to understand each step of the transaction, in order to know where to search :

1) client access a web app via IAG : tool=HTTPwatch or Fillder

2) Web App answers “401 error, negociate” (it can also accept NTLM depending on the config) : Tool : WhlFilter

3) IAG intercept this 401 error, and check if SSO is requested on this application (Web Setting TAB, “automatically reply to application-specific..” checkbox). Tool=WhlFilter.

4) KCD is specified for authentication, and a SPN has been also indicated by administrator. Tool : IAG configuration console

5) IAG contacts a KDC, and request a ticket on behalf of the user, for that specific SPN. Tool : Protocol analyzer and WhlFilter

6) KDC generates (or fail) a ticket for this user, this SPN. Tool : network analyzer or whlfilter.

7) IAG received this ticket, and reply to the application “401”error. It resends a HTTP GET (or POST) with this time an “authorization” header which contains the TGS. Tool : whlFilter.

8) Application receives this TGS, and authenticate the user. Tool : application itself.

What if it “fails” ? Depending on the step, tools and approach are different.

No TGS requested by IAG

IAG will request a TGS “only” if it receives a 401 error from the Web Application, and only if IAG is set to provide SSO.

Make sure that the 401 error contains this “negociate” option. If not, check application configuration, without this trigger IAG will not do the job.

IAG ask a ticket, but it fails

Trace all the traffic leaving the IAG machine towards Domain Controlers (they run the Kerberos KDC service).

With the protocol analyzer you can see the REQUEST (REQ) and the (RESPONSE). Check in the response the error code, it will tell you what is going on if it fails.

Most of the time, there is a configuration error in the AD for KDC : check the IAG account machine, verify that KCD is authorized, that application is authorized, that the SPNs are correctly configured.

WhlFilter trace is nice here, but looking at the frames we can clearly see Kerberos protocol, and error code. Then loop with online information (SDK, articles) that will explain what the error is.

TGS is received, Application authentication fails

You need to capture the traffic between IAG and the web application.

With protocol analyzer, you need to use HTTP to be able to debug this, HTTPs will cipher the data so impossible to investigate.

Use WhlFilter if it is HTTPs.

Locate all the “HTTP Get”. Locate the ones that contain in the HTTP header an “authorization” field, this is where authentication is located.

With Wireshark, click the + sign, this will give you de details or the authorization. It may contain clear text, NTLM or Kerberos.

We need to see Kerberos there, and we can see the different information of the TGS.

Check the name of the user, the SPN, … and make sure that the published application is waiting for the same information.

If TGS is sent correctly but authorization fail, this is an application configuration problem. Make sure that the parameters in the TGS are the one expected by the application, especially the SPN.

Conclusion

Kerberos is very wide, you may encounter other scenario.. but this is the most common ones.