A strange tale of HttpApplication.AuthenticateRequest and Trace

You know how sometimes you think you're pretty sure you know what the sum total of your database shenanigans are in any given ASP.NET page, but you want to make sure? Well, under load it's hard to do a SQL trace and really see what the hell is going on. Because I have all the SQLness funneling through a handful of helper methods in POP Forums (which is so close to a public beta that I can smell it), I figured it'd be easy enough to output the various calls to the Trace in ASP.NET, along with some execution times. Easy it was.

But there was one piece of weirdness I couldn't understand. The database call to update user session data, fired from an HttpModule's AuthenticateRequest event, seemed to be firing three times, every page. My first clue that something was strange should have been that the execution times were exactly the same, for all three entries in the Trace output.

Still, I stepped through the code first, putting a conditional breakpoint to make sure I was only tracking the page request and not the CSS and graphics (since the runtime serves all of the above on the local dev server app). Yep, just one call. Then I did fire up the SQL trace, and sure enough, just one call to the database. But when I looked at the ASP.NET page trace (via trace.axd), the call appeared three times.

The bottom line is that the database call isn't being made in triplicate, even if it is appearing in Trace three times. Still, I'd love to know what's going on in the interaction between the ASP.NET Trace and the HttpModule. I'd even like to step into the framework code, but so far, I have no idea how to do that, even though I think I have it enabled. I'd really like to just browse the framework code, but I still don't know how or if that's possible. It's a useless feature, frankly, if I can't make it work.
 

4 Comments

  • A while back I was having a similar issue. I wish I could remember how I solved it but I seem to remember that it only happened in firefox.

    Have you noticed this happening across all browsers?

  • Yep... IE6, Firefox and Safari. It's so strange because, like I said, the database call that it's tied to (off the SqlCommand's StatementCompleted event) for sure only happens once. The dupes only happen in the page trace.

  • This hopefully is not your issue, but I was working on some httpModules this weekend and I had just copied and pasted my AddHandler signatures using the EndRequest event. I was trying to see how the pipeline executed, what was available, etc. Anyway I left two extra addHandler declarations for the EndRequest event in my Init method. I had it firing 3 times too. The funny thing is the logging to a file (what I was doing as a trace mechanism) was only done once.

  • I can't figure it out. As best I can tell, the SQL trace shows it executing once, and a breakpoint in the code is only hit once. I can only assume there's some really strange interaction between Trace and the application object. So strange.

Comments have been disabled for this content.