api: upgrade logging

Log runtime information to quickly check whether the values are sane when analyzing error logs sent in by users. Signed-off-by: Simon Rozman <[email protected]>
WireGuard · Feb 5, 2021 · efbeab2 · efbeab2
1 parent 542a281
commit efbeab2
Show file tree

Hide file tree

Showing 9 changed files with 422 additions and 177 deletions.
diff --git a/api/adapter.c b/api/adapter.c
diff --git a/api/elevate.c b/api/elevate.c
@@ -42,7 +42,7 @@ _Return_type_success_(return != FALSE) BOOL ElevateToSystem(void)
     CloseHandle(CurrentProcessToken);
     if (!Ret)
     {
-        LOG_ERROR(L"Failed to get token information", LastError);
+        LOG_ERROR(LastError, L"Failed to get token information");
         goto cleanup;
     }
     if (EqualSid(TokenUserBuffer.MaybeLocalSystem.User.Sid, LocalSystemSid))

diff --git a/api/logger.c b/api/logger.c
@@ -5,6 +5,7 @@
 
 #include "logger.h"
 #include <Windows.h>
+#include <winternl.h>
 #include <wchar.h>
 
 static BOOL CALLBACK
@@ -25,6 +26,13 @@ WintunSetLogger(_In_ WINTUN_LOGGER_CALLBACK NewLogger)
     Logger = NewLogger;
 }
 
+static VOID
+StrTruncate(_Inout_count_(StrChars) WCHAR *Str, _In_ SIZE_T StrChars)
+{
+    Str[StrChars - 2] = L'\u2026'; /* Horizontal Ellipsis */
+    Str[StrChars - 1] = 0;
+}
+
 _Post_equals_last_error_ DWORD
 LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *LogLine)
 {
@@ -33,10 +41,7 @@ LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ c
     {
         WCHAR Combined[0x400];
         if (_snwprintf_s(Combined, _countof(Combined), _TRUNCATE, L"%s: %s", Function, LogLine) == -1)
-        {
-            Combined[_countof(Combined) - 2] = L'\u2026'; /* Horizontal Ellipsis */
-            Combined[_countof(Combined) - 1] = 0;
-        }
+            StrTruncate(Combined, _countof(Combined));
         Logger(Level, Combined);
     }
     else
@@ -46,7 +51,26 @@ LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ c
 }
 
 _Post_equals_last_error_ DWORD
-LoggerError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix, _In_ DWORD Error)
+LoggerLogV(
+    _In_ WINTUN_LOGGER_LEVEL Level,
+    _In_z_ const WCHAR *Function,
+    _In_z_ _Printf_format_string_ const WCHAR *Format,
+    _In_ va_list Args)
+{
+    DWORD LastError = GetLastError();
+    WCHAR LogLine[0x400];
+    if (_vsnwprintf_s(LogLine, _countof(LogLine), _TRUNCATE, Format, Args) == -1)
+        StrTruncate(LogLine, _countof(LogLine));
+    if (Function)
+        LoggerLog(Level, Function, LogLine);
+    else
+        Logger(Level, LogLine);
+    SetLastError(LastError);
+    return LastError;
+}
+
+_Post_equals_last_error_ DWORD
+LoggerError(_In_ DWORD Error, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix)
 {
     WCHAR *SystemMessage = NULL, *FormattedMessage = NULL;
     FormatMessageW(
@@ -72,3 +96,51 @@ LoggerError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix, _In_ DWORD
     LocalFree(SystemMessage);
     return Error;
 }
+
+_Post_equals_last_error_ DWORD
+LoggerErrorV(
+    _In_ DWORD Error,
+    _In_z_ const WCHAR *Function,
+    _In_z_ _Printf_format_string_ const WCHAR *Format,
+    _In_ va_list Args)
+{
+    WCHAR Prefix[0x400];
+    if (_vsnwprintf_s(Prefix, _countof(Prefix), _TRUNCATE, Format, Args) == -1)
+        StrTruncate(Prefix, _countof(Prefix));
+    return LoggerError(Error, Function, Prefix);
+}
+
+VOID
+LoggerGetRegistryKeyPath(_In_ HKEY Key, _Out_cap_c_(MAX_REG_PATH) WCHAR *Path)
+{
+    DWORD LastError = GetLastError();
+    if (Key == NULL)
+    {
+        wcscpy_s(Path, MAX_REG_PATH, L"<null>");
+        goto out;
+    }
+    if (_snwprintf_s(Path, MAX_REG_PATH, _TRUNCATE, L"0x%p", Key) == -1)
+        StrTruncate(Path, MAX_REG_PATH);
+    HMODULE Dll = LoadLibraryExW(L"ntdll.dll", NULL, LOAD_LIBRARY_SEARCH_SYSTEM32);
+    if (Dll == NULL)
+        goto out;
+    typedef DWORD(__stdcall * NT_QUERY_KEY_FUNC)(
+        HANDLE KeyHandle, int KeyInformationClass, PVOID KeyInformation, ULONG Length, PULONG ResultLength);
+    NT_QUERY_KEY_FUNC NtQueryKey = (NT_QUERY_KEY_FUNC)(GetProcAddress(Dll, "NtQueryKey"));
+    struct _KEY_NAME_INFORMATION
+    {
+        ULONG NameLength;
+        WCHAR Name[MAX_REG_PATH];
+    } Buffer;
+    DWORD Size;
+    if (NtQueryKey == NULL || !NT_SUCCESS(NtQueryKey(Key, 3, &Buffer, sizeof(Buffer), &Size)) ||
+        Size < offsetof(struct _KEY_NAME_INFORMATION, Name) || Buffer.NameLength >= MAX_REG_PATH * sizeof(WCHAR))
+        goto cleanupDll;
+    Buffer.NameLength /= sizeof(WCHAR);
+    wmemcpy_s(Path, MAX_REG_PATH, Buffer.Name, Buffer.NameLength);
+    Path[Buffer.NameLength] = L'\0';
+cleanupDll:
+    FreeLibrary(Dll);
+out:
+    SetLastError(LastError);
+}
diff --git a/api/logger.h b/api/logger.h
@@ -7,7 +7,10 @@
 
 #include "wintun.h"
 #include "entry.h"
+#include "registry.h"
 #include <Windows.h>
+#include <stdarg.h>
+#include <wchar.h>
 
 extern WINTUN_LOGGER_CALLBACK Logger;
 
@@ -21,22 +24,73 @@ _Post_equals_last_error_ DWORD
 LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *LogLine);
 
 _Post_equals_last_error_ DWORD
-LoggerError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix, _In_ DWORD Error);
+LoggerLogV(
+    _In_ WINTUN_LOGGER_LEVEL Level,
+    _In_z_ const WCHAR *Function,
+    _In_z_ _Printf_format_string_ const WCHAR *Format,
+    _In_ va_list Args);
 
 static inline _Post_equals_last_error_ DWORD
-LoggerLastError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix)
+LoggerLogFmt(
+    _In_ WINTUN_LOGGER_LEVEL Level,
+    _In_z_ const WCHAR *Function,
+    _In_z_ _Printf_format_string_ const WCHAR *Format,
+    ...)
+{
+    va_list Args;
+    va_start(Args, Format);
+    DWORD LastError = LoggerLogV(Level, Function, Format, Args);
+    va_end(Args);
+    return LastError;
+}
+
+_Post_equals_last_error_ DWORD
+LoggerError(_In_ DWORD Error, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix);
+
+_Post_equals_last_error_ DWORD
+LoggerErrorV(
+    _In_ DWORD Error,
+    _In_z_ const WCHAR *Function,
+    _In_z_ _Printf_format_string_ const WCHAR *Format,
+    _In_ va_list Args);
+
+static inline _Post_equals_last_error_ DWORD
+LoggerErrorFmt(_In_ DWORD Error, _In_z_ const WCHAR *Function, _In_z_ _Printf_format_string_ const WCHAR *Format, ...)
+{
+    va_list Args;
+    va_start(Args, Format);
+    DWORD LastError = LoggerErrorV(Error, Function, Format, Args);
+    va_end(Args);
+    return LastError;
+}
+
+static inline _Post_equals_last_error_ DWORD
+LoggerLastErrorV(_In_z_ const WCHAR *Function, _In_z_ _Printf_format_string_ const WCHAR *Format, _In_ va_list Args)
 {
     DWORD LastError = GetLastError();
-    LoggerError(Function, Prefix, LastError);
+    LoggerErrorV(LastError, Function, Format, Args);
     SetLastError(LastError);
     return LastError;
 }
 
+static inline _Post_equals_last_error_ DWORD
+LoggerLastErrorFmt(_In_z_ const WCHAR *Function, _In_z_ _Printf_format_string_ const WCHAR *Format, ...)
+{
+    va_list Args;
+    va_start(Args, Format);
+    DWORD LastError = LoggerLastErrorV(Function, Format, Args);
+    va_end(Args);
+    return LastError;
+}
+
+VOID
+LoggerGetRegistryKeyPath(_In_ HKEY Key, _Out_cap_c_(MAX_REG_PATH) WCHAR *Path);
+
 #define __L(x) L##x
 #define _L(x) __L(x)
-#define LOG(lvl, msg) (LoggerLog((lvl), _L(__FUNCTION__), msg))
-#define LOG_ERROR(msg, err) (LoggerError(_L(__FUNCTION__), msg, (err)))
-#define LOG_LAST_ERROR(msg) (LoggerLastError(_L(__FUNCTION__), msg))
+#define LOG(lvl, msg, ...) (LoggerLogFmt((lvl), _L(__FUNCTION__), msg, __VA_ARGS__))
+#define LOG_ERROR(err, msg, ...) (LoggerErrorFmt((err), _L(__FUNCTION__), msg, __VA_ARGS__))
+#define LOG_LAST_ERROR(msg, ...) (LoggerLastErrorFmt(_L(__FUNCTION__), msg, __VA_ARGS__))
 
 #define RET_ERROR(Ret, Error) ((Error) == ERROR_SUCCESS ? (Ret) : (SetLastError(Error), 0))
 
@@ -46,13 +100,14 @@ static inline _Return_type_success_(return != NULL) _Ret_maybenull_
     void *Data = HeapAlloc(ModuleHeap, Flags, Size);
     if (!Data)
     {
-        LoggerLog(WINTUN_LOG_ERR, Function, L"Out of memory");
+        LoggerLogFmt(WINTUN_LOG_ERR, Function, L"Out of memory (flags: 0x%x, requested size: 0x%zx)", Flags, Size);
         SetLastError(ERROR_OUTOFMEMORY);
     }
     return Data;
 }
 #define Alloc(Size) LoggerAlloc(_L(__FUNCTION__), 0, Size)
 #define Zalloc(Size) LoggerAlloc(_L(__FUNCTION__), HEAP_ZERO_MEMORY, Size)
+
 static inline void
 Free(void *Ptr)
 {

diff --git a/api/namespace.c b/api/namespace.c
@@ -32,7 +32,7 @@ static _Return_type_success_(
         Free(Str);
         if (GetLastError() != ERROR_INSUFFICIENT_BUFFER)
         {
-            LOG_LAST_ERROR(L"Failed");
+            LOG_LAST_ERROR(L"Failed: %s", Source);
             return NULL;
         }
         Len = -Len;
@@ -53,7 +53,7 @@ static _Return_type_success_(return != FALSE) BOOL NamespaceRuntimeInit(void)
     NTSTATUS Status;
     if (!BCRYPT_SUCCESS(Status = BCryptOpenAlgorithmProvider(&AlgProvider, BCRYPT_SHA256_ALGORITHM, NULL, 0)))
     {
-        LOG(WINTUN_LOG_ERR, L"Failed to open algorithm provider");
+        LOG(WINTUN_LOG_ERR, L"Failed to open algorithm provider (status: 0x%x)", Status);
         LastError = RtlNtStatusToDosError(Status);
         goto cleanupLeaveCriticalSection;
     }
@@ -88,10 +88,10 @@ static _Return_type_success_(return != FALSE) BOOL NamespaceRuntimeInit(void)
                 break;
             if ((LastError = GetLastError()) == ERROR_PATH_NOT_FOUND)
                 continue;
-            LOG_ERROR(L"Failed to open private namespace", LastError);
+            LOG_ERROR(LastError, L"Failed to open private namespace");
         }
         else
-            LOG_ERROR(L"Failed to create private namespace", LastError);
+            LOG_ERROR(LastError, L"Failed to create private namespace");
         goto cleanupBoundaryDescriptor;
     }
 
@@ -118,7 +118,7 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
     NTSTATUS Status;
     if (!BCRYPT_SUCCESS(Status = BCryptCreateHash(AlgProvider, &Sha256, NULL, 0, NULL, 0, 0)))
     {
-        LOG(WINTUN_LOG_ERR, L"Failed to create hash");
+        LOG(WINTUN_LOG_ERR, L"Failed to create hash (status: 0x%x)", Status);
         SetLastError(RtlNtStatusToDosError(Status));
         return NULL;
     }
@@ -127,7 +127,7 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
     if (!BCRYPT_SUCCESS(
             Status = BCryptHashData(Sha256, (PUCHAR)mutex_label, sizeof(mutex_label) /* Including NULL 2 bytes */, 0)))
     {
-        LOG(WINTUN_LOG_ERR, L"Failed to hash data");
+        LOG(WINTUN_LOG_ERR, L"Failed to hash data (status: 0x%x)", Status);
         LastError = RtlNtStatusToDosError(Status);
         goto cleanupSha256;
     }
@@ -140,14 +140,14 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
     if (!BCRYPT_SUCCESS(
             Status = BCryptHashData(Sha256, (PUCHAR)PoolNorm, (int)wcslen(PoolNorm) + 2 /* Add in NULL 2 bytes */, 0)))
     {
-        LOG(WINTUN_LOG_ERR, L"Failed to hash data");
+        LOG(WINTUN_LOG_ERR, L"Failed to hash data (status: 0x%x)", Status);
         LastError = RtlNtStatusToDosError(Status);
         goto cleanupPoolNorm;
     }
     BYTE Hash[32];
     if (!BCRYPT_SUCCESS(Status = BCryptFinishHash(Sha256, Hash, sizeof(Hash), 0)))
     {
-        LOG(WINTUN_LOG_ERR, L"Failed to calculate hash");
+        LOG(WINTUN_LOG_ERR, L"Failed to calculate hash (status: 0x%x)", Status);
         LastError = RtlNtStatusToDosError(Status);
         goto cleanupPoolNorm;
     }
@@ -159,18 +159,19 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
     HANDLE Mutex = CreateMutexW(&SecurityAttributes, FALSE, MutexName);
     if (!Mutex)
     {
-        LastError = LOG_LAST_ERROR(L"Failed to create mutex");
+        LastError = LOG_LAST_ERROR(L"Failed to create mutex %s", MutexName);
         goto cleanupPoolNorm;
     }
-    switch (WaitForSingleObject(Mutex, INFINITE))
+    DWORD Result = WaitForSingleObject(Mutex, INFINITE);
+    switch (Result)
     {
     case WAIT_OBJECT_0:
     case WAIT_ABANDONED:
         Free(PoolNorm);
         BCryptDestroyHash(Sha256);
         return Mutex;
     }
-    LOG(WINTUN_LOG_ERR, L"Failed to get mutex");
+    LOG(WINTUN_LOG_ERR, L"Failed to get mutex %s (status: 0x%x)", MutexName, Result);
     LastError = ERROR_GEN_FAILURE;
     CloseHandle(Mutex);
 cleanupPoolNorm:
@@ -192,13 +193,14 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakeDriverInstallationMute
         LOG_LAST_ERROR(L"Failed to create mutex");
         return NULL;
     }
-    switch (WaitForSingleObject(Mutex, INFINITE))
+    DWORD Result = WaitForSingleObject(Mutex, INFINITE);
+    switch (Result)
     {
     case WAIT_OBJECT_0:
     case WAIT_ABANDONED:
         return Mutex;
     }
-    LOG(WINTUN_LOG_ERR, L"Failed to get mutex");
+    LOG(WINTUN_LOG_ERR, L"Failed to get mutex (status: 0x%x)", Result);
     CloseHandle(Mutex);
     SetLastError(ERROR_GEN_FAILURE);
     return NULL;