Skip to content

Commit bc5cde8

Browse files
rozmansirozmansi
committed
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]>
1 parent 542a281 commit bc5cde8

File tree

10 files changed

+431
-177
lines changed

10 files changed

+431
-177
lines changed

‎api/adapter.c‎

Lines changed: 173 additions & 112 deletions
Large diffs are not rendered by default.

‎api/elevate.c‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ _Return_type_success_(return != FALSE) BOOL ElevateToSystem(void)
4242
CloseHandle(CurrentProcessToken);
4343
if (!Ret)
4444
{
45-
LOG_ERROR(L"Failed to get token information", LastError);
45+
LOG_ERROR(LastError, L"Failed to get token information");
4646
goto cleanup;
4747
}
4848
if (EqualSid(TokenUserBuffer.MaybeLocalSystem.User.Sid, LocalSystemSid))

‎api/logger.c‎

Lines changed: 70 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,9 @@
44
*/
55

66
#include "logger.h"
7+
#include "ntdll.h"
78
#include <Windows.h>
9+
#include <winternl.h>
810
#include <wchar.h>
911

1012
static BOOL CALLBACK
@@ -25,6 +27,13 @@ WintunSetLogger(_In_ WINTUN_LOGGER_CALLBACK NewLogger)
2527
Logger = NewLogger;
2628
}
2729

30+
static VOID
31+
StrTruncate(_Inout_count_(StrChars) WCHAR *Str, _In_ SIZE_T StrChars)
32+
{
33+
Str[StrChars - 2] = L'\u2026'; /* Horizontal Ellipsis */
34+
Str[StrChars - 1] = 0;
35+
}
36+
2837
_Post_equals_last_error_ DWORD
2938
LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *LogLine)
3039
{
@@ -33,10 +42,7 @@ LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ c
3342
{
3443
WCHAR Combined[0x400];
3544
if (_snwprintf_s(Combined, _countof(Combined), _TRUNCATE, L"%s: %s", Function, LogLine) == -1)
36-
{
37-
Combined[_countof(Combined) - 2] = L'\u2026'; /* Horizontal Ellipsis */
38-
Combined[_countof(Combined) - 1] = 0;
39-
}
45+
StrTruncate(Combined, _countof(Combined));
4046
Logger(Level, Combined);
4147
}
4248
else
@@ -46,7 +52,26 @@ LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ c
4652
}
4753

4854
_Post_equals_last_error_ DWORD
49-
LoggerError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix, _In_ DWORD Error)
55+
LoggerLogV(
56+
_In_ WINTUN_LOGGER_LEVEL Level,
57+
_In_z_ const WCHAR *Function,
58+
_In_z_ _Printf_format_string_ const WCHAR *Format,
59+
_In_ va_list Args)
60+
{
61+
DWORD LastError = GetLastError();
62+
WCHAR LogLine[0x400];
63+
if (_vsnwprintf_s(LogLine, _countof(LogLine), _TRUNCATE, Format, Args) == -1)
64+
StrTruncate(LogLine, _countof(LogLine));
65+
if (Function)
66+
LoggerLog(Level, Function, LogLine);
67+
else
68+
Logger(Level, LogLine);
69+
SetLastError(LastError);
70+
return LastError;
71+
}
72+
73+
_Post_equals_last_error_ DWORD
74+
LoggerError(_In_ DWORD Error, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix)
5075
{
5176
WCHAR *SystemMessage = NULL, *FormattedMessage = NULL;
5277
FormatMessageW(
@@ -72,3 +97,43 @@ LoggerError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix, _In_ DWORD
7297
LocalFree(SystemMessage);
7398
return Error;
7499
}
100+
101+
_Post_equals_last_error_ DWORD
102+
LoggerErrorV(
103+
_In_ DWORD Error,
104+
_In_z_ const WCHAR *Function,
105+
_In_z_ _Printf_format_string_ const WCHAR *Format,
106+
_In_ va_list Args)
107+
{
108+
WCHAR Prefix[0x400];
109+
if (_vsnwprintf_s(Prefix, _countof(Prefix), _TRUNCATE, Format, Args) == -1)
110+
StrTruncate(Prefix, _countof(Prefix));
111+
return LoggerError(Error, Function, Prefix);
112+
}
113+
114+
VOID
115+
LoggerGetRegistryKeyPath(_In_ HKEY Key, _Out_cap_c_(MAX_REG_PATH) WCHAR *Path)
116+
{
117+
DWORD LastError = GetLastError();
118+
if (Key == NULL)
119+
{
120+
wcscpy_s(Path, MAX_REG_PATH, L"<null>");
121+
goto out;
122+
}
123+
if (_snwprintf_s(Path, MAX_REG_PATH, _TRUNCATE, L"0x%p", Key) == -1)
124+
StrTruncate(Path, MAX_REG_PATH);
125+
union
126+
{
127+
KEY_NAME_INFORMATION KeyNameInfo;
128+
WCHAR Data[offsetof(KEY_NAME_INFORMATION, Name) + MAX_REG_PATH];
129+
} Buffer;
130+
DWORD Size;
131+
if (!NT_SUCCESS(NtQueryKey(Key, 3, &Buffer, sizeof(Buffer), &Size)) ||
132+
Size < offsetof(KEY_NAME_INFORMATION, Name) || Buffer.KeyNameInfo.NameLength >= MAX_REG_PATH * sizeof(WCHAR))
133+
goto out;
134+
Buffer.KeyNameInfo.NameLength /= sizeof(WCHAR);
135+
wmemcpy_s(Path, MAX_REG_PATH, Buffer.KeyNameInfo.Name, Buffer.KeyNameInfo.NameLength);
136+
Path[Buffer.KeyNameInfo.NameLength] = L'\0';
137+
out:
138+
SetLastError(LastError);
139+
}

‎api/logger.h‎

Lines changed: 62 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,10 @@
77

88
#include "wintun.h"
99
#include "entry.h"
10+
#include "registry.h"
1011
#include <Windows.h>
12+
#include <stdarg.h>
13+
#include <wchar.h>
1114

1215
extern WINTUN_LOGGER_CALLBACK Logger;
1316

@@ -21,22 +24,73 @@ _Post_equals_last_error_ DWORD
2124
LoggerLog(_In_ WINTUN_LOGGER_LEVEL Level, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *LogLine);
2225

2326
_Post_equals_last_error_ DWORD
24-
LoggerError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix, _In_ DWORD Error);
27+
LoggerLogV(
28+
_In_ WINTUN_LOGGER_LEVEL Level,
29+
_In_z_ const WCHAR *Function,
30+
_In_z_ _Printf_format_string_ const WCHAR *Format,
31+
_In_ va_list Args);
2532

2633
static inline _Post_equals_last_error_ DWORD
27-
LoggerLastError(_In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix)
34+
LoggerLogFmt(
35+
_In_ WINTUN_LOGGER_LEVEL Level,
36+
_In_z_ const WCHAR *Function,
37+
_In_z_ _Printf_format_string_ const WCHAR *Format,
38+
...)
39+
{
40+
va_list Args;
41+
va_start(Args, Format);
42+
DWORD LastError = LoggerLogV(Level, Function, Format, Args);
43+
va_end(Args);
44+
return LastError;
45+
}
46+
47+
_Post_equals_last_error_ DWORD
48+
LoggerError(_In_ DWORD Error, _In_z_ const WCHAR *Function, _In_z_ const WCHAR *Prefix);
49+
50+
_Post_equals_last_error_ DWORD
51+
LoggerErrorV(
52+
_In_ DWORD Error,
53+
_In_z_ const WCHAR *Function,
54+
_In_z_ _Printf_format_string_ const WCHAR *Format,
55+
_In_ va_list Args);
56+
57+
static inline _Post_equals_last_error_ DWORD
58+
LoggerErrorFmt(_In_ DWORD Error, _In_z_ const WCHAR *Function, _In_z_ _Printf_format_string_ const WCHAR *Format, ...)
59+
{
60+
va_list Args;
61+
va_start(Args, Format);
62+
DWORD LastError = LoggerErrorV(Error, Function, Format, Args);
63+
va_end(Args);
64+
return LastError;
65+
}
66+
67+
static inline _Post_equals_last_error_ DWORD
68+
LoggerLastErrorV(_In_z_ const WCHAR *Function, _In_z_ _Printf_format_string_ const WCHAR *Format, _In_ va_list Args)
2869
{
2970
DWORD LastError = GetLastError();
30-
LoggerError(Function, Prefix, LastError);
71+
LoggerErrorV(LastError, Function, Format, Args);
3172
SetLastError(LastError);
3273
return LastError;
3374
}
3475

76+
static inline _Post_equals_last_error_ DWORD
77+
LoggerLastErrorFmt(_In_z_ const WCHAR *Function, _In_z_ _Printf_format_string_ const WCHAR *Format, ...)
78+
{
79+
va_list Args;
80+
va_start(Args, Format);
81+
DWORD LastError = LoggerLastErrorV(Function, Format, Args);
82+
va_end(Args);
83+
return LastError;
84+
}
85+
86+
VOID
87+
LoggerGetRegistryKeyPath(_In_ HKEY Key, _Out_cap_c_(MAX_REG_PATH) WCHAR *Path);
88+
3589
#define __L(x) L##x
3690
#define _L(x) __L(x)
37-
#define LOG(lvl, msg) (LoggerLog((lvl), _L(__FUNCTION__), msg))
38-
#define LOG_ERROR(msg, err) (LoggerError(_L(__FUNCTION__), msg, (err)))
39-
#define LOG_LAST_ERROR(msg) (LoggerLastError(_L(__FUNCTION__), msg))
91+
#define LOG(lvl, msg, ...) (LoggerLogFmt((lvl), _L(__FUNCTION__), msg, __VA_ARGS__))
92+
#define LOG_ERROR(err, msg, ...) (LoggerErrorFmt((err), _L(__FUNCTION__), msg, __VA_ARGS__))
93+
#define LOG_LAST_ERROR(msg, ...) (LoggerLastErrorFmt(_L(__FUNCTION__), msg, __VA_ARGS__))
4094

4195
#define RET_ERROR(Ret, Error) ((Error) == ERROR_SUCCESS ? (Ret) : (SetLastError(Error), 0))
4296

@@ -46,13 +100,14 @@ static inline _Return_type_success_(return != NULL) _Ret_maybenull_
46100
void *Data = HeapAlloc(ModuleHeap, Flags, Size);
47101
if (!Data)
48102
{
49-
LoggerLog(WINTUN_LOG_ERR, Function, L"Out of memory");
103+
LoggerLogFmt(WINTUN_LOG_ERR, Function, L"Out of memory (flags: 0x%x, requested size: 0x%zx)", Flags, Size);
50104
SetLastError(ERROR_OUTOFMEMORY);
51105
}
52106
return Data;
53107
}
54108
#define Alloc(Size) LoggerAlloc(_L(__FUNCTION__), 0, Size)
55109
#define Zalloc(Size) LoggerAlloc(_L(__FUNCTION__), HEAP_ZERO_MEMORY, Size)
110+
56111
static inline void
57112
Free(void *Ptr)
58113
{

‎api/namespace.c‎

Lines changed: 15 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ static _Return_type_success_(
3232
Free(Str);
3333
if (GetLastError() != ERROR_INSUFFICIENT_BUFFER)
3434
{
35-
LOG_LAST_ERROR(L"Failed");
35+
LOG_LAST_ERROR(L"Failed: %s", Source);
3636
return NULL;
3737
}
3838
Len = -Len;
@@ -53,7 +53,7 @@ static _Return_type_success_(return != FALSE) BOOL NamespaceRuntimeInit(void)
5353
NTSTATUS Status;
5454
if (!BCRYPT_SUCCESS(Status = BCryptOpenAlgorithmProvider(&AlgProvider, BCRYPT_SHA256_ALGORITHM, NULL, 0)))
5555
{
56-
LOG(WINTUN_LOG_ERR, L"Failed to open algorithm provider");
56+
LOG(WINTUN_LOG_ERR, L"Failed to open algorithm provider (status: 0x%x)", Status);
5757
LastError = RtlNtStatusToDosError(Status);
5858
goto cleanupLeaveCriticalSection;
5959
}
@@ -88,10 +88,10 @@ static _Return_type_success_(return != FALSE) BOOL NamespaceRuntimeInit(void)
8888
break;
8989
if ((LastError = GetLastError()) == ERROR_PATH_NOT_FOUND)
9090
continue;
91-
LOG_ERROR(L"Failed to open private namespace", LastError);
91+
LOG_ERROR(LastError, L"Failed to open private namespace");
9292
}
9393
else
94-
LOG_ERROR(L"Failed to create private namespace", LastError);
94+
LOG_ERROR(LastError, L"Failed to create private namespace");
9595
goto cleanupBoundaryDescriptor;
9696
}
9797

@@ -118,7 +118,7 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
118118
NTSTATUS Status;
119119
if (!BCRYPT_SUCCESS(Status = BCryptCreateHash(AlgProvider, &Sha256, NULL, 0, NULL, 0, 0)))
120120
{
121-
LOG(WINTUN_LOG_ERR, L"Failed to create hash");
121+
LOG(WINTUN_LOG_ERR, L"Failed to create hash (status: 0x%x)", Status);
122122
SetLastError(RtlNtStatusToDosError(Status));
123123
return NULL;
124124
}
@@ -127,7 +127,7 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
127127
if (!BCRYPT_SUCCESS(
128128
Status = BCryptHashData(Sha256, (PUCHAR)mutex_label, sizeof(mutex_label) /* Including NULL 2 bytes */, 0)))
129129
{
130-
LOG(WINTUN_LOG_ERR, L"Failed to hash data");
130+
LOG(WINTUN_LOG_ERR, L"Failed to hash data (status: 0x%x)", Status);
131131
LastError = RtlNtStatusToDosError(Status);
132132
goto cleanupSha256;
133133
}
@@ -140,14 +140,14 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
140140
if (!BCRYPT_SUCCESS(
141141
Status = BCryptHashData(Sha256, (PUCHAR)PoolNorm, (int)wcslen(PoolNorm) + 2 /* Add in NULL 2 bytes */, 0)))
142142
{
143-
LOG(WINTUN_LOG_ERR, L"Failed to hash data");
143+
LOG(WINTUN_LOG_ERR, L"Failed to hash data (status: 0x%x)", Status);
144144
LastError = RtlNtStatusToDosError(Status);
145145
goto cleanupPoolNorm;
146146
}
147147
BYTE Hash[32];
148148
if (!BCRYPT_SUCCESS(Status = BCryptFinishHash(Sha256, Hash, sizeof(Hash), 0)))
149149
{
150-
LOG(WINTUN_LOG_ERR, L"Failed to calculate hash");
150+
LOG(WINTUN_LOG_ERR, L"Failed to calculate hash (status: 0x%x)", Status);
151151
LastError = RtlNtStatusToDosError(Status);
152152
goto cleanupPoolNorm;
153153
}
@@ -159,18 +159,19 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const
159159
HANDLE Mutex = CreateMutexW(&SecurityAttributes, FALSE, MutexName);
160160
if (!Mutex)
161161
{
162-
LastError = LOG_LAST_ERROR(L"Failed to create mutex");
162+
LastError = LOG_LAST_ERROR(L"Failed to create mutex %s", MutexName);
163163
goto cleanupPoolNorm;
164164
}
165-
switch (WaitForSingleObject(Mutex, INFINITE))
165+
DWORD Result = WaitForSingleObject(Mutex, INFINITE);
166+
switch (Result)
166167
{
167168
case WAIT_OBJECT_0:
168169
case WAIT_ABANDONED:
169170
Free(PoolNorm);
170171
BCryptDestroyHash(Sha256);
171172
return Mutex;
172173
}
173-
LOG(WINTUN_LOG_ERR, L"Failed to get mutex");
174+
LOG(WINTUN_LOG_ERR, L"Failed to get mutex %s (status: 0x%x)", MutexName, Result);
174175
LastError = ERROR_GEN_FAILURE;
175176
CloseHandle(Mutex);
176177
cleanupPoolNorm:
@@ -192,13 +193,14 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakeDriverInstallationMute
192193
LOG_LAST_ERROR(L"Failed to create mutex");
193194
return NULL;
194195
}
195-
switch (WaitForSingleObject(Mutex, INFINITE))
196+
DWORD Result = WaitForSingleObject(Mutex, INFINITE);
197+
switch (Result)
196198
{
197199
case WAIT_OBJECT_0:
198200
case WAIT_ABANDONED:
199201
return Mutex;
200202
}
201-
LOG(WINTUN_LOG_ERR, L"Failed to get mutex");
203+
LOG(WINTUN_LOG_ERR, L"Failed to get mutex (status: 0x%x)", Result);
202204
CloseHandle(Mutex);
203205
SetLastError(ERROR_GEN_FAILURE);
204206
return NULL;

‎api/ntdll.h‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,12 @@ typedef struct _RTL_PROCESS_MODULES
3232
RTL_PROCESS_MODULE_INFORMATION Modules[1];
3333
} RTL_PROCESS_MODULES, *PRTL_PROCESS_MODULES;
3434

35+
typedef struct _KEY_NAME_INFORMATION
36+
{
37+
ULONG NameLength;
38+
WCHAR Name[1];
39+
} KEY_NAME_INFORMATION, *PKEY_NAME_INFORMATION;
40+
3541
#define STATUS_INFO_LENGTH_MISMATCH ((NTSTATUS)0xC0000004L) // TODO: #include <ntstatus.h> instead of this
3642
#define STATUS_PNP_DEVICE_CONFIGURATION_PENDING ((NTSTATUS)0xC0000495L)
3743

@@ -46,3 +52,12 @@ typedef struct _RTL_PROCESS_MODULES
4652
EXTERN_C
4753
DECLSPEC_IMPORT VOID NTAPI
4854
RtlGetNtVersionNumbers(_Out_opt_ DWORD *MajorVersion, _Out_opt_ DWORD *MinorVersion, _Out_opt_ DWORD *BuildNumber);
55+
56+
EXTERN_C
57+
DECLSPEC_IMPORT DWORD NTAPI
58+
NtQueryKey(
59+
_In_ HANDLE KeyHandle,
60+
_In_ int KeyInformationClass,
61+
_Out_bytecap_post_bytecount_(Length, *ResultLength) PVOID KeyInformation,
62+
_In_ ULONG Length,
63+
_Out_ PULONG ResultLength);

0 commit comments

Comments
 (0)