I'm debugging an ASP.NET application which is seemingly randomly losing the content of some static fields. I did some simple custom logging (because even log4net was flaky), and found out that the application is being loaded into two app domains. Here is a snippet from the log:
6/27/2011 9:01:01 PM /LM/W3SVC/1/ROOT/MyApp-1-129537072581658334: log message 1
6/27/2011 9:01:01 PM /LM/W3SVC/1/ROOT/MyApp-1-129537072581658334: log message 2
6/27/2011 9:01:01 PM /LM/W3SVC/1/ROOT/MyApp-1-129537072581658334: log message 3
6/27/2011 9:01:01 PM /LM/W3SVC/1/ROOT/MyApp-1-129537072581658334: log message 4
6/27/2011 9:01:02 PM /LM/W3SVC/1/ROOT/MyApp-4-129537072620628334: log message 5 <-
6/27/2011 9:01:02 PM /LM/W3SVC/1/ROOT/MyApp-4-129537072620628334: log message 6
6/27/2011 9:04:50 PM /LM/W3SVC/1/ROOT/MyApp-1-129537074647228334: log message 7
6/27/2011 9:04:50 PM /LM/W3SVC/1/ROOT/MyApp-1-129537074647228334: log message 8
The item after the time/date is the current app domain name.
The application is just a regular ASP.NET (not MVC) application handling some AJAX request and passing them to a bunch of ASP.NET libraries. The only unusual thing is that one of the libraries uses a bit of reflection to lookup some classes which then instantiates and runs them on separate threads. But it does not do anything explicitly with app domains.
By the way, the highlighted row from the log file comes from the ASP.NET app itself (i.e. not from one of those separate thread) from an ASPX handler.
Am I interpreting the log correctly? If so, what can cause an application to be loaded and served from multiple app domains?
Edit: This question is essentially related to this one: ASP.NET Application state vs a Static object. However, based on what I've seen today, it does not seem possible to rely on static fields. I could move everything to the Application object, but I guess a synchronization would be a bit cumbersome. I'm more and more convinced the application does something non-standard.
Edit 2: I did a little bit more investigation, and it seems that there is always a 1-1 relation between application and app domains (which is something I would expect). So I think that what I'm seeing is recycling.
Edit 3: After some more experiments and poking around, I enabled IIS health monitoring (based on http://blogs.msdn.com/b/tess/archive/2006/08/02/asp-net-case-study-lost-session-variables-and-appdomain-recycles.aspx), and found out that the application is started twice in a quick succession. It's actuall quite puzzling. Here are the log events:
Event code: 1003
Event message: Application compilation is starting.
Event time: 6/28/2011 8:34:31 AM
Event time (UTC): 6/28/2011 3:34:31 PM
Event ID: d42336b18c264516a4ba5aa1e62df276
Event sequence: 1
Event occurrence: 1
Event detail code: 0
Application information:
Application domain: /LM/W3SVC/1/ROOT/MyApp-1-129537488697736549
Trust level: Full
Application Virtual Path: /MyApp
Application Path: [snip]\MyApp\
Machine name: US-SEA-R9759B2
Process information:
Process ID: 7624
Process name: w3wp.exe
Account name: IIS APPPOOL\DefaultAppPool
----
Event code: 1001
Event message: Application is starting.
Event time: 6/28/2011 8:34:33 AM
Event time (UTC): 6/28/2011 3:34:33 PM
Event ID: f7fbecb1ba1a4a24833016cec47458c6
Event sequence: 1
Event occurrence: 1
Event detail code: 0
Application information:
Application domain: /LM/W3SVC/1/ROOT-2-129537488729428362
Trust level: Full
Application Virtual Path: /
Application Path: [snip]\RootApp\
Machine name: US-SEA-R9759B2
Process information:
Process ID: 7624
Process name: w3wp.exe
Account name: IIS APPPOOL\DefaultAppPool
----
Event code: 1001
Event message: Application is starting.
Event time: 6/28/2011 8:34:40 AM
Event time (UTC): 6/28/2011 3:34:40 PM
Event ID: 07a3dc31e8804caca1ddc3b2101962e3
Event sequence: 1
Event occurrence: 1
Event detail code: 0
Application information:
Application domain: /LM/W3SVC/1/ROOT-3-129537488807712839
Trust level: Full
Application Virtual Path: /
Application Path: [snip]\RootApp\
Machine name: US-SEA-R9759B2
Process information:
Process ID: 7624
Process name: w3wp.exe
Account name: IIS APPPOOL\DefaultAppPool
----
Event code: 1001
Event message: Application is starting.
Event time: 6/28/2011 8:34:40 AM
Event time (UTC): 6/28/2011 3:34:40 PM
Event ID: db304b519a084fa797fbcfe66fbb0b48
Event sequence: 1
Event occurrence: 1
Event detail code: 0
Application information:
Application domain: /LM/W3SVC/1/ROOT/MyApp-4-129537488808502885
Trust level: Full
Application Virtual Path: /MyApp
Application Path: [snip]\MyApp\
Machine name: US-SEA-R9759B2
Process information:
Process ID: 7624
Process name: w3wp.exe
Account name: IIS APPPOOL\DefaultAppPool
The MyApp application sits in another application (the RootApp). What I would expect would be two log messages: MyApp starting and RootApp starting.
If I had to guess there is something on your site that is changing web.config files, dlls, aspx, asmx or some other file. Whenever those files get changed a new instance of the web application gets started and any new requests get served from that new web application while the old requests get served from the existing application. Once all of the old requests complete the old application is shut down. This is good for deployments as it doesn't break peoples existing sessions but it means you shouldn't have anything that is automatically changing web.config files on every request or things like that.
This page describes in much better detail how this works http://technet.microsoft.com/en-us/library/cc759560(WS.10).aspx
Did you accidentally set the number of worker processes in the AppPool Properties (Performance Tab) to 2?
In those properties, there could also be a setting that let's your AppPool recycle far too often, based on number or requests or any of those recycling settings