Fix crash caused by race condition in WinHttp teardown (#788)

Upon receiving a suspend event, the WinHttp provider will automatically tear down any active WebSocket connections. Depending on the current state of the connection, the suspend handler will either call WinHttpWebSocketClose followed by WinHttpCloseHandle, or just call WinHttpCloseHandle directly. If we receive a WinHttp disconnect callback at the same time, the disconnect handler will call WinHttpCloseHandle. This leads to race condition between the two handlers:

If the suspend handler runs first and determines that it needs to call WinHttpWebSocketClose (because at that point we believe the WebSocket is still connected) and then the disconnect handler runs and calls WinHttpCloseHandle BEFORE the suspend handler actually calls WinHttpWebSocketClose, the WinHttp handle may be in an invalid state when WebSocketClose finally gets called, leading to a crash.

The fix here involves a couple things. First, I updated the suspend handler to forego the call to WinHttpWebSocketClose altogether. This means that during suspend the WebSocket won't be torn down gracefully, but it greatly simplifies the LHC teardown process. Second, there is some additional logic needed to make sure that LHC still raises a disconnected event to clients during suspend, as the flow will change slightly with the removal of the WinHttpWebSocketClose call.

This change also contains a fix for a debug assert due to buffer size in FormatTrace

Source/HTTP/WinHttp/winhttp_connection.cpp

@@ -383,7 +383,6 @@ HRESULT WinHttpConnection::WebSocketDisconnect(_In_ HCWebSocketCloseStatus close
 
 HRESULT WinHttpConnection::Close(ConnectionClosedCallback callback)
 {
-    bool doWebSocketClose = false;
     bool doWinHttpClose = false;
     bool closeComplete = false;
 
@@ -402,9 +401,8 @@ HRESULT WinHttpConnection::Close(ConnectionClosedCallback callback)
         {
         case ConnectionState::WebSocketConnected:
         {
-            doWebSocketClose = true;
-            HC_TRACE_VERBOSE(HTTPCLIENT, "WinHttpConnection::Close: ConnectionState=WebSocketConnected, Closing WebSocket");
-            m_state = ConnectionState::WebSocketClosing;
+            doWinHttpClose = true;
+            HC_TRACE_VERBOSE(HTTPCLIENT, "WinHttpConnection::Close: ConnectionState=WebSocketConnected, Closing WinHttp handle");
             break;
         }
         case ConnectionState::WebSocketClosing:
@@ -430,13 +428,7 @@ HRESULT WinHttpConnection::Close(ConnectionClosedCallback callback)
         }
     }
 
-    if (doWebSocketClose)
-    {
-        assert(m_winHttpWebSocketExports.close);
-        DWORD result = m_winHttpWebSocketExports.close(m_hRequest, static_cast<USHORT>(HCWebSocketCloseStatus::GoingAway), nullptr, 0);
-        return HRESULT_FROM_WIN32(result);
-    }
-    else if (doWinHttpClose)
+    if (doWinHttpClose)
     {
         StartWinHttpClose();
     }
@@ -709,6 +701,11 @@ void WinHttpConnection::callback_status_request_error(
                 HC_TRACE_VERBOSE(HTTPCLIENT, "WinHttpConnection::callback_status_request_error after WebSocket was connected, moving to disconnect flow.");
                 disconnect = true;
             }
+            else if (pRequestContext->m_state == ConnectionState::WinHttpClosing)
+            {
+                HC_TRACE_VERBOSE(HTTPCLIENT, "WinHttpConnection::callback_status_request_error during WinHttpCloseHandle was connected, moving to disconnect flow.");
+                disconnect = true;
+            }
         }
 
         if (disconnect)
@@ -1326,7 +1323,7 @@ void WinHttpConnection::StartWinHttpClose()
         }
         else
         {
-            HC_TRACE_VERBOSE(HTTPCLIENT, "WinHttpConnection::StartWinHttpClose, transitioning to ConnectionState::WinHttpClosing");
+            HC_TRACE_VERBOSE(HTTPCLIENT, "WinHttpConnection::StartWinHttpClose, current state=%llu transitioning to ConnectionState::WinHttpClosing", m_state);
             m_state = ConnectionState::WinHttpClosing;
         }
     }

Source/Logger/trace.cpp

@@ -41,6 +41,16 @@ int sprintf_s(char* buffer, size_t size, _Printf_format_string_ char const* form
     return result;
 }
 
+template<size_t SIZE>
+int _snprintf_s(char(&buffer)[SIZE], size_t /*count*/, _Printf_format_string_ char const* format ...) noexcept
+{
+    va_list varArgs{};
+    va_start(varArgs, format);
+    auto result = vsnprintf(buffer, SIZE, format, varArgs);
+    va_end(varArgs);
+    return result;
+}
+
 template<size_t SIZE>
 int vstprintf_s(char(&buffer)[SIZE], _Printf_format_string_ char const* format, va_list varArgs) noexcept
 {
@@ -129,7 +139,7 @@ void FormatTrace(
 #endif
 
     // [threadId][level][time][area] message
-    auto written = sprintf_s(outputBuffer, "[%04llX][%s][%02d:%02d:%02d.%03u][%s] %s",
+    auto written = _snprintf_s(outputBuffer, SIZE - 3, "[%04llX][%s][%02d:%02d:%02d.%03u][%s] %s",
         threadId,
         traceLevelNames[static_cast<size_t>(level)],
         fmtTime.tm_hour,