The One With The FBA Redirect Loop

Applies to: Exchange 2013

Recently I came across a few cases where all users logging into OWA and ECP would be perpetually redirected back to the FBA logon page.  The customer had just replaced their old certificate with a new one, from a supported 3rd-party vendor, and the certificate seemed to check out, having a trusted chain, accessible CRLs, etc.  (TLDR)

Setup:

  • Exchange 2013 CAS
  • Forms-based authentication (FBA) enabled

Symptom:

  1. Log on to OWA or ECP by browsing to the site which will redirect you (302) to the FBA page
  2. Enter the credentials as you normally would and submit the form
  3. Get redirected back to /owa without an error message or an event being thrown

Sample Log

Digging into the logs, we see a distinct pattern.  First up, the IIS log:

 #Software: Microsoft Internet Information Services 8.5
#Version: 1.0
#Date: 2015-01-14 18:39:49
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status time-taken
2015-01-14 18:39:49 192.168.137.113 GET /owa &CorrelationID=;&cafeReqId=78641dc0-8e3c-47b5-a4bc-30e1d7d91546; 443 - 127.0.0.1 Mozilla/5.0+(Windows+NT+6.3;+WOW64) - 302 0 0 8514
2015-01-14 18:39:50 192.168.137.113 GET /owa/auth/logon.aspx url=https%3a%2f%2fmail.contoso.com%2fowa&reason=0&CorrelationID=;&cafeReqId=9a5cb876-58cf-4f35-9ccb-bf06b0980656; 443 - 127.0.0.1 Mozilla/5.0+(Windows+NT+6.3;+WOW64) - 200 0 0 1343
2015-01-14 18:39:51 192.168.137.113 GET /owa/auth/logon.aspx replaceCurrent=1&url=https%3a%2f%2fmail.contoso.com%2fowa&CorrelationID=;&cafeReqId=cdec7c7e-e80e-4218-b295-f2e623d8bf24; 443 - 127.0.0.1 Mozilla/5.0+(Windows+NT+6.3;+WOW64) https://mail.contoso.com/owa/auth/logon.aspx?url=https%3a%2f%2fmail.contoso.com%2fowa&reason=0 200 0 0 1156
2015-01-14 18:40:02 192.168.137.113 POST /owa/auth.owa &CorrelationID=;&cafeReqId=55c7a045-aad3-4fa3-a345-3fab3436da17; 443 contoso\jason 127.0.0.1 Mozilla/5.0+(Windows+NT+6.3;+WOW64) https://mail.contoso.com/owa/auth/logon.aspx?replaceCurrent=1&url=https%3a%2f%2fmail.contoso.com%2fowa 302 0 0 1688
2015-01-14 18:40:02 192.168.137.113 GET /owa &CorrelationID=;&cafeReqId=6afdd6df-f2ed-4c04-9bc1-ae870305f0b5; 443 - 127.0.0.1 Mozilla/5.0+(Windows+NT+6.3;+WOW64) https://mail.contoso.com/owa/auth/logon.aspx?replaceCurrent=1&url=https%3a%2f%2fmail.contoso.com%2fowa 302 0 0 62
2015-01-14 18:40:02 192.168.137.113 GET /owa/auth/logon.aspx url=https%3a%2f%2fmail.contoso.com%2fowa&reason=0&CorrelationID=;&cafeReqId=ebc7e50b-e71a-43bd-84a7-40e6f70fb2a3; 443 - 127.0.0.1 Mozilla/5.0+(Windows+NT+6.3;+WOW64) https://mail.contoso.com/owa/auth/logon.aspx?replaceCurrent=1&url=https%3a%2f%2fmail.contoso.com%2fowa 200 0 0 390
2015-01-14 18:40:02 192.168.137.113 GET /owa/auth/logon.aspx replaceCurrent=1&url=https%3a%2f%2fmail.contoso.com%2fowa&CorrelationID=;&cafeReqId=97fc51f2-b4d6-4dfb-bfc4-6692260543e4; 443 - 127.0.0.1 Mozilla/5.0+(Windows+NT+6.3;+WOW64) https://mail.contoso.com/owa/auth/logon.aspx?url=https%3a%2f%2fmail.contoso.com%2fowa&reason=0 200 0 0 140

There are a few things that are really important here: the URI, the HTTP VERB used, and the response code.  When we remove the noise and focus on those, we get this pattern:

  1. GET,  /owa,                 302
  2. GET,  /owa/auth/logon.aspx, 200
  3. GET,  /owa/auth/logon.aspx, 200
  4. POST, /owa/auth.owa,        302
  5. GET,  /owa,                 302 (starts repeating with step 2)

To get an idea of what's happening here, we need to understand how the FBA logon works.  In a nutshell, this is what's supposed to happen:

  1. A user browses to the OWA page, in general that's "/owa".
  2. OWA needs to authenticate the user, so it redirects the browser to /owa/auth/logon.aspx.
  3. Logon.aspx is the FBA page.  The form POSTs the user name and password to "/owa/auth.owa".
  4. As part of the FBA model, we store an encrypted cookie with a short TTL in the browser, and redirect the browser to /owa.
  5. OWA allows the user to complete the login, and displays the user's mailbox.

In the customer's environment, the process breaks down on step 5.  Instead of allowing the login, we're just redirected to the FBA again.

Unfortunately there's no clear indication of what's happening in the event or IIS logs.  The only real clue is in the HttpProxy\Owa log:

 #Software: Microsoft Exchange Server
#Version: 15.00.0995.012
#Log-type: HttpProxy Logs
#Date: 2015-01-14T18:39:49.098Z
#Fields: DateTime,RequestId,MajorVersion,MinorVersion,BuildVersion,RevisionVersion,ClientRequestId,Protocol,UrlHost,UrlStem,ProtocolAction,AuthenticationType,IsAuthenticated,AuthenticatedUser,Organization,AnchorMailbox,UserAgent,ClientIpAddress,ServerHostName,HttpStatus,BackEndStatus,ErrorCode,Method,ProxyAction,TargetServer,TargetServerVersion,RoutingType,RoutingHint,BackEndCookie,ServerLocatorHost,ServerLocatorLatency,RequestBytes,ResponseBytes,TargetOutstandingRequests,AuthModulePerfContext,HttpPipelineLatency,CalculateTargetBackEndLatency,GlsLatencyBreakup,TotalGlsLatency,AccountForestLatencyBreakup,TotalAccountForestLatency,ResourceForestLatencyBreakup,TotalResourceForestLatency,ADLatency,SharedCacheLatencyBreakup,TotalSharedCacheLatency,ActivityContextLifeTime,ModuleToHandlerSwitchingLatency,ClientReqStreamLatency,BackendReqInitLatency,BackendReqStreamLatency,BackendProcessingLatency,BackendRespInitLatency,BackendRespStreamLatency,ClientRespStreamLatency,KerberosAuthHeaderLatency,HandlerCompletionLatency,RequestHandlerLatency,HandlerToModuleSwitchingLatency,ProxyTime,CoreLatency,RoutingLatency,HttpProxyOverhead,TotalRequestTime,UrlQuery,BackEndGenericInfo,GenericInfo,GenericErrors
2015-01-14T18:39:49.082Z,78641dc0-8e3c-47b5-a4bc-30e1d7d91546,15,0,995,12,,Owa,mail.contoso.com,/owa,,FBA,False,,,,Mozilla/5.0 (Windows NT 6.3; WOW64),127.0.0.1,CONTOSERVER,302,,,GET,,,,,,,,,0,,,,,,,,,,,,,,,531.2234,,,,,,,,,,,,,,616,,616,618,,,BeginRequest=2015-01-14T18:39:48.551Z;CorrelationID=;OnAuthenticate=259;NoCookies=302 - GET/E14AuthPost;EndRequest=2015-01-14T18:39:49.082Z;,
2015-01-14T18:39:50.473Z,9a5cb876-58cf-4f35-9ccb-bf06b0980656,15,0,995,12,,Owa,mail.contoso.com,/owa/auth/logon.aspx,,FBA,False,,,,Mozilla/5.0 (Windows NT 6.3; WOW64),127.0.0.1,CONTOSERVER,200,,,GET,,,,,,,,,0,,,,152,,,,,,,,,,,1234.2881,,,,,,,,,,,,,,1077,,1229,1229,?url=https%3a%2f%2fmail.contoso.com%2fowa&reason=0,,BeginRequest=2015-01-14T18:39:49.239Z;CorrelationID=;OnAuthenticate=108;SelectHandler=151;EndRequest=2015-01-14T18:39:50.473Z;,
2015-01-14T18:39:51.676Z,cdec7c7e-e80e-4218-b295-f2e623d8bf24,15,0,995,12,,Owa,mail.contoso.com,/owa/auth/logon.aspx,,FBA,False,,,,Mozilla/5.0 (Windows NT 6.3; WOW64),127.0.0.1,CONTOSERVER,200,,,GET,,,,,,,,,0,,,,0,,,,,,,,,,,1047.0835,,,,,,,,,,,,,,1055,,1055,1055,?replaceCurrent=1&url=https%3a%2f%2fmail.contoso.com%2fowa,,BeginRequest=2015-01-14T18:39:50.629Z;CorrelationID=;EndRequest=2015-01-14T18:39:51.676Z;I32:ATE.C[CONTOSERVER.contoso.com]=2;F:ATE.AL[CONTOSERVER.contoso.com]=16;I32:ADS.C[CONTOSERVER]=1;F:ADS.AL[CONTOSERVER]=3.2332;I32:ADR.C[CONTOSERVER]=1;F:ADR.AL[CONTOSERVER]=5.214,
2015-01-14T18:40:02.839Z,55c7a045-aad3-4fa3-a345-3fab3436da17,15,0,995,12,,Owa,mail.contoso.com,/owa/auth.owa,,FBA,True,contoso\jason,,Sid~S-1-5-12-3456789012-3456789012-3456789012-3456,Mozilla/5.0 (Windows NT 6.3; WOW64),127.0.0.1,CONTOSERVER,302,,,POST,,,,,WindowsIdentity,,CONTOSERVER,78,145,,,,892,629,,0,90;,90,7;11;,18,108,,0,1656.8489,36,,,,,,,,,101,727,0,,763,,1655,1655,,,BeginRequest=2015-01-14T18:40:01.182Z;CorrelationID=;OnAuthenticate=155;ProxyState-Run=None;ServerLocatorCall=47e9ec43-db6e-4278-b364-1d3049692e7a;FEAuth=BEVersion-1941996515;ProxyState-Complete=CalculateBackEnd;EndRequest=2015-01-14T18:40:02.839Z;I32:ATE.C[CONTOSERVER.contoso.com]=4;F:ATE.AL[CONTOSERVER.contoso.com]=11.75;I32:ADS.C[CONTOSERVER]=4;F:ADS.AL[CONTOSERVER]=6.2329;I32:ADR.C[CONTOSERVER]=1;F:ADR.AL[CONTOSERVER]=1.0308,
2015-01-14T18:40:02.902Z,6afdd6df-f2ed-4c04-9bc1-ae870305f0b5,15,0,995,12,,Owa,mail.contoso.com,/owa,,FBA,False,,,,Mozilla/5.0 (Windows NT 6.3; WOW64),127.0.0.1,CONTOSERVER,302,,,GET,,,,,,,,,0,,,,,,,,,,,,,,,31.26,,,,,,,,,,,,,,27,,27,27,,,BeginRequest=2015-01-14T18:40:02.870Z;CorrelationID=;NoCookies=302 - GET/E14AuthPost;EndRequest=2015-01-14T18:40:02.902Z;,
2015-01-14T18:40:02.933Z,ebc7e50b-e71a-43bd-84a7-40e6f70fb2a3,15,0,995,12,,Owa,mail.contoso.com,/owa/auth/logon.aspx,,FBA,False,,,,Mozilla/5.0 (Windows NT 6.3; WOW64),127.0.0.1,CONTOSERVER,200,,,GET,,,,,,,,,0,,,,0,,,,,,,,,,,0,,,,,,,,,,,,,,1,,1,1,?url=https%3a%2f%2fmail.contoso.com%2fowa&reason=0,,BeginRequest=2015-01-14T18:40:02.933Z;CorrelationID=;EndRequest=2015-01-14T18:40:02.933Z;,
2015-01-14T18:40:03.371Z,97fc51f2-b4d6-4dfb-bfc4-6692260543e4,15,0,995,12,,Owa,mail.contoso.com,/owa/auth/logon.aspx,,FBA,False,,,,Mozilla/5.0 (Windows NT 6.3; WOW64),127.0.0.1,CONTOSERVER,200,,,GET,,,,,,,,,0,,,,0,,,,,,,,,,,0,,,,,,,,,,,,,,2,,2,2,?replaceCurrent=1&url=https%3a%2f%2fmail.contoso.com%2fowa,,BeginRequest=2015-01-14T18:40:03.371Z;CorrelationID=;EndRequest=2015-01-14T18:40:03.371Z;,

The lines highlighted in blue correspond with lines 4 and 5 above -- the POST to auth.owa and subsequent GET of /owa.  Notice that a username (contoso\jason) appears here, indicating successful authentication.  A bad auth attempt would result in a 401 or 403.  The next line doesn't show a user, and also shows NoCookies=302.

That pattern indicates we authenticated successfully, but then for some reason didn't have the expected cookie when coming back to /owa.  So what happened?

It turns out the cookie we set earlier in step 4 fails to decrypt, and we send the user back to the FBA page to try again.  There aren't a lot of scenarios where we should fail to decrypt a legitimate cookie, so let's look at the cert, which is what we use to encrypt/decrypt the cookie data.  Remember, the customer just changed the cert, so we knew it was more than likely related, but standard cert checks succeeded.

We used certutil  to verify most of this:

  • Certificate chain is valid, up to the CA root
  • The current date was within the certificate's validity period
  • CRL, AIA, and OCSP checks were successful
  • The names on the certificate (subject name, alternative names) matched the URL we were browsing

That's the standard list of things I check when running into your run-of-the-mill certificate issues, but since they checked out, I just dumped the cert for an eyeball test (grab the serial number from Get-ExchangeCertificate or the cert itself, no spaces):

certutil -store my certificateSerialNumber

The provider was listed as "Provider = Microsoft Software Key Storage Provider".  The KSP is a provider that is used with Cryptography API: Next Generation (CNG).  Exchange FBA does not support CNG certificates.  Exchange only uses and supports the legacy CryptoAPI which uses Cryptographic Service Providers (CSP).

Solution

Migrate the certificate to a CSP or request a CSP certificate from your certificate provider.  If you use a CSP or KSP from another software or hardware vendor, contact the relevant vendor for the equivalent instructions.  For example this will be the case if you use a Microsoft RSA SChannel Cryptographic Provider and the certificate is not locked into a KSP:

  1. Backup your existing certificate, including the private key.  For more information on how to do this, please reference the Export-ExchangeCertificate cmdlet.

  2. Note which services are bound to the certificate currently using Get-ExchangeCertificate.

  3. Delete the certificate and private key.  If you use Remove-ExchangeCertificate, you'll need to temporarily assign a different certificate to the bound services first.  If you just use PowerShell or MMC you'll need to reboot the server afterwards as bound services cache the certificate.

  4. Import the new certificate into a CSP using certutil (pfx/p12):

    certutil -csp "Microsoft RSA SChannel Cryptographic Provider" -importpfx <CertificateFilename>

  5. Ensure the certificate is still bound to the same services using Get-ExchangeCertificate, and if not, re-set them using Enable-ExchangeCertificate.

  6. Restart the server (see step 3).

Verify the certificate now has its private key stored with a CSP:

certutil -store my <CertificateSerialNumber>
The output should now show: "Provider = Microsoft RSA SChannel Cryptographic Provider"

Jason Slaughter