In AWS, a Task is placed on an EC2 instance, and an ASP.NET WebAPI 2 app is started in a docker container.
The root site is empty, and the "/myapp" subdirectory contains the running web app.
The application pool is configured to auto-start and remain always-on. The preloadEnabled setting is active to ensure overlapped recycling occurs correctly and Application_Start completes before serving requests. I've even designated a warmup page that sets a flag, and confirmed that's called as well before a new process is handed requests.
The problem I have is that when the Task is first placed, before Application_Start has even been called, I see Windows System logs indicating that IIS thinks a configuration change has taken place that requires an app pool restart. The result is that a 2nd w3wp.exe process begins executing Application_Start logic just a few seconds after the first one begins, before it has even had a chance to complete its Application_Start run. Eventually, both process crash, and they're replaced with a third process that completes successfully and begins serving requests.
So my first question is, why would a fresh docker container that's about to start IIS immediately think that some settings change has occurred that requires the initial process to recycle? By the time this system log is written, no user-code has even run; it's timestamp appears a few seconds before Application_Start even logs any activity. My second question is, how might I figure out what is triggering this apparent settings change or what that settings change is? The log doesn't mention what settings or file changed or why. This seems particularly tough to debug within a docker container.
To my knowledge, there is no virus-scanner touching files in the docker container (as originally suggested here), and as far as I know, a docker image's file system is already locked-in upon startup; it's not like lines in the docker file that alter settings are re-running when the image is mounted.
System Logs:
01/25/2022 22:36:59 WAS Warning A process serving application pool 'DefaultAppPool' terminated unexpectedly. The process id was '11592'. The process exit code was '0xc0000005'.
01/25/2022 22:36:59 WAS Warning A process serving application pool 'DefaultAppPool' suffered a fatal communication error with the Windows Process Activation Service. The process id was '1328'. The data field contains the error number. 109 0 7 128
01/25/2022 22:34:35 WAS Information The worker processes serving application pool 'DefaultAppPool' are being recycled due to 1 or more configuration changes in the application pool properties which necessitate a restart of the processes.
Note that the first log at 22:34:35 indicating something has changed occurs BEFORE the first process even reaches Application_Start, because the first log output by Application_Start is timestamped well after it. Toggling different app pool settings like startup timeouts and so on alter the reason why the two processes crash (for example, sometimes it's an OutOfMemoryException instead of an access violation), but none of this explains why it thinks a pool recycle is necessary before the first one even starts, and then starts two process, one almost right after the other. I'm less concerned about why they both eventually crash, and are then replaced by an identical third process that completes without any problem at all.
0 Answers