From c7aad6161166d330099cc48ceab7ee158b8225a2 Mon Sep 17 00:00:00 2001 From: Blue Date: Wed, 8 Oct 2025 18:24:31 -0700 Subject: [PATCH] Improve logging when socket operations fail (#13579) * Don't throw when processing an empty argument * Cleanup diff --- src/linux/init/util.cpp | 14 +++++----- src/linux/init/util.h | 4 ++- src/shared/inc/stringshared.h | 17 ++++++++++++ src/windows/common/hvsocket.cpp | 12 +++++---- src/windows/common/hvsocket.hpp | 12 +++++++-- src/windows/common/socket.cpp | 37 +++++++++++++++----------- src/windows/common/socket.hpp | 38 ++++++++++++++++++++++----- src/windows/service/exe/WslCoreVm.cpp | 5 ++-- src/windows/service/exe/WslCoreVm.h | 2 +- 9 files changed, 103 insertions(+), 38 deletions(-) diff --git a/src/linux/init/util.cpp b/src/linux/init/util.cpp index ed214f3..8befb93 100644 --- a/src/linux/init/util.cpp +++ b/src/linux/init/util.cpp @@ -537,7 +537,7 @@ Return Value: return Socket; } -wil::unique_fd UtilConnectVsock(unsigned int Port, bool CloseOnExec, std::optional SocketBuffer) noexcept +wil::unique_fd UtilConnectVsock(unsigned int Port, bool CloseOnExec, std::optional SocketBuffer, const std::source_location& Source) noexcept /*++ @@ -553,6 +553,8 @@ Arguments: 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 {}; } diff --git a/src/linux/init/util.h b/src/linux/init/util.h index b90fa6c..dc744ef 100644 --- a/src/linux/init/util.h +++ b/src/linux/init/util.h @@ -28,6 +28,7 @@ Abstract: #include #include #include +#include #include "lxinitshared.h" #include "lxdef.h" #include "common.h" @@ -128,7 +129,8 @@ wil::unique_fd UtilConnectToInteropServer(std::optional Pid = {}); wil::unique_fd UtilConnectUnix(const char* Path); -wil::unique_fd UtilConnectVsock(unsigned int Port, bool CloseOnExec, std::optional SocketBuffer = {}) noexcept; +wil::unique_fd UtilConnectVsock( + unsigned int Port, bool CloseOnExec, std::optional SocketBuffer = {}, const std::source_location& Source = std::source_location::current()) noexcept; // Needs to be declared before UtilCreateChildProcess(). void UtilSetThreadName(const char* Name); diff --git a/src/shared/inc/stringshared.h b/src/shared/inc/stringshared.h index e000153..bf0d47e 100644 --- a/src/shared/inc/stringshared.h +++ b/src/shared/inc/stringshared.h @@ -20,6 +20,7 @@ Abstract: #include #include #include +#include #ifndef WIN32 #include @@ -834,6 +835,22 @@ struct std::formatter } }; +template <> +struct std::formatter +{ + template + static constexpr auto parse(TCtx& ctx) + { + return ctx.begin(); + } + + template + 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 { diff --git a/src/windows/common/hvsocket.cpp b/src/windows/common/hvsocket.cpp index d2b730f..96b426c 100644 --- a/src/windows/common/hvsocket.cpp +++ b/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(&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; diff --git a/src/windows/common/hvsocket.hpp b/src/windows/common/hvsocket.hpp index 4caca79..08b08a0 100644 --- a/src/windows/common/hvsocket.hpp +++ b/src/windows/common/hvsocket.hpp @@ -19,9 +19,17 @@ Abstract: namespace wsl::windows::common::hvsocket { -wil::unique_socket Accept(_In_ SOCKET ListenSocket, _In_ int Timeout, _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); +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(); diff --git a/src/windows/common/socket.cpp b/src/windows/common/socket.cpp index 74c1aaf..89d6a87 100644 --- a/src/windows/common/socket.cpp +++ b/src/windows/common/socket.cpp @@ -17,7 +17,8 @@ Abstract: #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(&ListenSocket), sizeof(ListenSocket)) == SOCKET_ERROR); + THROW_LAST_ERROR_IF_MSG( + setsockopt(Socket, SOL_SOCKET, SO_UPDATE_ACCEPT_CONTEXT, reinterpret_cast(&ListenSocket), sizeof(ListenSocket)) == SOCKET_ERROR, + "From: %hs", + std::format("{}", Location).c_str()); return; } -std::pair wsl::windows::common::socket::GetResult(_In_ SOCKET Socket, _In_ OVERLAPPED& Overlapped, _In_ DWORD Timeout, _In_ HANDLE ExitHandle) +std::pair 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 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 wsl::windows::common::socket::GetResult(_In_ SOCKET Sock return {bytesProcessed, flagsReturned}; } -int wsl::windows::common::socket::Receive(_In_ SOCKET Socket, _In_ gsl::span Buffer, _In_opt_ HANDLE ExitHandle, _In_ DWORD Flags, _In_ DWORD Timeout) +int wsl::windows::common::socket::Receive( + _In_ SOCKET Socket, _In_ gsl::span 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 Buffer, _In_opt_ HANDLE ExitHandle, _In_ DWORD Flags, _In_ DWORD Timeout) + _In_ SOCKET Socket, _In_ gsl::span 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 wsl::windows::common::socket::Receive(_In_ SOCKET Socket, _In_opt_ HANDLE ExitHandle, _In_ DWORD Timeout) +std::vector 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 Buffer(Size); - WI_VERIFY(Receive(Socket, gsl::make_span(Buffer), ExitHandle, Timeout) == static_cast(Size)); + WI_VERIFY(Receive(Socket, gsl::make_span(Buffer), ExitHandle, MSG_WAITALL, Timeout, Location) == static_cast(Size)); return Buffer; } -int wsl::windows::common::socket::Send(_In_ SOCKET Socket, _In_ gsl::span Buffer, _In_opt_ HANDLE ExitHandle) +int wsl::windows::common::socket::Send( + _In_ SOCKET Socket, _In_ gsl::span 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(Buffer.size())); diff --git a/src/windows/common/socket.hpp b/src/windows/common/socket.hpp index 3cab9e6..a72e8ce 100644 --- a/src/windows/common/socket.hpp +++ b/src/windows/common/socket.hpp @@ -18,16 +18,42 @@ Abstract: namespace wsl::windows::common::socket { -void Accept(_In_ SOCKET ListenSocket, _In_ SOCKET Socket, _In_ int Timeout, _In_opt_ HANDLE ExitHandle); +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 GetResult(_In_ SOCKET Socket, _In_ OVERLAPPED& Overlapped, _In_ DWORD Timeout, _In_ HANDLE ExitHandle); +std::pair 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 Buffer, _In_opt_ HANDLE ExitHandle = nullptr, _In_ DWORD Flags = MSG_WAITALL, _In_ DWORD Timeout = INFINITE); +int Receive( + _In_ SOCKET Socket, + _In_ gsl::span 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 Receive(_In_ SOCKET Socket, _In_opt_ HANDLE ExitHandle = nullptr, _In_ DWORD Timeout = INFINITE); +std::vector 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 Buffer, _In_opt_ HANDLE ExitHandle = nullptr, _In_ DWORD Flags = MSG_WAITALL, _In_ DWORD Timeout = INFINITE); +int ReceiveNoThrow( + _In_ SOCKET Socket, + _In_ gsl::span 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 Buffer, _In_opt_ HANDLE ExitHandle = nullptr); +int Send( + _In_ SOCKET Socket, + _In_ gsl::span Buffer, + _In_opt_ HANDLE ExitHandle = nullptr, + _In_ const std::source_location& Location = std::source_location::current()); } // namespace wsl::windows::common::socket diff --git a/src/windows/service/exe/WslCoreVm.cpp b/src/windows/service/exe/WslCoreVm.cpp index b7b9517..adb08bb 100644 --- a/src/windows/service/exe/WslCoreVm.cpp +++ b/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); diff --git a/src/windows/service/exe/WslCoreVm.h b/src/windows/service/exe/WslCoreVm.h index e4596fb..df664e0 100644 --- a/src/windows/service/exe/WslCoreVm.h +++ b/src/windows/service/exe/WslCoreVm.h @@ -61,7 +61,7 @@ public: ~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 {