Improve logging when socket operations fail (#13579)

* Don't throw when processing an empty argument

* Cleanup diff

Author: OneBlue

src/linux/init/util.cpp

@@ -537,7 +537,7 @@ Return Value:
     return Socket;
 }
 
-wil::unique_fd UtilConnectVsock(unsigned int Port, bool CloseOnExec, std::optional<int> SocketBuffer) noexcept
+wil::unique_fd UtilConnectVsock(unsigned int Port, bool CloseOnExec, std::optional<int> SocketBuffer, const std::source_location& Source) noexcept
 
 /*++
 
@@ -553,6 +553,8 @@ Routine Description:
 
     SocketBuffer - Optionally supplies the size to use for the socket send and receive buffers.
 
+    Source - Supplies the caller location.
+
 Return Value:
 
     A file descriptor representing the connected socket, -1 on failure.
@@ -565,7 +567,7 @@ Return Value:
     wil::unique_fd SocketFd{socket(AF_VSOCK, Type, 0)};
     if (!SocketFd)
     {
-        LOG_ERROR("socket failed {}", errno);
+        LOG_ERROR("socket failed {} (from: {})", errno, Source);
         return {};
     }
 
@@ -577,7 +579,7 @@ Return Value:
     Timeout.tv_sec = LX_INIT_HVSOCKET_TIMEOUT_SECONDS;
     if (setsockopt(SocketFd.get(), AF_VSOCK, SO_VM_SOCKETS_CONNECT_TIMEOUT, &Timeout, sizeof(Timeout)) < 0)
     {
-        LOG_ERROR("setsockopt SO_VM_SOCKETS_CONNECT_TIMEOUT failed {}", errno);
+        LOG_ERROR("setsockopt SO_VM_SOCKETS_CONNECT_TIMEOUT failed {}, (from: {})", errno, Source);
         return {};
     }
 
@@ -586,13 +588,13 @@ Return Value:
         int BufferSize = *SocketBuffer;
         if (setsockopt(SocketFd.get(), SOL_SOCKET, SO_SNDBUF, &BufferSize, sizeof(BufferSize)) < 0)
         {
-            LOG_ERROR("setsockopt(SO_SNDBUF, {}) failed {}", BufferSize, errno);
+            LOG_ERROR("setsockopt(SO_SNDBUF, {}) failed {}, (from: {})", BufferSize, errno, Source);
             return {};
         }
 
         if (setsockopt(SocketFd.get(), SOL_SOCKET, SO_RCVBUF, &BufferSize, sizeof(BufferSize)) < 0)
         {
-            LOG_ERROR("setsockopt(SO_RCVBUF, {}) failed {}", BufferSize, errno);
+            LOG_ERROR("setsockopt(SO_RCVBUF, {}) failed {}, (from: {})", BufferSize, errno, Source);
             return {};
         }
     }
@@ -603,7 +605,7 @@ Return Value:
     SocketAddress.svm_port = Port;
     if (connect(SocketFd.get(), (const struct sockaddr*)&SocketAddress, sizeof(SocketAddress)) < 0)
     {
-        LOG_ERROR("connect port {} failed {}", Port, errno);
+        LOG_ERROR("connect port {} failed {} (from: {})", Port, errno, Source);
         return {};
     }
 

src/linux/init/util.h

@@ -28,6 +28,7 @@ Module Name:
 #include <future>
 #include <filesystem>
 #include <vector>
+#include <source_location>
 #include "lxinitshared.h"
 #include "lxdef.h"
 #include "common.h"
@@ -128,7 +129,8 @@ wil::unique_fd UtilConnectToInteropServer(std::optional<pid_t> Pid = {});
 
 wil::unique_fd UtilConnectUnix(const char* Path);
 
-wil::unique_fd UtilConnectVsock(unsigned int Port, bool CloseOnExec, std::optional<int> SocketBuffer = {}) noexcept;
+wil::unique_fd UtilConnectVsock(
+    unsigned int Port, bool CloseOnExec, std::optional<int> SocketBuffer = {}, const std::source_location& Source = std::source_location::current()) noexcept;
 
 // Needs to be declared before UtilCreateChildProcess().
 void UtilSetThreadName(const char* Name);

src/shared/inc/stringshared.h

@@ -20,6 +20,7 @@ Module Name:
 #include <fstream>
 #include <gsl/gsl>
 #include <format>
+#include <source_location>
 
 #ifndef WIN32
 #include <string.h>
@@ -834,6 +835,22 @@ struct std::formatter<wchar_t[N], char>
     }
 };
 
+template <>
+struct std::formatter<std::source_location, char>
+{
+    template <typename TCtx>
+    static constexpr auto parse(TCtx& ctx)
+    {
+        return ctx.begin();
+    }
+
+    template <typename TCtx>
+    auto format(const std::source_location& location, TCtx& ctx) const
+    {
+        return std::format_to(ctx.out(), "{}[{}:{}]", location.function_name(), location.file_name(), location.line());
+    }
+};
+
 template <>
 struct std::formatter<char*, wchar_t>
 {

src/windows/common/hvsocket.cpp

@@ -39,15 +39,17 @@ void InitializeWildcardSocketAddress(_Out_ PSOCKADDR_HV Address)
 }
 } // namespace
 
-wil::unique_socket wsl::windows::common::hvsocket::Accept(_In_ SOCKET ListenSocket, _In_ int Timeout, _In_opt_ HANDLE ExitHandle)
+wil::unique_socket wsl::windows::common::hvsocket::Accept(
+    _In_ SOCKET ListenSocket, _In_ int Timeout, _In_opt_ HANDLE ExitHandle, _In_ const std::source_location& Location)
 {
     wil::unique_socket Socket = Create();
-    wsl::windows::common::socket::Accept(ListenSocket, Socket.get(), Timeout, ExitHandle);
+    wsl::windows::common::socket::Accept(ListenSocket, Socket.get(), Timeout, ExitHandle, Location);
 
     return Socket;
 }
 
-wil::unique_socket wsl::windows::common::hvsocket::Connect(_In_ const GUID& VmId, _In_ unsigned long Port, _In_opt_ HANDLE ExitHandle)
+wil::unique_socket wsl::windows::common::hvsocket::Connect(
+    _In_ const GUID& VmId, _In_ unsigned long Port, _In_opt_ HANDLE ExitHandle, _In_ const std::source_location& Location)
 {
     OVERLAPPED Overlapped{};
     const wil::unique_event OverlappedEvent(wil::EventOptions::ManualReset);
@@ -71,7 +73,7 @@ wil::unique_socket wsl::windows::common::hvsocket::Connect(_In_ const GUID& VmId
 
     if (Result != 0)
     {
-        socket::GetResult(Socket.get(), Overlapped, INFINITE, ExitHandle);
+        socket::GetResult(Socket.get(), Overlapped, INFINITE, ExitHandle, Location);
     }
 
     ULONG Timeout = CONNECT_TIMEOUT;
@@ -86,7 +88,7 @@ wil::unique_socket wsl::windows::common::hvsocket::Connect(_In_ const GUID& VmId
     const BOOL Success = ConnectFn(Socket.get(), reinterpret_cast<sockaddr*>(&Addr), sizeof(Addr), nullptr, 0, nullptr, &Overlapped);
     if (Success == FALSE)
     {
-        socket::GetResult(Socket.get(), Overlapped, INFINITE, ExitHandle);
+        socket::GetResult(Socket.get(), Overlapped, INFINITE, ExitHandle, Location);
     }
 
     return Socket;

src/windows/common/hvsocket.hpp

@@ -19,9 +19,17 @@ Module Name:
 
 namespace wsl::windows::common::hvsocket {
 
-wil::unique_socket Accept(_In_ SOCKET ListenSocket, _In_ int Timeout, _In_opt_ HANDLE ExitHandle = nullptr);
-
-wil::unique_socket Connect(_In_ const GUID& VmId, _In_ unsigned long Port, _In_opt_ HANDLE ExitHandle = nullptr);
+wil::unique_socket Accept(
+    _In_ SOCKET ListenSocket,
+    _In_ int Timeout,
+    _In_opt_ HANDLE ExitHandle = nullptr,
+    const std::source_location& Location = std::source_location::current());
+
+wil::unique_socket Connect(
+    _In_ const GUID& VmId,
+    _In_ unsigned long Port,
+    _In_opt_ HANDLE ExitHandle = nullptr,
+    const std::source_location& Location = std::source_location::current());
 
 wil::unique_socket Create();
 

src/windows/common/socket.cpp

@@ -17,7 +17,8 @@ Module Name:
 #include "socket.hpp"
 #pragma hdrstop
 
-void wsl::windows::common::socket::Accept(_In_ SOCKET ListenSocket, _In_ SOCKET Socket, _In_ int Timeout, _In_opt_ HANDLE ExitHandle)
+void wsl::windows::common::socket::Accept(
+    _In_ SOCKET ListenSocket, _In_ SOCKET Socket, _In_ int Timeout, _In_opt_ HANDLE ExitHandle, _In_ const std::source_location& Location)
 {
     CHAR AcceptBuffer[2 * sizeof(SOCKADDR_STORAGE)]{};
     DWORD BytesReturned;
@@ -29,17 +30,20 @@ void wsl::windows::common::socket::Accept(_In_ SOCKET ListenSocket, _In_ SOCKET
 
     if (!Success)
     {
-        GetResult(ListenSocket, Overlapped, Timeout, ExitHandle);
+        GetResult(ListenSocket, Overlapped, Timeout, ExitHandle, Location);
     }
 
     // Set the accept context to mark the socket as connected.
-    THROW_LAST_ERROR_IF(
-        setsockopt(Socket, SOL_SOCKET, SO_UPDATE_ACCEPT_CONTEXT, reinterpret_cast<char*>(&ListenSocket), sizeof(ListenSocket)) == SOCKET_ERROR);
+    THROW_LAST_ERROR_IF_MSG(
+        setsockopt(Socket, SOL_SOCKET, SO_UPDATE_ACCEPT_CONTEXT, reinterpret_cast<char*>(&ListenSocket), sizeof(ListenSocket)) == SOCKET_ERROR,
+        "From: %hs",
+        std::format("{}", Location).c_str());
 
     return;
 }
 
-std::pair<DWORD, DWORD> wsl::windows::common::socket::GetResult(_In_ SOCKET Socket, _In_ OVERLAPPED& Overlapped, _In_ DWORD Timeout, _In_ HANDLE ExitHandle)
+std::pair<DWORD, DWORD> wsl::windows::common::socket::GetResult(
+    _In_ SOCKET Socket, _In_ OVERLAPPED& Overlapped, _In_ DWORD Timeout, _In_ HANDLE ExitHandle, _In_ const std::source_location& Location)
 {
     const int error = WSAGetLastError();
     THROW_HR_IF(HRESULT_FROM_WIN32(error), error != WSA_IO_PENDING);
@@ -64,7 +68,7 @@ std::pair<DWORD, DWORD> wsl::windows::common::socket::GetResult(_In_ SOCKET Sock
         return {0, 0};
     }
 
-    THROW_HR_IF(HCS_E_CONNECTION_TIMEOUT, (waitStatus != WAIT_OBJECT_0));
+    THROW_HR_IF_MSG(HCS_E_CONNECTION_TIMEOUT, (waitStatus != WAIT_OBJECT_0), "From: %hs", std::format("{}", Location).c_str());
 
     cancelFunction.release();
     const bool result = WSAGetOverlappedResult(Socket, &Overlapped, &bytesProcessed, FALSE, &flagsReturned);
@@ -83,16 +87,17 @@ std::pair<DWORD, DWORD> wsl::windows::common::socket::GetResult(_In_ SOCKET Sock
     return {bytesProcessed, flagsReturned};
 }
 
-int wsl::windows::common::socket::Receive(_In_ SOCKET Socket, _In_ gsl::span<gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle, _In_ DWORD Flags, _In_ DWORD Timeout)
+int wsl::windows::common::socket::Receive(
+    _In_ SOCKET Socket, _In_ gsl::span<gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle, _In_ DWORD Flags, _In_ DWORD Timeout, _In_ const std::source_location& Location)
 {
-    const int BytesRead = ReceiveNoThrow(Socket, Buffer, ExitHandle, Flags, Timeout);
+    const int BytesRead = ReceiveNoThrow(Socket, Buffer, ExitHandle, Flags, Timeout, Location);
     THROW_LAST_ERROR_IF(BytesRead == SOCKET_ERROR);
 
     return BytesRead;
 }
 
 int wsl::windows::common::socket::ReceiveNoThrow(
-    _In_ SOCKET Socket, _In_ gsl::span<gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle, _In_ DWORD Flags, _In_ DWORD Timeout)
+    _In_ SOCKET Socket, _In_ gsl::span<gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle, _In_ DWORD Flags, _In_ DWORD Timeout, _In_ const std::source_location& Location)
 {
     OVERLAPPED Overlapped{};
     const wil::unique_event OverlappedEvent(wil::EventOptions::ManualReset);
@@ -103,7 +108,7 @@ int wsl::windows::common::socket::ReceiveNoThrow(
         try
         {
             BytesReturned = SOCKET_ERROR;
-            auto [innerBytes, Flags] = GetResult(Socket, Overlapped, Timeout, ExitHandle);
+            auto [innerBytes, Flags] = GetResult(Socket, Overlapped, Timeout, ExitHandle, Location);
             BytesReturned = innerBytes;
         }
         catch (...)
@@ -116,20 +121,22 @@ int wsl::windows::common::socket::ReceiveNoThrow(
     return BytesReturned;
 }
 
-std::vector<gsl::byte> wsl::windows::common::socket::Receive(_In_ SOCKET Socket, _In_opt_ HANDLE ExitHandle, _In_ DWORD Timeout)
+std::vector<gsl::byte> wsl::windows::common::socket::Receive(
+    _In_ SOCKET Socket, _In_opt_ HANDLE ExitHandle, _In_ DWORD Timeout, _In_ const std::source_location& Location)
 {
-    Receive(Socket, {}, ExitHandle, MSG_PEEK);
+    Receive(Socket, {}, ExitHandle, MSG_PEEK, Timeout, Location);
 
     ULONG Size = 0;
     THROW_LAST_ERROR_IF(ioctlsocket(Socket, FIONREAD, &Size) == SOCKET_ERROR);
 
     std::vector<gsl::byte> Buffer(Size);
-    WI_VERIFY(Receive(Socket, gsl::make_span(Buffer), ExitHandle, Timeout) == static_cast<int>(Size));
+    WI_VERIFY(Receive(Socket, gsl::make_span(Buffer), ExitHandle, MSG_WAITALL, Timeout, Location) == static_cast<int>(Size));
 
     return Buffer;
 }
 
-int wsl::windows::common::socket::Send(_In_ SOCKET Socket, _In_ gsl::span<const gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle)
+int wsl::windows::common::socket::Send(
+    _In_ SOCKET Socket, _In_ gsl::span<const gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle, _In_ const std::source_location& Location)
 {
     OVERLAPPED Overlapped{};
     const wil::unique_event OverlappedEvent(wil::EventOptions::ManualReset);
@@ -139,7 +146,7 @@ int wsl::windows::common::socket::Send(_In_ SOCKET Socket, _In_ gsl::span<const
     if (WSASend(Socket, &VectorBuffer, 1, &BytesWritten, 0, &Overlapped, nullptr) != 0)
     {
         DWORD Flags;
-        std::tie(BytesWritten, Flags) = GetResult(Socket, Overlapped, INFINITE, ExitHandle);
+        std::tie(BytesWritten, Flags) = GetResult(Socket, Overlapped, INFINITE, ExitHandle, Location);
     }
 
     WI_ASSERT(BytesWritten == gsl::narrow_cast<DWORD>(Buffer.size()));

src/windows/common/socket.hpp

@@ -18,16 +18,42 @@ Module Name:
 
 namespace wsl::windows::common::socket {
 
-void Accept(_In_ SOCKET ListenSocket, _In_ SOCKET Socket, _In_ int Timeout, _In_opt_ HANDLE ExitHandle);
-
-std::pair<DWORD, DWORD> GetResult(_In_ SOCKET Socket, _In_ OVERLAPPED& Overlapped, _In_ DWORD Timeout, _In_ HANDLE ExitHandle);
-
-int Receive(_In_ SOCKET Socket, _In_ gsl::span<gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle = nullptr, _In_ DWORD Flags = MSG_WAITALL, _In_ DWORD Timeout = INFINITE);
-
-std::vector<gsl::byte> Receive(_In_ SOCKET Socket, _In_opt_ HANDLE ExitHandle = nullptr, _In_ DWORD Timeout = INFINITE);
-
-int ReceiveNoThrow(_In_ SOCKET Socket, _In_ gsl::span<gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle = nullptr, _In_ DWORD Flags = MSG_WAITALL, _In_ DWORD Timeout = INFINITE);
-
-int Send(_In_ SOCKET Socket, _In_ gsl::span<const gsl::byte> Buffer, _In_opt_ HANDLE ExitHandle = nullptr);
+void Accept(
+    _In_ SOCKET ListenSocket,
+    _In_ SOCKET Socket,
+    _In_ int Timeout,
+    _In_opt_ HANDLE ExitHandle,
+    _In_ const std::source_location& Location = std::source_location::current());
+
+std::pair<DWORD, DWORD> GetResult(
+    _In_ SOCKET Socket, _In_ OVERLAPPED& Overlapped, _In_ DWORD Timeout, _In_ HANDLE ExitHandle, _In_ const std::source_location& Location);
+
+int Receive(
+    _In_ SOCKET Socket,
+    _In_ gsl::span<gsl::byte> Buffer,
+    _In_opt_ HANDLE ExitHandle = nullptr,
+    _In_ DWORD Flags = MSG_WAITALL,
+    _In_ DWORD Timeout = INFINITE,
+    _In_ const std::source_location& Location = std::source_location::current());
+
+std::vector<gsl::byte> Receive(
+    _In_ SOCKET Socket,
+    _In_opt_ HANDLE ExitHandle = nullptr,
+    _In_ DWORD Timeout = INFINITE,
+    _In_ const std::source_location& Location = std::source_location::current());
+
+int ReceiveNoThrow(
+    _In_ SOCKET Socket,
+    _In_ gsl::span<gsl::byte> Buffer,
+    _In_opt_ HANDLE ExitHandle = nullptr,
+    _In_ DWORD Flags = MSG_WAITALL,
+    _In_ DWORD Timeout = INFINITE,
+    _In_ const std::source_location& Location = std::source_location::current());
+
+int Send(
+    _In_ SOCKET Socket,
+    _In_ gsl::span<const gsl::byte> Buffer,
+    _In_opt_ HANDLE ExitHandle = nullptr,
+    _In_ const std::source_location& Location = std::source_location::current());
 
 } // namespace wsl::windows::common::socket

src/windows/service/exe/WslCoreVm.cpp

@@ -879,9 +879,10 @@ WslCoreVm::~WslCoreVm() noexcept
     WSL_LOG("TerminateVmStop");
 }
 
-wil::unique_socket WslCoreVm::AcceptConnection(_In_ DWORD ReceiveTimeout) const
+wil::unique_socket WslCoreVm::AcceptConnection(_In_ DWORD ReceiveTimeout, _In_ const std::source_location& Location) const
 {
-    auto socket = wsl::windows::common::hvsocket::Accept(m_listenSocket.get(), m_vmConfig.KernelBootTimeout, m_terminatingEvent.get());
+    auto socket =
+        wsl::windows::common::hvsocket::Accept(m_listenSocket.get(), m_vmConfig.KernelBootTimeout, m_terminatingEvent.get(), Location);
     if (ReceiveTimeout != 0)
     {
         THROW_LAST_ERROR_IF(setsockopt(socket.get(), SOL_SOCKET, SO_RCVTIMEO, (const char*)&ReceiveTimeout, sizeof(ReceiveTimeout)) == SOCKET_ERROR);

src/windows/service/exe/WslCoreVm.h

@@ -61,7 +61,7 @@ class WslCoreVm
 
     ~WslCoreVm() noexcept;
 
-    wil::unique_socket AcceptConnection(_In_ DWORD ReceiveTimeout = 0) const;
+    wil::unique_socket AcceptConnection(_In_ DWORD ReceiveTimeout = 0, _In_ const std::source_location& Location = std::source_location::current()) const;
 
     enum class DiskType
     {