locked
Calling WinHttpReceiveResponse() sometimes hangs RRS feed

  • Question

  • Hi,

    We are seeing an issue with WinHTTP, where calling WinHttpReceiveResponse() hangs in certain cases:

    When receiving a 401 error from a certain server, the call to WinHttpReceiveResponse() sometimes doesn't return, regardless of the timeout we set as a parameter. At first, this was difficult to reproduce, however we can now reproduce this consistently on certain machines (but not all!), when the server response uses chunked transfer-encoding, and the TCP layer breaks the packets down exactly after the HTTP-level-chunk-length is sent, so that the second TCP packet starts with the chunk data.

    In the problematic case, the WinHTTP trace shows that for some reason the thread pool is shut down and the winhttp-dll is released via FreeLibrary():

    12:46:30.133 ::WinHttpReceiveResponse(0x34be338, 0x0)
    12:46:30.133 ::sys-recver starts in _INIT state
    12:46:30.133 ::current thread is not impersonating
    12:46:30.133 ::sys-recver processing WebReceiveHttpResponse completion (error-cdoe = ERROR_SUCCESS (0x0), overlapped = 002FBD70))
    12:46:30.133 ::sys-recver has received response from WebIO
    12:46:30.133 ::sys-recver returning ERROR_SUCCESS (0) from RecvResponse()
    12:46:30.133 ::sys-req completes recv-headers inline (sync); error = ERROR_SUCCESS (0)
    12:46:30.134 ::user-creds is configured to use default credentials
    12:46:30.134 ::user-req created a default creds (scheme=16) to attempt auto-logon (target=0)
    12:46:30.134 ::usr-req 03519568 transitioning from state _SENDING_RECVING to state _READY
    12:46:30.134 ::sys-req transitioning from state _SENDING_RECVING to state _DRAINING_DATA
    12:46:30.134 ::current thread is not impersonating
    12:46:30.134 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.134 ::sys-recver transitioning from state _HEADERS_RECVED to state _READING_DATA
    12:46:30.134 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 201, error = ERROR_SUCCESS (0))
    12:46:30.134 ::sys-req pends drain-data
    12:46:30.134 ::usr-req 03519568 blocks waiting for async to complete...
    12:46:30.134 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_SUCCESS (0x0), #bytes = 201, overlapped = 0349D3F0)
    12:46:30.134 ::sys-req completes read-data successfully; # bytes transferred = 201
    12:46:30.134 ::current thread is not impersonating
    12:46:30.134 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.134 ::sys-recver transitioning from state _READING_DATA to state _READING_DATA
    12:46:30.134 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 28, error = ERROR_SUCCESS (0))
    12:46:30.134 ::sys-req pends drain-data
    12:46:30.134 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_SUCCESS (0x0), #bytes = 28, overlapped = 0349D3F0)
    12:46:30.134 ::sys-req completes read-data successfully; # bytes transferred = 28
    12:46:30.134 ::current thread is not impersonating
    12:46:30.134 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.134 ::sys-recver transitioning from state _READING_DATA to state _READING_DATA
    12:46:30.134 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 128, error = ERROR_SUCCESS (0))
    12:46:30.134 ::sys-req pends drain-data
    12:46:30.134 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_SUCCESS (0x0), #bytes = 128, overlapped = 0349D3F0)
    12:46:30.134 ::sys-req completes read-data successfully; # bytes transferred = 128
    12:46:30.134 ::current thread is not impersonating
    12:46:30.134 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.134 ::sys-recver transitioning from state _READING_DATA to state _READING_DATA
    12:46:30.134 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 28, error = ERROR_SUCCESS (0))
    12:46:30.134 ::sys-req pends drain-data
    12:46:30.134 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_SUCCESS (0x0), #bytes = 28, overlapped = 0349D3F0)
    12:46:30.134 ::sys-req completes read-data successfully; # bytes transferred = 28
    12:46:30.134 ::current thread is not impersonating
    12:46:30.134 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.134 ::sys-recver transitioning from state _READING_DATA to state _READING_DATA
    12:46:30.134 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 145, error = ERROR_SUCCESS (0))
    12:46:30.134 ::sys-req pends drain-data
    12:46:30.134 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_SUCCESS (0x0), #bytes = 145, overlapped = 0349D3F0)
    12:46:30.134 ::sys-req completes read-data successfully; # bytes transferred = 145
    12:46:30.134 ::current thread is not impersonating
    12:46:30.134 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.134 ::sys-recver transitioning from state _READING_DATA to state _READING_DATA
    12:46:30.134 ::sys-req pends drain-data
    12:46:30.134 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 109, error = ERROR_SUCCESS (0))
    12:46:30.134 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_SUCCESS (0x0), #bytes = 109, overlapped = 0349D3F0)
    12:46:30.134 ::sys-req completes read-data successfully; # bytes transferred = 109
    12:46:30.134 ::current thread is not impersonating
    12:46:30.134 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.134 ::sys-recver transitioning from state _READING_DATA to state _READING_DATA
    12:46:30.134 ::sys-req pends drain-data
    12:46:30.135 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 50, error = ERROR_SUCCESS (0))
    12:46:30.135 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_SUCCESS (0x0), #bytes = 50, overlapped = 0349D3F0)
    12:46:30.135 ::sys-req completes read-data successfully; # bytes transferred = 50
    12:46:30.135 ::current thread is not impersonating
    12:46:30.135 ::sys-recver calling WebReceiveHttpResponseEntity(overlapped = 0349D3F0, buffer-size = 8192)
    12:46:30.135 ::sys-recver transitioning from state _READING_DATA to state _READING_DATA
    12:46:30.135 ::sys-req pends drain-data
    12:46:30.135 :: <c-b> an async I/O operation completes (overlapped = 0349D3F0, #bytes/info = 0, error = ERROR_HANDLE_EOF (38))
    12:46:30.136 ::sys-recver processing WebReceiveHttpResponseEntity completion (error-cdoe = ERROR_HANDLE_EOF (0x26), #bytes = 0, overlapped = 0349D3F0)
    12:46:30.136 ::sys-recver detected EOF; all data has been read
    12:46:30.136 ::sys-req completes read-data successfully; # bytes transferred = 0
    12:46:30.136 ::sys-req shutting down; End-Of-File reached for read-data
    12:46:30.136 ::usr-req 03519568 transitioning from state _READY to state _SENDING_RECVING
    12:46:30.136 ::sys-req updates BytesToSend to 0
    12:46:30.136 ::sys-req transitioning from state _INIT to state _SENDING
    12:46:30.136 ::current thread is not impersonating
    12:46:30.136 ::sys-sender calling HttpSendHttpRequest(overlapped = 002FBD70)
    12:46:30.136 ::sys-sender transitioning from state _INIT to state _SENDING
    12:46:30.136 ::usr-req 03519568 received OnDnsResolvingName callback
    12:46:30.136 ::usr-req 03519568 received OnDnsNameResolved callback
    12:46:30.136 ::usr-req 03519568 received OnTcpConnecting callback
    12:46:30.136 ::sys-req pends send-request
    12:46:30.147 ::usr-req 03519568 received OnTcpConnected callback
    12:46:30.147 ::usr-req 03519568 received OnSendingRequest callback
    12:46:30.148 ::usr-req 03519568 received OnRequestSent callback
    12:46:30.293 ::thread pool is shutting down
    12:46:30.293 ::thread pool closed
    12:46:30.293 ::thread pool destroyed
    12:46:30.293 ::winhttp-dll object released its reference to winhttp.dll via FreeLibrary()
    12:46:32.069 ::thread pool is shutting down

    • Moved by Jesse Jiang Tuesday, October 25, 2011 5:54 AM (From:Visual C++ General)
    Monday, October 24, 2011 1:58 PM

All replies

  • Hi ,

     

    I think your issue should be raised in the Winsock Kernel (WSK). I believe they will know more information of this issue than us, and I will move this one to that forum.

     

    Thanks for your understanding,

     

    Best regards,

    Jesse


    Jesse Jiang [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.

    Tuesday, October 25, 2011 5:54 AM