Thread.CurrentPrincipal claims incorrectly to be anynomous

Question

I'm seeing requests on my server that appear to be made by an anynomous client, although I'm certain they were made by an authenticated user - I have fiddler logs showing that the client sent valid asp.net auth cookies, and server logs indicating that the cookie arrived and is valid. The problem has been observed across all browsers.

The flow of data is:

1. User visits login url, on a machine that's part of a webfarm (all with the same machine, decrypt keys)
2. On successful forms authentication, user is redirect to a restricted url, their homepage
3. Homepage renders correctly, knowns the identify of the user, and includes javascript to perform 7 asynchronous post-backs to get additional data
4. Javascript kicks off 7 http.get requests, hitting different machines in the webfarm (assume round robin)
5. Server validates request: ~0.01% fail to authenticate.

Thoughts?

Now into details:

A very small number of the asynchronous requests land at my server (with evidence they were not manipulated or faked) and appear to be anonymous. Of the 7 requests made, some number may or may not work (ie, 5/7 will succeed, 2 will fail). There doesn't appear to be any patterns in success / failures. In the cases where my requests appear to be anonymous, the CurrentPrincipal.Identity records:

Thread.CurrentPrincipal.Identity.IsAuthenticated; // false
Thread.CurrentPrincipal.Identity.Name; // null (or empty, unsure off hand)

Dumping the http.context.request.params collection to a log file, I'm able to see the following relevent (and scrubbed) properties (complete params below):

context: {"userId":10000,"userName":"johnsmith"}
HTTP_COOKIE:.ASPXAUTH=[valid auth cookie value]
HTTP_X_REQUESTED_WITH:XMLHttpRequest
X-Requested-With: XMLHttpRequest
    AUTH_TYPE: 
    AUTH_USER: 
    AUTH_PASSWORD: 
    LOGON_USER: 
    REMOTE_USER: 
    HTTP_COOKIE: .ASPXAUTH=[valid auth cookie value]

I know the auth cookie is valid - during these same requests I'm able to decrypt the auth cookie and extract the following:

CookiePath: /
Expiration: 9/23/2105 8:14:22 PM
Expired: False
IsPersistent: True
IssueDate: 8/30/2010 2:54:22 PM
Name: johnsmith
UserData: 
Version: 2

Not sure how to proceed at this point. This problem seems to have been exacerbated with our recent migration to mvc 2.0 / asp.net 4.0, but my confidence isn't high that was the cause.

I've reached out to a handful of my customers who have had this problem, and that's been even more frustrating (but does reflect what I'm able to read in my logs). Once in this state, it's hard to get out of it. Clearing cache and cookies seem to have no effect. But, switching to a new browser and it's generally OK. Likewise, waiting several hours and returning with the same browser and it's also generally ok, but not always. As stated earlier, this is seen across all browsers.

Any suggestions?
Kevin

------------
Here is the remainder of the log snippet (scrubbed for pii) that I've captured:

8/30/2010 2:54:43 PM: Anonymous user detected:
    Identity Name:
    IsAuthenticated::False
HttpContextInformation to follow:

8/30/2010 2:54:43 PM: Request Param collection contents:
context: {"userId":10000,"userName":"johnsmith"}
    .ASPXAUTH: A3C6615642F1F543397160C84C0E016C8439BDF400B0130AADAB82C93E77FFF3BEAD7726223F02049FA65B2C3E1773928C0371C4F580F2432C1538551BC5654020AD76F37159BA6BB68D7A68744AE036
    ASP.NET_SessionId: m5vit3cyv0rsiosqg5xmhhuu
    ALL_HTTP: HTTP_CONNECTION:close
HTTP_ACCEPT:text/javascript, text/html, application/xml, text/xml, */*
HTTP_ACCEPT_ENCODING:gzip, deflate
HTTP_ACCEPT_LANGUAGE:en-us
HTTP_COOKIE:.ASPXAUTH=A3C6615642F1F543397160C84C0E016C8439BDF400B0130AADAB82C93E77FFF3BEAD7726223F02049FA65B2C3E1773928C0371C4F580F2432C1538551BC5654020AD76F37159BA6BB68D7A68744AE036
HTTP_HOST:www.host.com
HTTP_REFERER:http://www.host.com/
HTTP_USER_AGENT:Mozilla/5.0 (iPhone; U; CPU iPhone OS 4_0 like Mac OS X; en-us) AppleWebKit/532.9 (KHTML, like Gecko) Version/4.0.5 Mobile/8A293 Safari/6531.22.7
HTTP_X_FORWARDED_FOR:166.137.139.139
HTTP_X_REQUESTED_WITH:XMLHttpRequest

    ALL_RAW: Connection: close
Accept: text/javascript, text/html, application/xml, text/xml, */*
Accept-Encoding: gzip, deflate
Accept-Language: en-us
Cookie: .ASPXAUTH=A3C6615642F1F543397160C84C0E016C8439BDF400B0130AADAB82C93E77FFF3BEAD7726223F02049FA65B2C3E1773928C0371C4F580F2432C1538551BC5654020AD76F37159BA6BB68D7A68744AE036
Host: www.host.com
Referer: http://www.host.com/
User-Agent: Mozilla/5.0 (iPhone; U; CPU iPhone OS 4_0 like Mac OS X; en-us) AppleWebKit/532.9 (KHTML, like Gecko) Version/4.0.5 Mobile/8A293 Safari/6531.22.7
X-Forwarded-For: 166.137.139.139
X-Requested-With: XMLHttpRequest

    APPL_MD_PATH: /LM/W3SVC/792523/Root
    APPL_PHYSICAL_PATH: d:\localpath\
    AUTH_TYPE: 
    AUTH_USER: 
    AUTH_PASSWORD: 
    LOGON_USER: 
    REMOTE_USER: 
    CERT_COOKIE: 
    CERT_FLAGS: 
    CERT_ISSUER: 
    CERT_KEYSIZE: 
    CERT_SECRETKEYSIZE: 
    CERT_SERIALNUMBER: 
    CERT_SERVER_ISSUER: 
    CERT_SERVER_SUBJECT: 
    CERT_SUBJECT: 
    CONTENT_LENGTH: 0
    CONTENT_TYPE: 
    GATEWAY_INTERFACE: CGI/1.1
    HTTPS: off
    HTTPS_KEYSIZE: 
    HTTPS_SECRETKEYSIZE: 
    HTTPS_SERVER_ISSUER: 
    HTTPS_SERVER_SUBJECT: 
    INSTANCE_ID: 792523
    INSTANCE_META_PATH: /LM/W3SVC/792523
    LOCAL_ADDR: 10.248.50.207
    PATH_INFO: /resource
    PATH_TRANSLATED: d:\localpath\resource
    QUERY_STRING: context={%22userId%22:10000,%22userName%22:%22johnsmith%22}
    REMOTE_ADDR: 10.208.205.171
    REMOTE_HOST: 10.208.205.171
    REMOTE_PORT: 37966
    REQUEST_METHOD: GET
    SCRIPT_NAME: /resouce
    SERVER_NAME: www.host.com
    SERVER_PORT: 80
    SERVER_PORT_SECURE: 0
    SERVER_PROTOCOL: HTTP/1.0
    SERVER_SOFTWARE: Microsoft-IIS/6.0
    URL: /resource
    HTTP_CONNECTION: close
    HTTP_ACCEPT: text/javascript, text/html, application/xml, text/xml, */*
    HTTP_ACCEPT_ENCODING: gzip, deflate
    HTTP_ACCEPT_LANGUAGE: en-us
    HTTP_COOKIE: .ASPXAUTH=A3C6615642F1F543397160C84C0E016C8439BDF400B0130AADAB82C93E77FFF3BEAD7726223F02049FA65B2C3E1773928C0371C4F580F2432C1538551BC5654020AD76F37159BA6BB68D7A68744AE036
    HTTP_HOST: www.host.com
    HTTP_REFERER: http://www.host.com/
    HTTP_USER_AGENT: Mozilla/5.0 (iPhone; U; CPU iPhone OS 4_0 like Mac OS X; en-us) AppleWebKit/532.9 (KHTML, like Gecko) Version/4.0.5 Mobile/8A293 Safari/6531.22.7
    HTTP_X_FORWARDED_FOR: 166.137.139.139
    HTTP_X_REQUESTED_WITH: XMLHttpRequest


8/30/2010 2:54:43 PM: Auth Ticket collection contents:
    CookiePath: /
    Expiration: 9/23/2105 8:14:22 PM
    Expired: False
    IsPersistent: True
    IssueDate: 8/30/2010 2:54:22 PM
    Name: johnsmith
    UserData: 
    Version: 2

Answer 1

This answer works, but is disappointing and alarming at the same time.

I spent 2 months working part time with MSDN technical support, and we finally found a work-around for this problem. I'm going to leave it to Microsoft to fix the problem, as it’s almost certainly an issue in the .net framework. But first, let me summarize the problem, give additional relevant background information and a few interesting things we found along the way.

The symptom was fleeting: Our website had a few reports of users who would authenticate with our website and see the correct state. But seemingly randomly, they’d be signed out of our website, or occasionally, experience the anonymous view. It was very frustrating, an nearly impossible to reproduce locally, in house.

Also on symptoms: through logging we saw mobile (iphone, ipad & android) browsers were disproportionately impacted, although all browsers and operating systems were impacted to some degree. And one last random symptom: It’d work for a user one day, not the next, and later in the afternoon, work again. Of course, switching browsers almost always fixed the problem.

We quickly assumed an auth issue, likely around the authentication cookie. The strange part was, I was able to prove (tracing) that the requests that were erroring included a proper cookie that I was able to decrypt, but that the .net framework was ignoring, in a non-deterministic way. I eventually began logging all requests that were in this state – auth cookie ignored by the .net framework, but seemingly valid to me, and found around 2% of my users were impacted.

I switched from using Thread.CurrentPrincipal.Identity to HttpContext.Current.User.Identity, to no avail, and tried a handful of other settings. Curiously, the only change I was able to make that made a dent was migrate to the .net 4 framework (from 3.5). The problem became an order of magnitude worst. Also tried various load balancer configurations, and was able to rule out multiple machine configurations – the same machine that issued the auth cookie would later reject it.

To re-iterate the symptoms: we had certain users (non-deterministic) who at times would not be able to user our website in an authenticated mode (also non-deterministic). Cute.

By now, the product team in Redmond was involved, and also stumped. But they did come up with a suggestion, which ultimately resolved the issue, here goes: Try forcing the Microsoft.net framework to use cookies as the authentication mode, as opposed to using a cookieless state:

<authentication mode="Forms">
  <forms cookieless="UseCookies" />
</authentication>

Flipped the switch and instantly the problematic requests ended (once I expired the session of those in an odd state).

While I’m glad that the problem was resolved – or rather worked around, it’s the non-deterministic handling of various browsers that worries me. Why would the .net framework see a browser one day, and treat it as supporting cookies, and later the same day say it should use a cookieless session?

My last concern is around how many other sites out there are losing 2% of their authenticated traffic without knowing? Considering the fix, it feels very much like a bug in the .net 4 framework.