request never completes in stress case of auto-update and process termination

[tjanczuk]

This is a stress scenario:

1. Client sends requests to the server sequentially. Subsequent request is only sent when response to the previous request is received.
2. Server similates auto-update at 1.3 second interval through changes to a watched file.
3. Server throws unhandled exceptions in node.js processes 1 second after the process was created.

Observed: After 5-20 minutes client request "hangs" - no response is received. However, server remains healthy - requests from other clients succeed.

Expected: HTTP 200 or 500

Private instrumentation show the following ETW traces of the hanging request:

2       <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode increases pending async operation count</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode scheduled a retry of a named pipe connection to the node.exe process </Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode dispatched new http request</Data>
1       <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode decreases pending async operation count</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode leaves CNodeHttpModule::OnExecuteRequestHandler with RQ_NOTIFICATION_PENDING</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode created named pipe connection to the node.exe process</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode initiated sending http request headers to the node.exe process and completed synchronously</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode finished sending http request headers to the node.exe process</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode initiated reading http request body chunk and completed synchronously</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode detected the end of the http request body</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode starting to read http response</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode initiated reading http response chunk and will complete asynchronously</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode starting to process http response status line</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode finished processing http response status line</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode starting to process http response headers</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode finished processing http response headers</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode starting to process http response body chunk header</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode finished processing http response body chunk header</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode starting to process http response body</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode started sending http response body chunk</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode finished processing http request/response</Data>
0       <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode decreases pending async operation count</Data>
        <Data>{D57E3549-5B8C-4FD5-B5C5-53E44137894F}: iisnode posts completion from FinalizeResponse</Data>

This ETW trace suggests the final PostComplete(0) was called, but OnAsyncCompletion associated with that PostComplete was not invoked. As a result IIS considers the request active.

Status of the CNodeHttpStoredContext representing this request:

-       CNodeHttpStoredContext::last    0x0000002946d210d0 {activityId={D57E3549-5B8C-4FD5-B5C5-53E44137894F} nodeApplication=0x0000002944f19c50 {...} ...} CNodeHttpStoredContext *
+       IHttpStoredContext  {...}   IHttpStoredContext
+       activityId  {D57E3549-5B8C-4FD5-B5C5-53E44137894F}  _GUID
+       nodeApplication 0x0000002944f19c50 {scriptName=0x005c003f003f005c <Error reading characters of string.> applicationManager=...} CNodeApplication *
+       context 0x0000002945e593d0 {...}    IHttpContext *
+       asyncContext    {overlapped={Internal=0 InternalHigh=147 Offset=0 ...} completionProcessor=0x0000000000000000 continueSynchronously=...}    ASYNC_CONTEXT
+       process 0x0000002945df2f30 {processManager=0x0000002945e9ec90 {application=0x0000002944f19cd0 {scriptName=0x0000002944f6d1d0 L"f:\\Program Files\\iisnode\\www\\helloworld\\hello.js" ...} ...} ...}    CNodeProcess *
        pipe    0xffffffffffffffff  void *
        connectionRetryCount    1   unsigned long
        buffer  0x0000002945e5a218  void *
        bufferSize  4096    unsigned long
        dataSize    0   unsigned long
        parsingOffset   0   unsigned long
        chunkTransmitted    0   __int64
        chunkLength 0   __int64
        isChunked   1   int
        result  S_OK    HRESULT
        requestNotificationStatus   RQ_NOTIFICATION_CONTINUE (0)    REQUEST_NOTIFICATION_STATUS
        pendingAsyncOperationCount  0   volatile long
+       targetUrl   0x0000002945e58bb8 "/node/helloworld/hello.js/151656"   const char *
        targetUrlLength 32  unsigned long
+       childContext    0x0000000000000000 {...}    IHttpContext *
        isLastChunk 1   int
        isConnectionFromPool    0   int
        expectResponseBody  1   int
        closeConnection 0   int
        isUpgrade   0   int
+       upgradeContext  0x0000000000000000 {activityId={Data1=??? Data2=??? Data3=??? ...} nodeApplication=??? context=??? ...} CNodeHttpStoredContext *
        opaqueFlagSet   0   int
        requestPumpStarted  0   int
+       startTime   {dwLowDateTime=895178349 dwHighDateTime=30296823 }  _FILETIME
+       responseChunk   {DataChunkType=HttpDataChunkFromMemory (0) FromMemory={pBuffer=0x0000002946d09c40 BufferLength=14 } ...}    _HTTP_DATA_CHUNK
        responseChunkBufferSize 14  unsigned long
+       eventProvider   0x0000002945dad2b0 {handle=11822126287825616 advapi=advapi32.dll!0x000007fd39d80000 {unused=9460301 } ...}  CNodeEventProvider *

The CNodeApplication had already been disposed. Response appears to be fully processed with the final call to PostComplete to transition to the IIS thread on OnAsyncCompletion. The latter method appears not to be called.

[tjanczuk]

The CNodeProcess instance associated with the request appears still to exist:

-       process 0x0000002945df2f30 {processManager=0x0000002945e9ec90 {application=0x0000002944f19cd0 {scriptName=0x0000002944f6d1d0 L"f:\\Program Files\\iisnode\\www\\helloworld\\hello.js" ...} ...} ...}    CNodeProcess *
+       processManager  0x0000002945e9ec90 {application=0x0000002944f19cd0 {scriptName=0x0000002944f6d1d0 L"f:\\Program Files\\iisnode\\www\\helloworld\\hello.js" ...} ...}    CNodeProcessManager *
+       activeRequestPool   {requestCount=0 syncRoot={DebugInfo=0xffffffffffffffff {Type=??? CreatorBackTraceIndex=??? CriticalSection=...} ...} ...}   CActiveRequestPool
+       namedPipe   0x0000002945df2f70 "\\\\.\\pipe\\925ef079-dc12-4f75-9740-0e69203a4991"  char[256]
        process 0x000000000001de30  void *
        processWatcher  0x000000000001e1ec  void *
        maxConcurrentRequestsPerProcess 4096    unsigned long
        isClosing   0   int
+       startupInfo {cb=104 lpReserved=0x0000002944f02514 {0} lpDesktop=0x0000002944f02512 {0} ...} _STARTUPINFOW
        hasProcessExited    0   int
+       overlapped  {Internal=0 InternalHigh=0 Offset=0 ...}    _OVERLAPPED
+       connectionPool  {list=0x0000002946d26010 {Alignment=0 Region=0 Header8={Depth=0 Sequence=0 NextEntry=0 ...} ...} count=...} CConnectionPool
        pid 2336    unsigned long