application unable to process requests

[tjanczuk]

The node.js app is unable to process requests. Below is the dump of w3wp.exe threads. It appears iisnode is blocked waiting on critical sections which prevents processing of requests.

ntdll!NtWaitForKeyedEvent+15
ntdll!RtlAcquireSRWLockExclusive+12e
iisnode!CNodeApplicationManager::RecycleApplication+45 c:\projects\iisnode\src\iisnode\cnodeapplicationmanager.cpp @ 298 + a
iisnode!CNodeApplicationManager::OnScriptModified+11 c:\projects\iisnode\src\iisnode\cnodeapplicationmanager.cpp @ 336
iisnode!CFileWatcher::ScanDirectory+1c0 c:\projects\iisnode\src\iisnode\cfilewatcher.cpp @ 565 + 19
iisnode!CFileWatcher::Worker+bb c:\projects\iisnode\src\iisnode\cfilewatcher.cpp @ 504
msvcr100!_endthreadex+3f
msvcr100!_endthreadex+ce
kernel32!BaseThreadInitThunk+e
ntdll!__RtlUserThreadStart+70
ntdll!_RtlUserThreadStart+1b

We got other threads like below stuck wanting to get that critical section lock

ntdll!ZwWaitForSingleObject+15
ntdll!RtlpWaitOnCriticalSection+13e
ntdll!RtlEnterCriticalSection+150
iisnode!CFileWatcher::RemoveWatch+3f c:\projects\iisnode\src\iisnode\cfilewatcher.cpp @ 408 + a
iisnode!CNodeApplication::~CNodeApplication+13 c:\projects\iisnode\src\iisnode\cnodeapplication.cpp @ 11 + 10
iisnode!CNodeProcessManager::GracefulShutdown+e5 c:\projects\iisnode\src\iisnode\cnodeprocessmanager.cpp @ 343
msvcr100!_endthreadex+3f
msvcr100!_endthreadex+ce
kernel32!BaseThreadInitThunk+e
ntdll!__RtlUserThreadStart+70
ntdll!_RtlUserThreadStart+1b

ntdll!ZwWaitForSingleObject+15
ntdll!RtlpWaitOnCriticalSection+13e
ntdll!RtlEnterCriticalSection+150
iisnode!CFileWatcher::WatchFiles+33b c:\projects\iisnode\src\iisnode\cfilewatcher.cpp @ 139 + 10
iisnode!CNodeApplication::Initialize+fc c:\projects\iisnode\src\iisnode\cnodeapplication.cpp @ 49 + 26
iisnode!CNodeApplicationManager::GetOrCreateNodeApplicationCore+ad c:\projects\iisnode\src\iisnode\cnodeapplicationmanager.cpp @ 380 + c
iisnode!CNodeApplicationManager::GetOrCreateNodeApplication+98 c:\projects\iisnode\src\iisnode\cnodeapplicationmanager.cpp @ 653 + 11
iisnode!CNodeApplicationManager::Dispatch+111 c:\projects\iisnode\src\iisnode\cnodeapplicationmanager.cpp @ 205 + 12
iisnode!CNodeHttpModule::OnExecuteRequestHandler+97 c:\projects\iisnode\src\iisnode\cnodehttpmodule.cpp @ 26 + 11
iiscore!NOTIFICATION_CONTEXT::RequestDoWork+128
iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+305
iiscore!NOTIFICATION_CONTEXT::CallModules+28
iiscore!W3_CONTEXT::DoStateRequestExecuteHandler+36
iiscore!W3_CONTEXT::DoWork+d7
iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+49
iiscore!W3_CONTEXT::ExecuteRequest+20c
rewrite!RegisterModule+4fd4
rewrite!RegisterModule+817e
rewrite!RegisterModule+1c24f
rewrite!RegisterModule+3e65
rewrite!RegisterModule+5eb
iiscore!NOTIFICATION_CONTEXT::RequestDoWork+d5
iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+305
iiscore!NOTIFICATION_CONTEXT::CallModules+28
iiscore!W3_CONTEXT::DoStateRequestStart+63
iiscore!W3_CONTEXT::DoWork+8d
iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+49
iiscore!W3_MAIN_CONTEXT::OnNewRequest+47
w3dt!UL_NATIVE_REQUEST::DoStateProcess+26
w3dt!UL_NATIVE_REQUEST::DoWork+60
w3dt!OverlappedCompletionRoutine+1a
w3tp!THREAD_POOL_DATA::ThreadPoolThread+89
w3tp!THREAD_POOL_DATA::ThreadPoolThread+24
w3tp!THREAD_MANAGER::ThreadManagerThread+39
kernel32!BaseThreadInitThunk+e
ntdll!__RtlUserThreadStart+70
ntdll!_RtlUserThreadStart+1b

ntdll!NtWaitForKeyedEvent+15
ntdll!RtlAcquireSRWLockShared+105
iisnode!CNodeApplicationManager::Dispatch+96 c:\projects\iisnode\src\iisnode\cnodeapplicationmanager.cpp @ 186 + a
iisnode!CNodeHttpModule::OnExecuteRequestHandler+97 c:\projects\iisnode\src\iisnode\cnodehttpmodule.cpp @ 26 + 11
iiscore!NOTIFICATION_CONTEXT::RequestDoWork+128
iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+305
iiscore!NOTIFICATION_CONTEXT::CallModules+28
iiscore!W3_CONTEXT::DoStateRequestExecuteHandler+36
iiscore!W3_CONTEXT::DoWork+d7
iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+49
iiscore!W3_CONTEXT::ExecuteRequest+20c
rewrite!RegisterModule+4fd4
rewrite!RegisterModule+22aa9
rewrite!RegisterModule+1c3f2
rewrite!RegisterModule+3e65
rewrite!RegisterModule+5eb
iiscore!NOTIFICATION_CONTEXT::RequestDoWork+d5
iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+305
iiscore!NOTIFICATION_CONTEXT::CallModules+28
iiscore!W3_CONTEXT::DoStateRequestStart+63
iiscore!W3_CONTEXT::DoWork+8d
iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+49
iiscore!W3_MAIN_CONTEXT::OnNewRequest+47
w3dt!UL_NATIVE_REQUEST::DoStateProcess+26
w3dt!UL_NATIVE_REQUEST::DoWork+60
w3dt!OverlappedCompletionRoutine+1a
w3tp!THREAD_POOL_DATA::ThreadPoolThread+89
w3tp!THREAD_POOL_DATA::ThreadPoolThread+24
w3tp!THREAD_MANAGER::ThreadManagerThread+39
kernel32!BaseThreadInitThunk+e
ntdll!__RtlUserThreadStart+70
ntdll!_RtlUserThreadStart+1b

[tjanczuk]

This appears to happen as a result of node.js application recycle when iisnode detects that node.js files on disk have changed.

Hypothesis: stack traces suggest a deadlock between adding and removing entries in CFileWatcher. There is a possible logical issue in removing file watches in https://github.com/tjanczuk/iisnode/blob/master/src/iisnode/cfilewatcher.cpp#L453. This line of code may cause incomplete removal of WatchedFile entires associated with a given CNodeApplication. (There may be many WatchedFile entries within and across WatchedDirectories associated with a single CNodeApplication). Since the CNodeApplication is later disposed, subsequent file changed events may be trying to acquire a lock over a disposed CRITICAL_SECTION, possibly leading to a deadlock. Cases that cause an AV might have escaped detection since they result in IIS spinning another instance of the worker process.

[tjanczuk]

This is a classic deadlock situation that can arise when a new message arrives during recycling of a node.js application as a result of changes in the watched files.

There are two locks in the scenario: FileWatcher lock (FW) and Application Manager lock (AM). The file watcher thread holds the FW lock to scan files for changes. It detects a file has changed, and under FW lock, calls into the CNodeApplicationManager to recycle the affected application. The CNodeApplicationManager attempts to acquire the AM lock to perform that operation:

    iisnode.dll!CNodeApplicationManager::RecycleApplication(CNodeApplication * app, int requiresLock) Line 305  C++
    iisnode.dll!CNodeApplicationManager::RecycleApplication(CNodeApplication * app) Line 297    C++
    iisnode.dll!CNodeApplicationManager::OnScriptModified(CNodeApplicationManager * manager, CNodeApplication * application) Line 343   C++
    iisnode.dll!CFileWatcher::ScanDirectory(CFileWatcher::_WatchedDirectory * directory, int unc) Line 566  C++
>   iisnode.dll!CFileWatcher::Worker(void * arg) Line 504   C++
    iisnode.dll!_callthreadstartex() Line 354   C
    iisnode.dll!_threadstartex(void * ptd) Line 332 C

In the meantime, a new message arrives on another thread. That thread acquires the AW lock to create a new node.js application to process it. Under the AW lock, as part of the initialization process it attempts to acquire the FW lock to register a new file watch:

>   iisnode.dll!CFileWatcher::WatchFiles(const wchar_t * mainFileName, const wchar_t * watchedFiles, void (CNodeApplicationManager *, CNodeApplication *) * callback, CNodeApplicationManager * manager, CNodeApplication * application) Line 139   C++
    iisnode.dll!CNodeApplication::Initialize(const wchar_t * scriptName, IHttpContext * context) Line 49    C++
    iisnode.dll!CNodeApplicationManager::GetOrCreateNodeApplicationCore(const wchar_t * physicalPath, unsigned long physicalPathLength, IHttpContext * context, CNodeApplication * * application) Line 387  C++
    iisnode.dll!CNodeApplicationManager::GetOrCreateNodeApplication(IHttpContext * context, NodeDebugCommand debugCommand, int allowCreate, CNodeApplication * * application) Line 660  C++
    iisnode.dll!CNodeApplicationManager::Dispatch(IHttpContext * context, IHttpEventProvider * pProvider, CNodeHttpStoredContext * * ctx) Line 212  C++
    iisnode.dll!CNodeHttpModule::OnExecuteRequestHandler(IHttpContext * pHttpContext, IHttpEventProvider * pProvider) Line 39   C++

So we have one thread waiting on AW lock under FW, and another waiting on FW lock under AW. Deadlock.

Open question: Why do application exist in the CFileWatcher that CNodeApplicationManager is unaware of (since it attempts to create a new CNodeApplication for the incoming message? Is that a side effect of the issue mentioned in the previous comment of not cleaning up CFileWatcher structres properly in https://github.com/tjanczuk/iisnode/blob/master/src/iisnode/cfilewatcher.cpp#L453?

[tjanczuk]

Repro steps:

server.js:

var http = require('http');

var sent = false;

http.createServer(function (req, res) {
    res.writeHead(200, {'Content-Type': 'text/html'});
    res.end(sent ? '' : ('\n' + process.pid));
    sent = true;
}).listen(process.env.PORT);  

setTimeout(function() { throw "Die!"; }, 1000);

(self-killing the process every 1s is not related to the issue but appears to shorten the time to repro)

iisnode.yml:

watchedFiles: watchdog.txt;*.js;iisnode.yml;node_modules\*;views\*.jade;views\*.ejb;routes\*.js
nodeProcessCountPerApplication: 0
maxConcurrentRequestsPerProcess: 4096

update.js:

setInterval(function () {
    require('fs').appendFileSync('watchdog.txt', '.');
    process.stdout.write('.');
}, 1300);

Start the updater and use curl as a stress test client:

echo > watchdog.txt
start node update.js
curl --silent http://localhost/node/helloworld/hello.js/[1-1000000000]

You will see curl outputting PIDs of node.exe processes interlaced with some HTTP 500 messages, which is expected. When curl appears to hang, the w3wp.exe is in the deadlocked state. This takes a few minutes on my box. Attach VS and party on.

[tjanczuk]

The fix in e907682 fixes the problem for configurations with only one node.js application within an IIS worker process (i.e. one entry point to a node.js applicaiton, e.g. server.js). This is the vast majority of cases. In fact, I am unaware of anyone utilizing the ability of iisnode to host more than one node.js application in a single IIS worker process (i.e. server1.js and server2.js).

This fix fixes the deadlock issue for deployments with single node.js application running in an IIS worker process. It does not solve the deadlock issue for deployments with multiple node.js applications running in a single IIS worker process. Such fix would be more risky in terms of regressions to other scenarios. Given no evidence anyone needs it I am postponing this fix indefinitely. Please reactivate if you hit the issue.

[tjanczuk]

The fix seems to have resolved the deadlock problem, but uncovered an AV that occurs about ~15 mins into stress testing the app above by auto-updating it every 1.3 seconds. Below are the details:

FAULTING_IP:
iisnode!CNodeEventProvider::Log+1b [e:\projects\iisnode\src\iisnode\cnodeeventprovider.cpp @ 63]
7135aa6b 837e1800 cmp dword ptr [esi+18h],0

EXCEPTION_RECORD: ffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 7135aa6b (iisnode!CNodeEventProvider::Log+0x0000001b)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000000
Parameter[1]: 00000018
Attempt to read from address 00000018

FAULTING_THREAD: 0000148c

PROCESS_NAME: w3wp.exe

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1: 00000000

EXCEPTION_PARAMETER2: 00000018

READ_ADDRESS: 00000018

FOLLOWUP_IP:
iisnode!CNodeEventProvider::Log+1b [e:\projects\iisnode\src\iisnode\cnodeeventprovider.cpp @ 63]
7135aa6b 837e1800 cmp dword ptr [esi+18h],0

NTGLOBALFLAG: 2

APPLICATION_VERIFIER_FLAGS: 0

APP: w3wp.exe

MANAGED_STACK: !dumpstack -EE
No export dumpstack found

MANAGED_BITNESS_MISMATCH:
Managed code needs matching platform of sos.dll for proper analysis. Use 'x86' debugger.

BUGCHECK_STR: APPLICATION_FAULT_NULL_CLASS_PTR_READ_STACK_POINTER_MISMATCH

PRIMARY_PROBLEM_CLASS: NULL_CLASS_PTR_READ_STACK_POINTER_MISMATCH

DEFAULT_BUCKET_ID: NULL_CLASS_PTR_READ_STACK_POINTER_MISMATCH

LAST_CONTROL_TRANSFER: from 71360989 to 7135aa6b

STACK_TEXT:
038afb7c 71360989 7138fa28 00000005 00a80b04 iisnode!CNodeEventProvider::Log+0x1b
038afb94 71352610 00000000 00000000 00a80b20 iisnode!CProtocolBridge::SendHttpRequestHeadersCompleted+0xb9
038afdc0 713627db 00afc828 4e355781 00000000 iisnode!CAsyncManager::Worker+0xf0
038afdf8 71362903 00000000 038afe10 76b28543 iisnode!_callthreadstartex+0x1b
038afe04 76b28543 01357988 038afe54 77c5ac69 iisnode!_threadstartex+0x7c
038afe10 77c5ac69 01357988 48dc4606 00000000 KERNEL32!BaseThreadInitThunk+0xe
038afe54 77c5ac3c 71362887 01357988 ffffffff ntdll!__RtlUserThreadStart+0x72
038afe6c 00000000 71362887 01357988 00000000 ntdll!_RtlUserThreadStart+0x1b

FAULTING_SOURCE_LINE: e:\projects\iisnode\src\iisnode\cnodeeventprovider.cpp

FAULTING_SOURCE_FILE: e:\projects\iisnode\src\iisnode\cnodeeventprovider.cpp

FAULTING_SOURCE_LINE_NUMBER: 63

SYMBOL_STACK_INDEX: 0

SYMBOL_NAME: iisnode!CNodeEventProvider::Log+1b

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: iisnode

IMAGE_NAME: iisnode.dll

DEBUG_FLR_IMAGE_TIMESTAMP: 5180077c

STACK_COMMAND: ~15s ; kb

FAILURE_BUCKET_ID: NULL_CLASS_PTR_READ_STACK_POINTER_MISMATCH_c0000005_iisnode.dll!CNodeEventProvider::Log

BUCKET_ID: APPLICATION_FAULT_NULL_CLASS_PTR_READ_STACK_POINTER_MISMATCH_iisnode!CNodeEventProvider::Log+1b

WATSON_STAGEONE_URL: http://watson.microsoft.com/StageOne/w3wp_exe/8_0_9200_16384/5010885f/iisnode_dll/0_2_5_0/5180077c/c0000005/0000aa6b.htm?Retriage=1

Followup: MachineOwner

---

0:015> !uniqstack -bvpn
Processing 25 threads, please wait

. 14 Id: ad4.10e8 Suspend: 1 Teb: fee4e000 Unfrozen
Priority: 0 Priority class: 32

ChildEBP RetAddr Args to Child

00 0382f6e0 776d1129 0000049c 00000001 00000000 ntdll!NtWaitForSingleObject+0xc
01 0382f74c 713524f9 00000000 ffffffff 00000001 KERNELBASE!WaitForSingleObjectEx+0x8f
02 0382f768 713627db 00afc828 4e3d5dd9 00000000 iisnode!CAsyncManager::TimerWorker+0x19 [e:\projects\iisnode\src\iisnode\casyncmanager.cpp @ 150]
03 0382f7a0 71362903 00000000 0382f7b8 76b28543 iisnode!_callthreadstartex+0x1b [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 354]
04 0382f7ac 76b28543 01356a68 0382f7fc 77c5ac69 iisnode!_threadstartex+0x7c [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 332]
05 0382f7b8 77c5ac69 01356a68 48d44fae 00000000 KERNEL32!BaseThreadInitThunk+0xe
06 0382f7fc 77c5ac3c 71362887 01356a68 ffffffff ntdll!__RtlUserThreadStart+0x72
07 0382f814 00000000 71362887 01356a68 00000000 ntdll!_RtlUserThreadStart+0x1b

. 15 Id: ad4.148c Suspend: 1 Teb: fee4b000 Unfrozen
Priority: 0 Priority class: 32

ChildEBP RetAddr Args to Child

00 038afb7c 71360989 7138fa28 00000005 00a80b04 iisnode!CNodeEventProvider::Log+0x1b [e:\projects\iisnode\src\iisnode\cnodeeventprovider.cpp @ 63]
01 038afb94 71352610 00000000 00000000 00a80b20 iisnode!CProtocolBridge::SendHttpRequestHeadersCompleted+0xb9 [e:\projects\iisnode\src\iisnode\cprotocolbridge.cpp @ 793]
02 038afdc0 713627db 00afc828 4e355781 00000000 iisnode!CAsyncManager::Worker+0xf0 [e:\projects\iisnode\src\iisnode\casyncmanager.cpp @ 198]
03 038afdf8 71362903 00000000 038afe10 76b28543 iisnode!_callthreadstartex+0x1b [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 354]
04 038afe04 76b28543 01357988 038afe54 77c5ac69 iisnode!_threadstartex+0x7c [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 332]
05 038afe10 77c5ac69 01357988 48dc4606 00000000 KERNEL32!BaseThreadInitThunk+0xe
06 038afe54 77c5ac3c 71362887 01357988 ffffffff ntdll!__RtlUserThreadStart+0x72
07 038afe6c 00000000 71362887 01357988 00000000 ntdll!_RtlUserThreadStart+0x1b

. 16 Id: ad4.d3c Suspend: 1 Teb: fee45000 Unfrozen
Priority: 0 Priority class: 32

ChildEBP RetAddr Args to Child

00 039afb80 77718092 000004a8 039afbe8 039afbcc ntdll!NtRemoveIoCompletion+0xc
01 039afbb4 71353ac0 000004a8 039afbe0 039afbe8 KERNELBASE!GetQueuedCompletionStatus+0x2a
02 039afc04 713627db 01379550 4e255645 00000000 iisnode!CFileWatcher::Worker+0x50 [e:\projects\iisnode\src\iisnode\cfilewatcher.cpp @ 489]
03 039afc3c 71362903 00000000 039afc54 76b28543 iisnode!_callthreadstartex+0x1b [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 354]
04 039afc48 76b28543 013553b8 039afc98 77c5ac69 iisnode!_threadstartex+0x7c [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 332]
05 039afc54 77c5ac69 013553b8 48cc44ca 00000000 KERNEL32!BaseThreadInitThunk+0xe
06 039afc98 77c5ac3c 71362887 013553b8 ffffffff ntdll!__RtlUserThreadStart+0x72
07 039afcb0 00000000 71362887 013553b8 00000000 ntdll!_RtlUserThreadStart+0x1b

. 18 Id: ad4.1570 Suspend: 1 Teb: fee6c000 Unfrozen
Priority: 0 Priority class: 32

ChildEBP RetAddr Args to Child

00 006cfb38 776dc752 00000001 01370ce8 00000000 ntdll!NtWaitForMultipleObjects+0xc
01 006cfcbc 76b26aeb 00000001 006cfc64 00000001 KERNELBASE!WaitForMultipleObjectsEx+0x10b
02 006cfcd8 7135d2a5 00000001 01370ce8 00000001 KERNEL32!WaitForMultipleObjects+0x19
03 006cfd00 713627db 00afd2e8 4dd35741 00000000 iisnode!CNodeProcessManager::GracefulShutdown+0xa5 [e:\projects\iisnode\src\iisnode\cnodeprocessmanager.cpp @ 329]
04 006cfd38 71362903 00000000 006cfd50 76b28543 iisnode!_callthreadstartex+0x1b [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 354]
05 006cfd44 76b28543 013d8e18 006cfd94 77c5ac69 iisnode!_threadstartex+0x7c [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 332]
06 006cfd50 77c5ac69 013d8e18 4b3a45c6 00000000 KERNEL32!BaseThreadInitThunk+0xe
07 006cfd94 77c5ac3c 71362887 013d8e18 ffffffff ntdll!__RtlUserThreadStart+0x72
08 006cfdac 00000000 71362887 013d8e18 00000000 ntdll!_RtlUserThreadStart+0x1b

. 23 Id: ad4.1184 Suspend: 1 Teb: fedd0000 Unfrozen
Priority: 0 Priority class: 32

ChildEBP RetAddr Args to Child

00 0407fdd0 776d1129 00002bac 00000001 00000000 ntdll!NtWaitForSingleObject+0xc
01 0407fe3c 7135c6b1 00000000 ffffffff 00000001 KERNELBASE!WaitForSingleObjectEx+0x8f
02 0407fe64 713627db 01371890 49b854e5 00000000 iisnode!CNodeProcess::ProcessWatcher+0x51 [e:\projects\iisnode\src\iisnode\cnodeprocess.cpp @ 307]
03 0407fe9c 71362903 00000000 0407feb4 76b28543 iisnode!_callthreadstartex+0x1b [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 354]
04 0407fea8 76b28543 013db7b0 0407fef8 77c5ac69 iisnode!_threadstartex+0x7c [f:\dd\vctools\crt_bld\self_x86\crt\src\threadex.c @ 332]
05 0407feb4 77c5ac69 013db7b0 4f5146aa 00000000 KERNEL32!BaseThreadInitThunk+0xe
06 0407fef8 77c5ac3c 71362887 013db7b0 ffffffff ntdll!__RtlUserThreadStart+0x72
07 0407ff10 00000000 71362887 013db7b0 00000000 ntdll!_RtlUserThreadStart+0x1b

[tjanczuk]

Closing this issue and tracking the new issue in #274