HttpException “Request timed out” error occurs even if executionTimeout attribute is set to a large value
Symptoms
========
My customer receives the following response intermittently:
Request timed out. Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code. Exception Details: System.Web.HttpException: Request timed out.Source Error:
Stack Trace:
|
This issue typically occurs when the ASP.NET request executes for a period of time longer than the maximum timeout period allowed for server-side code execution.
My customer knows it will take 5 minutes to execute his ASP.NET page because the page needs to retrieve large data from database to generate a report. Therefore he has already set the value of executionTimeout attribute of httpRuntime element to 600 seconds in web.config. However he still receives HttpException “Request timed out” error while the ASP.NET page executes for 2 or 3 minutes.
How to Troubleshoot
===============
I used the instructions in my blog article “How to troubleshoot HttpException Request timed out (ASP.NET 2.0 32-bit)” to create a dump file while the error occurs.
Use windbg to open the dump file. Then load sos
0:018> .loadby sos mscorwks |
Dump all objects in the stack of the current thread. You will find System.Threading.Thread object:
0:018> !dso OS Thread Id: 0x1f50 (18) ESP/REG Object Name eax 028c1a64 System.Threading.Thread ebx 028c1a64 System.Threading.Thread ecx 029cab2c System.Web.RequestTimeoutManager+RequestTimeoutEntry esi 029cab2c System.Web.RequestTimeoutManager+RequestTimeoutEntry 0257f5dc 028fa520 System.Web.Util.DoubleLinkList 0257f5e0 02a67d68 System.Collections.ArrayList 0257f5e4 028fa3c8 System.Web.RequestTimeoutManager 0257f604 02a46294 System.Threading.ContextCallback 0257f608 028fa3c8 System.Web.RequestTimeoutManager 0257f630 028fa2b8 System.Web.HttpRuntime 0257f64c 02a671a0 System.Threading._ThreadPoolWaitCallback 0257f65c 028fa2b8 System.Web.HttpRuntime 0257f674 02a46294 System.Threading.ContextCallback 0257f678 02a671a0 System.Threading._ThreadPoolWaitCallback 0257f688 02a671b8 System.Threading.ExecutionContext 0257f694 02a671a0 System.Threading._ThreadPoolWaitCallback 0257f698 02a671b8 System.Threading.ExecutionContext 0257f6a4 02a671a0 System.Threading._ThreadPoolWaitCallback 0257f6ac 02a671a0 System.Threading._ThreadPoolWaitCallback |
Dump the information of System.Threading.Thread object and you will find the field DONT_USE_InternalThread:
0:018> !do 028c1a64 Name: System.Threading.Thread MethodTable: 048e1240 EEClass: 0469d994 Size: 56(0x38) bytes (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll) Fields: MT Field Offset Type VT Attr Value Name 048d2050 400063f 4 ....Contexts.Context 0 instance 028d3d74 m_Context 048dd960 4000640 8 ....ExecutionContext 0 instance 029b5e74 m_ExecutionContext 048e0c6c 4000641 c System.String 0 instance 00000000 m_Name 048e10d0 4000642 10 System.Delegate 0 instance 00000000 m_Delegate 048da368 4000643 14 System.Object[][] 0 instance 028f74ec m_ThreadStaticsBuckets 048e2e08 4000644 18 System.Int32[] 0 instance 028f7590 m_ThreadStaticsBits 048e3868 4000645 1c ...ation.CultureInfo 0 instance 028d440c m_CurrentCulture 048e3868 4000646 20 ...ation.CultureInfo 0 instance 028d440c m_CurrentUICulture 048e0888 4000647 24 System.Object 0 instance 00000000 m_ThreadStartArg 048e3534 4000648 28 System.IntPtr 1 instance 159a68 DONT_USE_InternalThread 048e2eb8 4000649 2c System.Int32 1 instance 2 m_Priority 048e2eb8 400064a 30 System.Int32 1 instance 9 m_ManagedThreadId 048b9888 400064b 16c ...LocalDataStoreMgr 0 shared static s_LocalDataStoreMgr >> Domain:Value 000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 << 048e0888 400064c 170 System.Object 0 shared static s_SyncObject >> Domain:Value 000d7f80:02673260 00106020:0268f5e8 000e1a08:027361a8 0015d670:028f74e0 << |
Run !threads command to list all threads and you will find the corresponded thread (whose OS thread Id is 1db8) which causes “Request timed out”:
0:018> !threads ThreadCount: 11 UnstartedThread: 0 BackgroundThread: 7 PendingThread: 0 DeadThread: 4 Hosted Runtime: no PreEmptive GC Alloc Lock ID OSID ThreadOBJ State GC Context Domain Count APT Exception XXXX 1 0 000dfa78 1808820 Enabled 00000000:00000000 000d7f80 0 MTA (Threadpool Worker) 13 2 1bf4 000eb758 b220 Enabled 00000000:00000000 000d7f80 0 MTA (Finalizer) 14 3 1a1c 00102678 80a220 Enabled 00000000:00000000 000d7f80 0 MTA (Threadpool Completion Port) 15 4 1d38 001058e0 1220 Enabled 00000000:00000000 000d7f80 0 Ukn 10 5 18cc 00136bb8 880a220 Enabled 00000000:00000000 000d7f80 0 MTA (Threadpool Completion Port) XXXX 6 0 00137bc8 1801820 Enabled 00000000:00000000 000d7f80 0 Ukn (Threadpool Worker) XXXX 7 0 001386d0 1801820 Enabled 00000000:00000000 000d7f80 0 Ukn (Threadpool Worker) XXXX 8 0 00158b08 1801820 Enabled 00000000:00000000 000d7f80 0 Ukn (Threadpool Worker) 16 9 1db8 00159a68 380b220 Enabled 00000000:00000000 0015d670 1 MTA (Threadpool Worker) 18 a 1f50 00169f38 180b220 Disabled 00000000:00000000 0015d670 0 MTA (Threadpool Worker) 19 b 1aec 0016b400 180b220 Enabled 00000000:00000000 000d7f80 0 MTA (Threadpool Worker) |
Switch to the problematic thread and list the call stack. You will find Default.aspx is waiting in the sleep function:
0:018> ~~[1db8]s eax=0000000f ebx=00000000 ecx=02419634 edx=02414e14 esi=00000000 edi=00deefc4 eip=7c82845c esp=00deef84 ebp=00deefec iopl=0 nv up ei pl nz na po nc cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000202 ntdll!KiFastSystemCallRet: 7c82845c c3 ret 0:016> !clrstack OS Thread Id: 0x1db8 (16) ESP EIP 00def0d4 7c82845c [HelperMethodFrame: 00def0d4] System.Threading.Thread.SleepInternal(Int32) 00def128 024c03a1 ASP.default_aspx.Page_Load(System.Object, System.EventArgs) 00def164 66f2a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs) 00def174 660b4cc4 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs) 00def188 660ae1c4 System.Web.UI.Control.OnLoad(System.EventArgs) 00def19c 660ae203 System.Web.UI.Control.LoadRecursive() 00def1b4 660aa2b4 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean) 00def30c 660a9ee4 System.Web.UI.Page.ProcessRequest(Boolean, Boolean) 00def344 660a9e11 System.Web.UI.Page.ProcessRequest() 00def37c 660a9da6 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext) 00def388 660a9d82 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext) 00def39c 024c0115 ASP.default_aspx.ProcessRequest(System.Web.HttpContext) 00def3a0 660b0256 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() 00def3d4 6608332c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef) 00def414 6608eb83 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception) 00def464 660828ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object) 00def480 66085e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest) 00def4b4 66085ac3 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest) 00def4c4 66084c5c System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32) |
However in this scenario, ASP.NET page only executes for about 2 minutes before executionTimeout (10 minutes) is reached. Why does HttpException “Request timed out” error still occurs?
Let us go back to check the thread which triggered ThreadAbortException:
0:018> !clrstack OS Thread Id: 0x1f50 (18) ESP EIP 0257f5dc 660e0732 System.Web.RequestTimeoutManager.CancelTimedOutRequests(System.DateTime) 0257f620 668e8433 System.Web.RequestTimeoutManager.Stop() 0257f63c 6606f756 System.Web.HttpRuntime.Dispose() 0257f65c 6606f635 System.Web.HttpRuntime.ReleaseResourcesAndUnloadAppDomain(System.Object) 0257f688 0487a09f System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object) 0257f690 0489043f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 0257f6a8 0487a603 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback) 0257f6bc 0487a499 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object) 0257f84c 79e71b4c [GCFrame: 0257f84c] |
The above call stack seemed to be unloading AppDomain, that is different from the call stack which appears for the real “timed out” issue (see below)
0246f7cc 660e0732 System.Web.RequestTimeoutManager.CancelTimedOutRequests(System.DateTime) 0246f810 66094d4c System.Web.RequestTimeoutManager.TimerCompletionCallback(System.Object) 0246f824 048584bf System.Threading._TimerCallback.TimerCallback_Context(System.Object) 0246f82c 0489043f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 0246f844 0485842b System.Threading._TimerCallback.PerformTimerCallback(System.Object) |
Use ILSpy to check System.Web.RequestTimeoutManager.Stop code. This method will add 1 year to the current time and then pass it to CancelTimedOutRequests method.
// System.Web.RequestTimeoutManagerinternal void Stop(){ if (this._timer != null) { ((IDisposable)this._timer).Dispose(); this._timer = null; } while (this._inProgressLock != 0) { Thread.Sleep(100); } if (this._requestCount > 0) { this.CancelTimedOutRequests(DateTime.UtcNow.AddYears(1)); }} |
Therefore the request appears “timed out” if the current time is “next year”.
Now I need to find out why System.Web.RequestTimeoutManager.Stop was called. Based on the method name System.Web.HttpRuntime.ReleaseResourcesAndUnloadAppDomain, it seems that AppDomain was being unloaded.
I check the System.Web.HttpRuntime object in the stack:
0:018> !do 028fa2b8 Name: System.Web.HttpRuntime MethodTable: 66149e70 EEClass: 65f4d534 Size: 152(0x98) bytes (C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll) Fields: MT Field Offset Type VT Attr Value Name 048cedac 4001106 4 ...amedPermissionSet 0 instance 00000000 _namedPermissionSet 6614a068 4001107 8 ...ileChangesMonitor 0 instance 028fb100 _fcm 6614b4b0 4001108 c ...ing.CacheInternal 0 instance 028fe65c _cacheInternal 6614b5a8 4001109 10 ...Web.Caching.Cache 0 instance 028fe588 _cachePublic 048b4738 400110a 74 System.Boolean 1 instance 0 _isOnUNCShare 66149efc 400110b 14 ...Web.Util.Profiler 0 instance 028fa350 _profiler 66149f44 400110c 18 ...estTimeoutManager 0 instance 028fa3c8 _timeoutManager 66151b78 400110d 1c ....Web.RequestQueue 0 instance 029a1970 _requestQueue 048b4738 400110e 75 System.Boolean 1 instance 0 _apartmentThreading 048b4738 400110f 76 System.Boolean 1 instance 1 _processRequestInApplicationTrust 048b4738 4001110 77 System.Boolean 1 instance 0 _beforeFirstRequest 048b82cc 4001111 84 System.DateTime 1 instance 028fa33c _firstRequestStartTime 048b4738 4001112 78 System.Boolean 1 instance 0 _firstRequestCompleted 048b4738 4001113 79 System.Boolean 1 instance 1 _userForcedShutdown 048b4738 4001114 7a System.Boolean 1 instance 1 _configInited 048b4738 4001115 7b System.Boolean 1 instance 1 _fusionInited 048e2eb8 4001116 6c System.Int32 1 instance 1 _activeRequestCount 048b82cc 4001117 8c System.DateTime 1 instance 028fa344 _lastShutdownAttemptTime 048b4738 4001118 7c System.Boolean 1 instance 1 _shutdownInProgress 048e0c6c 4001119 20 System.String 0 instance 02a49348 _shutDownStack 048e0c6c 400111a 24 System.String 0 instance 02a67038 _shutDownMessage 6612b95c 400111b 70 System.Int32 1 instance 3 _shutdownReason 048e0c6c 400111c 28 System.String 0 instance 0295e494 _trustLevel 048e0c6c 400111d 2c System.String 0 instance 028fa9b0 _wpUserId 048b4738 400111e 7d System.Boolean 1 instance 1 _shutdownWebEventRaised 048b4738 400111f 7e System.Boolean 1 instance 1 _enableHeaderChecking 048cf9f0 4001120 30 System.AsyncCallback 0 instance 028fa9fc _requestNotificationCompletionCallback 048cf9f0 4001121 34 System.AsyncCallback 0 instance 028faa1c _handlerCompletionCallback 66149fe4 4001122 38 ...fSendNotification 0 instance 028faa3c _asyncEndOfSendCallback 048cebcc 4001123 3c ...ding.WaitCallback 0 instance 028faa5c _appDomainUnloadallback 048e0e00 4001124 40 System.Exception 0 instance 00000000 _initializationError 048b4738 4001125 7f System.Boolean 1 instance 0 _hostingInitFailed 048c72a8 4001126 44 ...m.Threading.Timer 0 instance 00000000 _appDomainShutdownTimer 048e0c6c 4001127 48 System.String 0 instance 029710fc _tempDir 048e0c6c 4001128 4c System.String 0 instance 02971fd4 _codegenDir 048e0c6c 4001129 50 System.String 0 instance 028d3354 _appDomainAppId 048e0c6c 400112a 54 System.String 0 instance 028d3398 _appDomainAppPath 6614a32c 400112b 58 ...m.Web.VirtualPath 0 instance 028fb0d8 _appDomainAppVPath 048e0c6c 400112c 5c System.String 0 instance 028d34e4 _appDomainId 048b4738 400112d 80 System.Boolean 1 instance 0 _debuggingEnabled 048e36dc 400112e 60 System.Byte[] 0 instance 00000000 _appOfflineMessage 048e0c6c 400112f 64 System.String 0 instance 00000000 _clientScriptVirtualPath 048e0c6c 4001130 68 System.String 0 instance 00000000 _clientScriptPhysicalPath 66149e70 40010ff fc ...m.Web.HttpRuntime 0 shared static _theRuntime >> Domain:Value 000d7f80:02673dfc 00106020:02691b94 000e1a08:0273912c 0015d670:028fa2b8 << 048e36dc 4001100 100 System.Byte[] 0 shared static s_autogenKeys >> Domain:Value 000d7f80:02673a74 00106020:02691970 000e1a08:02738d2c 0015d670:028f9eb8 << 048e0c6c 4001101 104 System.String 0 shared static DirectorySeparatorString >> Domain:Value 000d7f80:02673ad8 00106020:02691adc 000e1a08:02738e98 0015d670:028fa024 << 048e0c6c 4001102 108 System.String 0 shared static DoubleDirectorySeparatorString >> Domain:Value 000d7f80:02673aec 00106020:02691af0 000e1a08:02738eac 0015d670:028fa038 << 048b4738 4001103 7ec System.Boolean 1 shared static s_initialized >> Domain:Value 000d7f80:1 00106020:1 000e1a08:1 0015d670:1 << 048e0c6c 4001104 10c System.String 0 shared static s_installDirectory >> Domain:Value 000d7f80:02673d68 00106020:02691b14 000e1a08:02738ee8 0015d670:028fa074 << 048b4738 4001105 7f0 System.Boolean 1 shared static s_isEngineLoaded >> Domain:Value 000d7f80:1 00106020:1 000e1a08:1 0015d670:1 << 048b4738 4001131 7f4 System.Boolean 1 shared static _useIntegratedPipeline >> Domain:Value 000d7f80:0 00106020:0 000e1a08:0 0015d670:0 << 6614772c 4001132 110 ...nloadEventHandler 0 shared static AppDomainShutdown >> Domain:Value 000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 << 66113ca4 4001133 114 ....FactoryGenerator 0 shared static s_factoryGenerator >> Domain:Value 000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 << 048e32c0 4001134 118 ...ections.Hashtable 0 shared static s_factoryCache >> Domain:Value 000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 << 048b4738 4001135 7f8 System.Boolean 1 shared static s_initializedFactory >> Domain:Value 000d7f80:0 00106020:0 000e1a08:0 0015d670:0 << 048e0888 4001136 11c System.Object 0 shared static s_factoryLock >> Domain:Value 000d7f80:02673b04 00106020:02691b08 000e1a08:02738ec4 0015d670:028fa050 << |
Based on the field _shutdownInProgress I get to know that AppDomain was being shut down. The shutdown message is:
0:018> !do -nofields 02a67038 Name: System.String MethodTable: 048e0c6c EEClass: 0469d65c Size: 194(0xc2) bytes (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll) String: Directory rename change notification for 'C:\Inetpub\wwwroot\Test'. Test dir change or directory rename Directory rename change notification for 'C:\Inetpub\wwwroot\Test'. Test dir change or directory rename HostingEnvironment initiated shutdown HostingEnvironment caused shutdown Directory rename change notification for 'C:\Inetpub\wwwroot\Test'. Test dir change or directory rename |
The call stack is:
0:018> !do -nofields 02a49348 Name: System.String MethodTable: 048e0c6c EEClass: 0469d65c Size: 4098(0x1002) bytes (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll) String: at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal() at System.Web.Hosting.HostingEnvironment.InitiateShutdown() at System.Web.HttpRuntime.ShutdownAppDomain(String stackTrace) at System.Web.HttpRuntime.OnCriticalDirectoryChange(Object sender, FileChangeEvent e) at System.Web.FileChangesMonitor.OnSubdirChange(Object sender, FileChangeEvent e) at System.Web.DirectoryMonitor.FireNotifications() at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback) at System.Web.Util.WorkItem.OnQueueUserWorkItemCompletion(Object state) at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state) |
The application sub-directories were being deleted (see Todd’s blog for more info), that caused ASP.NET to shutdown AppDomain, that in turn “timed out” the executing requests.
In my real case the customer’s application created and deleted temporary folders under the application directory.
Regards,
Xinjin from APAC DSI Team