From bc5cde89160e706789ec9cdadd06be8127d086f9 Mon Sep 17 00:00:00 2001 From: Simon Rozman Date: Tue, 2 Feb 2021 13:12:45 +0100 Subject: [PATCH] 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 --- api/adapter.c | 285 ++++++++++++++++++++++++++++------------------- api/elevate.c | 2 +- api/logger.c | 75 ++++++++++++- api/logger.h | 69 ++++++++++-- api/namespace.c | 28 ++--- api/ntdll.h | 15 +++ api/registry.c | 88 ++++++++++++--- api/resource.c | 20 ++-- api/rundll32_i.c | 24 ++-- api/session.c | 2 +- 10 files changed, 431 insertions(+), 177 deletions(-) diff --git a/api/adapter.c b/api/adapter.c index 1e43286..984af03 100644 --- a/api/adapter.c +++ b/api/adapter.c @@ -75,7 +75,11 @@ static _Return_type_success_(return != NULL) SP_DRVINFO_DETAIL_DATA_W *GetAdapte Free(DrvInfoDetailData); if (LastError != ERROR_INSUFFICIENT_BUFFER) { - SetLastError(LOG_ERROR(L"Failed", LastError)); + if (DevInfoData) + LOG_ERROR(LastError, L"Failed for adapter %u", DevInfoData->DevInst); + else + LOG_ERROR(LastError, L"Failed"); + SetLastError(LastError); return NULL; } } @@ -99,7 +103,8 @@ static _Return_type_success_(return != NULL) void *GetDeviceRegistryProperty( Free(Data); if (LastError != ERROR_INSUFFICIENT_BUFFER) { - SetLastError(LOG_ERROR(L"Querying property failed", LastError)); + SetLastError( + LOG_ERROR(LastError, L"Querying adapter %u property 0x%x failed", DevInfoData->DevInst, Property)); return NULL; } } @@ -122,7 +127,11 @@ static _Return_type_success_(return != NULL) LastError = GetLastError(); break; default: - LOG(WINTUN_LOG_ERR, L"Property is not a string"); + LOG(WINTUN_LOG_ERR, + L"Adapter %u property 0x%x is not a string (type: %u)", + DevInfoData->DevInst, + Property, + ValueType); LastError = ERROR_INVALID_DATATYPE; } Free(Buf); @@ -147,7 +156,11 @@ static _Return_type_success_(return != NULL) LastError = GetLastError(); break; default: - LOG(WINTUN_LOG_ERR, L"Property is not a string"); + LOG(WINTUN_LOG_ERR, + L"Adapter %u property 0x%x is not a string (type: %u)", + DevInfoData->DevInst, + Property, + ValueType); LastError = ERROR_INVALID_DATATYPE; } Free(Buf); @@ -170,7 +183,7 @@ IsOurAdapter(_In_ HDEVINFO DevInfo, _In_ SP_DEVINFO_DATA *DevInfoData) WCHAR *Hwids = GetDeviceRegistryMultiString(DevInfo, DevInfoData, SPDRP_HARDWAREID); if (!Hwids) { - LOG_LAST_ERROR(L"Failed to get hardware ID"); + LOG_LAST_ERROR(L"Failed to get adapter %u hardware ID", DevInfoData->DevInst); return FALSE; } BOOL IsOurs = IsOurHardwareID(Hwids); @@ -190,7 +203,7 @@ static _Return_type_success_(return != NULL) WCHAR *GetDeviceObjectFileName(_In_ ERROR_GEN_FAILURE); if (LastError != ERROR_SUCCESS) { - SetLastError(LOG_ERROR(L"Failed to query associated instances size", LastError)); + SetLastError(LOG_ERROR(LastError, L"Failed to query adapter %s associated instances size", InstanceId)); return NULL; } WCHAR *Interfaces = Alloc(InterfacesLen * sizeof(WCHAR)); @@ -206,7 +219,7 @@ static _Return_type_success_(return != NULL) WCHAR *GetDeviceObjectFileName(_In_ ERROR_GEN_FAILURE); if (LastError != ERROR_SUCCESS) { - LOG_ERROR(L"Failed to get associated instances", LastError); + LOG_ERROR(LastError, L"Failed to get adapter %s associated instances", InstanceId); Free(Interfaces); SetLastError(LastError); return NULL; @@ -227,9 +240,9 @@ static _Return_type_success_(return != INVALID_HANDLE_VALUE) HANDLE OpenDeviceOb OPEN_EXISTING, 0, NULL); - Free(Filename); if (Handle == INVALID_HANDLE_VALUE) - LOG_LAST_ERROR(L"Failed to connect to adapter"); + LOG_LAST_ERROR(L"Failed to connect to adapter %s associated instance %s", InstanceId, Filename); + Free(Filename); return Handle; } @@ -253,6 +266,7 @@ EnsureDeviceObject(_In_z_ const WCHAR *InstanceId) Sleep(50); } Exists = FALSE; + LOG_LAST_ERROR(L"Failed to connect to adapter %s associated instance %s", InstanceId, Filename); out: Free(Filename); return Exists; @@ -268,7 +282,7 @@ static _Return_type_success_(return != FALSE) BOOL if (SetupDiGetDeviceInstanceIdW(DevInfo, DevInfoData, NULL, 0, &RequiredBytes) || (LastError = GetLastError()) != ERROR_INSUFFICIENT_BUFFER) { - LOG_ERROR(L"Failed to query instance ID size", LastError); + LOG_ERROR(LastError, L"Failed to query adapter %u instance ID size", DevInfoData->DevInst); return FALSE; } WCHAR *InstanceId = Zalloc(sizeof(*InstanceId) * RequiredBytes); @@ -276,13 +290,13 @@ static _Return_type_success_(return != FALSE) BOOL return FALSE; if (!SetupDiGetDeviceInstanceIdW(DevInfo, DevInfoData, InstanceId, RequiredBytes, &RequiredBytes)) { - LastError = LOG_LAST_ERROR(L"Failed to get instance ID"); + LastError = LOG_LAST_ERROR(L"Failed to get adapter %u instance ID", DevInfoData->DevInst); goto cleanupInstanceId; } HANDLE NdisHandle = OpenDeviceObject(InstanceId); if (NdisHandle == INVALID_HANDLE_VALUE) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get adapter object"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get adapter %u object", DevInfoData->DevInst); goto cleanupInstanceId; } if (DeviceIoControl(NdisHandle, TUN_IOCTL_FORCE_CLOSE_HANDLES, NULL, 0, NULL, 0, &RequiredBytes, NULL)) @@ -293,7 +307,7 @@ static _Return_type_success_(return != FALSE) BOOL else if (GetLastError() == ERROR_NOTHING_TO_TERMINATE) LastError = ERROR_SUCCESS; else - LastError = LOG_LAST_ERROR(L"Failed to perform ioctl"); + LastError = LOG_LAST_ERROR(L"Failed to perform ioctl on adapter %u", DevInfoData->DevInst); CloseHandle(NdisHandle); cleanupInstanceId: Free(InstanceId); @@ -331,15 +345,15 @@ static _Return_type_success_(return != FALSE) BOOL ((Status & DN_HAS_PROBLEM) && ProblemCode == CM_PROB_DISABLED)) goto cleanupDeviceNode; - LOG(WINTUN_LOG_INFO, L"Force closing all open handles for existing adapter"); + LOG(WINTUN_LOG_INFO, L"Force closing all adapter %u open handles", DeviceNode->Data.DevInst); if (!ForceCloseWintunAdapterHandle(DevInfo, &DeviceNode->Data)) - LOG(WINTUN_LOG_WARN, L"Failed to force close adapter handles"); + LOG(WINTUN_LOG_WARN, L"Failed to force close adapter %u handles", DeviceNode->Data.DevInst); - LOG(WINTUN_LOG_INFO, L"Disabling existing adapter"); + LOG(WINTUN_LOG_INFO, L"Disabling adapter %u", DeviceNode->Data.DevInst); if (!SetupDiSetClassInstallParamsW(DevInfo, &DeviceNode->Data, &Params.ClassInstallHeader, sizeof(Params)) || !SetupDiCallClassInstaller(DIF_PROPERTYCHANGE, DevInfo, &DeviceNode->Data)) { - LOG_LAST_ERROR(L"Failed to disable existing adapter"); + LOG_LAST_ERROR(L"Failed to disable adapter %u", DeviceNode->Data.DevInst); LastError = LastError != ERROR_SUCCESS ? LastError : GetLastError(); goto cleanupDeviceNode; } @@ -364,11 +378,11 @@ static _Return_type_success_(return != FALSE) BOOL DWORD LastError = ERROR_SUCCESS; for (SP_DEVINFO_DATA_LIST *DeviceNode = AdaptersToEnable; DeviceNode; DeviceNode = DeviceNode->Next) { - LOG(WINTUN_LOG_INFO, L"Enabling existing adapter"); + LOG(WINTUN_LOG_INFO, L"Enabling adapter %u", DeviceNode->Data.DevInst); if (!SetupDiSetClassInstallParamsW(DevInfo, &DeviceNode->Data, &Params.ClassInstallHeader, sizeof(Params)) || !SetupDiCallClassInstaller(DIF_PROPERTYCHANGE, DevInfo, &DeviceNode->Data)) { - LOG_LAST_ERROR(L"Failed to enable existing adapter"); + LOG_LAST_ERROR(L"Failed to enable adapter %u", DeviceNode->Data.DevInst); LastError = LastError != ERROR_SUCCESS ? LastError : GetLastError(); } } @@ -401,7 +415,7 @@ CheckReboot(_In_ HDEVINFO DevInfo, _In_ SP_DEVINFO_DATA *DevInfoData) SP_DEVINSTALL_PARAMS_W DevInstallParams = { .cbSize = sizeof(SP_DEVINSTALL_PARAMS_W) }; if (!SetupDiGetDeviceInstallParamsW(DevInfo, DevInfoData, &DevInstallParams)) { - LOG_LAST_ERROR(L"Retrieving device installation parameters failed"); + LOG_LAST_ERROR(L"Retrieving adapter %u device installation parameters failed", DevInfoData->DevInst); return FALSE; } SetLastError(ERROR_SUCCESS); @@ -414,13 +428,13 @@ static _Return_type_success_(return != FALSE) BOOL SP_DEVINSTALL_PARAMS_W DevInstallParams = { .cbSize = sizeof(SP_DEVINSTALL_PARAMS_W) }; if (!SetupDiGetDeviceInstallParamsW(DevInfo, DevInfoData, &DevInstallParams)) { - LOG_LAST_ERROR(L"Retrieving device installation parameters failed"); + LOG_LAST_ERROR(L"Retrieving adapter %u device installation parameters failed", DevInfoData->DevInst); return FALSE; } DevInstallParams.Flags |= DI_QUIETINSTALL; if (!SetupDiSetDeviceInstallParamsW(DevInfo, DevInfoData, &DevInstallParams)) { - LOG_LAST_ERROR(L"Setting device installation parameters failed"); + LOG_LAST_ERROR(L"Setting adapter %u device installation parameters failed", DevInfoData->DevInst); return FALSE; } return TRUE; @@ -430,11 +444,17 @@ static _Return_type_success_(return != FALSE) BOOL GetNetCfgInstanceIdFromHKEY(_ { WCHAR *ValueStr = RegistryQueryString(Key, L"NetCfgInstanceId", TRUE); if (!ValueStr) - return RET_ERROR(TRUE, LOG(WINTUN_LOG_ERR, L"Failed to get NetCfgInstanceId")); + { + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + return RET_ERROR(TRUE, LOG(WINTUN_LOG_ERR, L"Failed to get %.*s\\NetCfgInstanceId", MAX_REG_PATH, RegPath)); + } DWORD LastError = ERROR_SUCCESS; if (FAILED(CLSIDFromString(ValueStr, CfgInstanceID))) { - LOG(WINTUN_LOG_ERR, L"NetCfgInstanceId is not a GUID"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG(WINTUN_LOG_ERR, L"%.*s\\NetCfgInstanceId is not a GUID: %s", MAX_REG_PATH, RegPath, ValueStr); LastError = ERROR_INVALID_DATA; } Free(ValueStr); @@ -447,7 +467,7 @@ static _Return_type_success_(return != FALSE) BOOL HKEY Key = SetupDiOpenDevRegKey(DevInfo, DevInfoData, DICS_FLAG_GLOBAL, 0, DIREG_DRV, KEY_QUERY_VALUE); if (Key == INVALID_HANDLE_VALUE) { - LOG_LAST_ERROR(L"Opening device registry key failed"); + LOG_LAST_ERROR(L"Opening adapter %u device registry key failed", DevInfoData->DevInst); return FALSE; } DWORD LastError = ERROR_SUCCESS; @@ -501,7 +521,7 @@ static _Return_type_success_(return != FALSE) BOOL { if (_snwprintf_s(Name, MAX_POOL_DEVICE_TYPE, _TRUNCATE, L"%s Tunnel", Pool) == -1) { - LOG(WINTUN_LOG_ERR, L"Pool name too long"); + LOG(WINTUN_LOG_ERR, L"Pool name too long: %s", Pool); SetLastError(ERROR_INVALID_PARAMETER); return FALSE; } @@ -553,7 +573,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER HKEY Key = SetupDiOpenDevRegKey(DevInfo, DevInfoData, DICS_FLAG_GLOBAL, 0, DIREG_DRV, KEY_QUERY_VALUE); if (Key == INVALID_HANDLE_VALUE) { - LOG_LAST_ERROR(L"Opening device registry key failed"); + LOG_LAST_ERROR(L"Opening adapter %u device registry key failed", DevInfoData->DevInst); return NULL; } @@ -573,13 +593,17 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER if (!RegistryQueryDWORD(Key, L"NetLuidIndex", &Adapter->LuidIndex, TRUE)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get NetLuidIndex"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get %.*s\\NetLuidIndex", MAX_REG_PATH, RegPath); goto cleanupAdapter; } if (!RegistryQueryDWORD(Key, L"*IfType", &Adapter->IfType, TRUE)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get *IfType"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get %.*s\\*IfType", MAX_REG_PATH, RegPath); goto cleanupAdapter; } @@ -587,13 +611,13 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER if (!SetupDiGetDeviceInstanceIdW( DevInfo, DevInfoData, Adapter->DevInstanceID, _countof(Adapter->DevInstanceID), &Size)) { - LastError = LOG_LAST_ERROR(L"Failed to get instance ID"); + LastError = LOG_LAST_ERROR(L"Failed to get adapter %u instance ID", DevInfoData->DevInst); goto cleanupAdapter; } if (wcsncpy_s(Adapter->Pool, _countof(Adapter->Pool), Pool, _TRUNCATE) == STRUNCATE) { - LOG(WINTUN_LOG_ERR, L"Pool name too long"); + LOG(WINTUN_LOG_ERR, L"Pool name too long: %s", Pool); LastError = ERROR_INVALID_PARAMETER; goto cleanupAdapter; } @@ -619,7 +643,7 @@ static _Return_type_success_(return != FALSE) BOOL MAX_INSTANCE_ID, Adapter->DevInstanceID) == -1) { - LOG(WINTUN_LOG_ERR, L"Registry path too long"); + LOG(WINTUN_LOG_ERR, L"Registry path too long: %.*s", MAX_INSTANCE_ID, Adapter->DevInstanceID); SetLastError(ERROR_INVALID_PARAMETER); return FALSE; } @@ -645,7 +669,7 @@ _Return_type_success_(return != NULL) WINTUN_ADAPTER *WINAPI HANDLE Mutex = NamespaceTakePoolMutex(Pool); if (!Mutex) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to take pool mutex"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to take %s pool mutex", Pool); goto cleanupToken; } @@ -685,7 +709,7 @@ _Return_type_success_(return != NULL) WINTUN_ADAPTER *WINAPI /* Check the Hardware ID to make sure it's a real Wintun device. */ if (!IsOurAdapter(DevInfo, &DevInfoData)) { - LOG(WINTUN_LOG_ERR, L"Foreign adapter with the same name exists"); + LOG(WINTUN_LOG_ERR, L"Foreign adapter %u named %s exists", DevInfoData.DevInst, Name); LastError = ERROR_ALREADY_EXISTS; goto cleanupDevInfo; } @@ -694,13 +718,13 @@ _Return_type_success_(return != NULL) WINTUN_ADAPTER *WINAPI { if ((LastError = GetLastError()) == ERROR_SUCCESS) { - LOG(WINTUN_LOG_ERR, L"Wintun adapter with the same name exists in another pool"); + LOG(WINTUN_LOG_ERR, L"Adapter %u named %s is not a member of %s pool", DevInfoData.DevInst, Name, Pool); LastError = ERROR_ALREADY_EXISTS; goto cleanupDevInfo; } else { - LOG(WINTUN_LOG_ERR, L"Failed to get pool membership"); + LOG(WINTUN_LOG_ERR, L"Failed to get adapter %u pool membership", DevInfoData.DevInst); goto cleanupDevInfo; } } @@ -708,13 +732,13 @@ _Return_type_success_(return != NULL) WINTUN_ADAPTER *WINAPI Adapter = CreateAdapterData(Pool, DevInfo, &DevInfoData); if (!Adapter) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to create adapter data"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to create adapter %u data", DevInfoData.DevInst); goto cleanupDevInfo; } if (!EnsureDeviceObject(Adapter->DevInstanceID)) { - LastError = LOG_LAST_ERROR(L"Device object file did not appear"); + LastError = GetLastError(); goto cleanupDevInfo; } @@ -738,7 +762,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI DWORD LastError = NciGetConnectionName(&Adapter->CfgInstanceID, Name, MAX_ADAPTER_NAME * sizeof(WCHAR), NULL); if (LastError != ERROR_SUCCESS) { - SetLastError(LOG_ERROR(L"Failed to get name", LastError)); + SetLastError(LOG_ERROR(LastError, L"Failed to get name")); return FALSE; } return TRUE; @@ -751,13 +775,13 @@ static _Return_type_success_(return != FALSE) BOOL DWORD LastError = ConvertInterfaceAliasToLuid(Name, &Luid); if (LastError != NO_ERROR) { - SetLastError(LOG_ERROR(L"Failed convert interface alias name to the locally unique identifier", LastError)); + SetLastError(LOG_ERROR(LastError, L"Failed convert interface %s name to the locally unique identifier", Name)); return FALSE; } LastError = ConvertInterfaceLuidToGuid(&Luid, Guid); if (LastError != NO_ERROR) { - SetLastError(LOG_ERROR(L"Failed convert interface locally to globally unique identifier", LastError)); + SetLastError(LOG_ERROR(LastError, L"Failed to convert interface %s LUID (%I64u) to GUID", Name, Luid.Value)); return FALSE; } return TRUE; @@ -771,7 +795,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI WCHAR AvailableName[MAX_ADAPTER_NAME]; if (wcsncpy_s(AvailableName, _countof(AvailableName), Name, _TRUNCATE) == STRUNCATE) { - LOG(WINTUN_LOG_ERR, L"Adapter name too long"); + LOG(WINTUN_LOG_ERR, L"Adapter name too long: %s", Name); SetLastError(ERROR_INVALID_PARAMETER); return FALSE; } @@ -788,7 +812,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI WCHAR Proposal[MAX_ADAPTER_NAME]; if (_snwprintf_s(Proposal, _countof(Proposal), _TRUNCATE, L"%s %d", Name, j + 1) == -1) { - LOG(WINTUN_LOG_ERR, L"Adapter name too long"); + LOG(WINTUN_LOG_ERR, L"Adapter name too long: %s %d", Name, j + 1); SetLastError(ERROR_INVALID_PARAMETER); return FALSE; } @@ -811,12 +835,12 @@ _Return_type_success_(return != FALSE) BOOL WINAPI break; if (i >= MaxSuffix || LastError != ERROR_DUP_NAME) { - SetLastError(LOG_ERROR(L"Setting adapter name failed", LastError)); + SetLastError(LOG_ERROR(LastError, L"Setting adapter name failed")); return FALSE; } if (_snwprintf_s(AvailableName, _countof(AvailableName), _TRUNCATE, L"%s %d", Name, i + 1) == -1) { - LOG(WINTUN_LOG_ERR, L"Adapter name too long"); + LOG(WINTUN_LOG_ERR, L"Adapter name too long: %s %d", Name, i + 1); SetLastError(ERROR_INVALID_PARAMETER); return FALSE; } @@ -830,7 +854,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI LastError = RegOpenKeyExW(HKEY_LOCAL_MACHINE, DeviceRegPath, 0, KEY_SET_VALUE, &DeviceRegKey); if (LastError != ERROR_SUCCESS) { - SetLastError(LOG_ERROR(L"Failed to open registry key", LastError)); + SetLastError(LOG_ERROR(LastError, L"Failed to open registry key %s", DeviceRegPath)); return FALSE; } WCHAR PoolDeviceTypeName[MAX_POOL_DEVICE_TYPE]; @@ -847,7 +871,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI PoolDeviceTypeName, (DWORD)((wcslen(PoolDeviceTypeName) + 1) * sizeof(WCHAR))); if (LastError != ERROR_SUCCESS) - LOG_ERROR(L"Failed to set FriendlyName", LastError); + LOG_ERROR(LastError, L"Failed to set %s\\FriendlyName", DeviceRegPath); cleanupDeviceRegKey: RegCloseKey(DeviceRegKey); return RET_ERROR(TRUE, LastError); @@ -886,7 +910,7 @@ static _Return_type_success_(return != FALSE) BOOL InstallCertificate(_In_z_ con const void *LockedResource = ResourceGetAddress(SignedResource, &SizeResource); if (!LockedResource) { - LOG(WINTUN_LOG_ERR, L"Failed to locate resource"); + LOG(WINTUN_LOG_ERR, L"Failed to locate resource %s", SignedResource); return FALSE; } const CERT_BLOB CertBlob = { .cbData = SizeResource, .pbData = (BYTE *)LockedResource }; @@ -1017,24 +1041,24 @@ static _Return_type_success_(return != FALSE) BOOL DWORD LastError = RegOpenKeyExW(HKEY_LOCAL_MACHINE, TcpipAdapterRegPath, 0, KEY_QUERY_VALUE, &TcpipAdapterRegKey); if (LastError != ERROR_SUCCESS) { - SetLastError(LOG_ERROR(L"Failed to open registry key", LastError)); + SetLastError(LOG_ERROR(LastError, L"Failed to open registry key %s", TcpipAdapterRegPath)); return FALSE; } WCHAR *Paths = RegistryQueryString(TcpipAdapterRegKey, L"IpConfig", TRUE); if (!Paths) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get IpConfig"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get %s\\IpConfig", TcpipAdapterRegPath); goto cleanupTcpipAdapterRegKey; } if (!Paths[0]) { - LOG(WINTUN_LOG_ERR, L"IpConfig is empty"); + LOG(WINTUN_LOG_ERR, L"%s\\IpConfig is empty", TcpipAdapterRegPath); LastError = ERROR_INVALID_DATA; goto cleanupPaths; } if (_snwprintf_s(Path, MAX_REG_PATH, _TRUNCATE, L"SYSTEM\\CurrentControlSet\\Services\\%s", Paths) == -1) { - LOG(WINTUN_LOG_ERR, L"Registry path too long"); + LOG(WINTUN_LOG_ERR, L"Registry path too long: %s", Paths); LastError = ERROR_INVALID_PARAMETER; goto cleanupPaths; } @@ -1051,7 +1075,7 @@ static _Return_type_success_(return != 0) DWORD VersionOfFile(_In_z_ const WCHAR DWORD Len = GetFileVersionInfoSizeW(Filename, &Zero); if (!Len) { - LOG_LAST_ERROR(L"Failed to query version info size"); + LOG_LAST_ERROR(L"Failed to query %s version info size", Filename); return 0; } VOID *VersionInfo = Alloc(Len); @@ -1062,18 +1086,18 @@ static _Return_type_success_(return != 0) DWORD VersionOfFile(_In_z_ const WCHAR UINT FixedInfoLen = sizeof(*FixedInfo); if (!GetFileVersionInfoW(Filename, 0, Len, VersionInfo)) { - LastError = LOG_LAST_ERROR(L"Failed to get version info"); + LastError = LOG_LAST_ERROR(L"Failed to get %s version info", Filename); goto out; } if (!VerQueryValueW(VersionInfo, L"\\", &FixedInfo, &FixedInfoLen)) { - LastError = LOG_LAST_ERROR(L"Failed to get version info root"); + LastError = LOG_LAST_ERROR(L"Failed to get %s version info root", Filename); goto out; } Version = FixedInfo->dwFileVersionMS; if (!Version) { - LOG(WINTUN_LOG_WARN, L"Determined version of file, but was v0.0, so returning failure"); + LOG(WINTUN_LOG_WARN, L"Determined version of %s, but was v0.0, so returning failure", Filename); LastError = ERROR_VERSION_PARSE_ERROR; } out: @@ -1114,7 +1138,7 @@ static _Return_type_success_(return != FALSE) BOOL } if (!CreateDirectoryW(RandomTempSubDirectory, &SecurityAttributes)) { - LOG_LAST_ERROR(L"Failed to create temporary folder"); + LOG_LAST_ERROR(L"Failed to create temporary folder %s", RandomTempSubDirectory); return FALSE; } return TRUE; @@ -1136,7 +1160,7 @@ MaybeGetRunningDriverVersion(BOOL ReturnOneIfRunningInsteadOfVersion) Free(Modules); if (Status == STATUS_INFO_LENGTH_MISMATCH) continue; - LOG(WINTUN_LOG_ERR, L"Failed to enumerate drivers"); + LOG(WINTUN_LOG_ERR, L"Failed to enumerate drivers (status: 0x%x)", Status); SetLastError(RtlNtStatusToDosError(Status)); return 0; } @@ -1197,7 +1221,7 @@ static _Return_type_success_(return != FALSE) BOOL SelectDriver( DWORD LastError; if (!SetupDiBuildDriverInfoList(DevInfo, DevInfoData, SPDIT_COMPATDRIVER)) { - LastError = LOG_LAST_ERROR(L"Failed building driver info list"); + LastError = LOG_LAST_ERROR(L"Failed building adapter %u driver info list", DevInfoData->DevInst); goto cleanupDriverInstallationLock; } BOOL DestroyDriverInfoListOnCleanup = TRUE; @@ -1217,7 +1241,7 @@ static _Return_type_success_(return != FALSE) BOOL SelectDriver( SP_DRVINFO_DETAIL_DATA_W *DrvInfoDetailData = GetAdapterDrvInfoDetail(DevInfo, DevInfoData, &DrvInfoData); if (!DrvInfoDetailData) { - LOG(WINTUN_LOG_WARN, L"Failed getting driver info detail"); + LOG(WINTUN_LOG_WARN, L"Failed getting adapter %u driver info detail", DevInfoData->DevInst); continue; } if (!IsOurDrvInfoDetail(DrvInfoDetailData)) @@ -1241,16 +1265,21 @@ static _Return_type_success_(return != FALSE) BOOL SelectDriver( LOG(WINTUN_LOG_WARN, L"Failed to unload existing driver, which means a reboot will likely be required"); } - LOG(WINTUN_LOG_INFO, L"Removing existing driver"); - if (!SetupUninstallOEMInfW(PathFindFileNameW(DrvInfoDetailData->InfFileName), SUOI_FORCEDELETE, NULL)) - LOG_LAST_ERROR(L"Unable to remove existing driver"); + LOG(WINTUN_LOG_INFO, + L"Removing existing driver %u.%u", + (DWORD)((DrvInfoData.DriverVersion & 0xffff000000000000) >> 48), + (DWORD)((DrvInfoData.DriverVersion & 0x0000ffff00000000) >> 32)); + LPWSTR InfFileName = PathFindFileNameW(DrvInfoDetailData->InfFileName); + if (!SetupUninstallOEMInfW(InfFileName, SUOI_FORCEDELETE, NULL)) + LOG_LAST_ERROR(L"Unable to remove existing driver %s", InfFileName); goto next; } if (!IsNewer(&DrvInfoData.DriverDate, DrvInfoData.DriverVersion, &DriverDate, DriverVersion)) goto next; if (!SetupDiSetSelectedDriverW(DevInfo, DevInfoData, &DrvInfoData)) { - LOG_LAST_ERROR(L"Failed to select driver"); + LOG_LAST_ERROR( + L"Failed to select driver %s for adapter %u", DrvInfoDetailData->InfFileName, DevInfoData->DevInst); goto next; } DriverDate = DrvInfoData.DriverDate; @@ -1261,15 +1290,23 @@ static _Return_type_success_(return != FALSE) BOOL SelectDriver( if (DriverVersion) { + LOG(WINTUN_LOG_INFO, + L"Using existing driver %u.%u", + (DWORD)((DriverVersion & 0xffff000000000000) >> 48), + (DWORD)((DriverVersion & 0x0000ffff00000000) >> 32)); LastError = ERROR_SUCCESS; DestroyDriverInfoListOnCleanup = FALSE; goto cleanupExistingAdapters; } + LOG(WINTUN_LOG_INFO, + L"Installing driver %u.%u", + (DWORD)((OurDriverVersion & 0xffff000000000000) >> 48), + (DWORD)((OurDriverVersion & 0x0000ffff00000000) >> 32)); WCHAR RandomTempSubDirectory[MAX_PATH]; if (!CreateTemporaryDirectory(RandomTempSubDirectory)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to create temporary folder"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to create temporary folder %s", RandomTempSubDirectory); goto cleanupExistingAdapters; } @@ -1300,7 +1337,7 @@ static _Return_type_success_(return != FALSE) BOOL SelectDriver( WCHAR InfStorePath[MAX_PATH]; if (!SetupCopyOEMInfW(InfPath, NULL, SPOST_NONE, 0, InfStorePath, MAX_PATH, NULL, NULL)) { - LastError = LOG_LAST_ERROR(L"Could not install driver to store"); + LastError = LOG_LAST_ERROR(L"Could not install driver %s to store", InfPath); goto cleanupDelete; } _Analysis_assume_nullterminated_(InfStorePath); @@ -1311,30 +1348,30 @@ static _Return_type_success_(return != FALSE) BOOL SelectDriver( if (wcsncpy_s(DevInstallParams->DriverPath, _countof(DevInstallParams->DriverPath), InfStorePath, _TRUNCATE) == STRUNCATE) { - LOG(WINTUN_LOG_ERR, L"Inf path too long"); + LOG(WINTUN_LOG_ERR, L"Inf path too long: %s", InfStorePath); LastError = ERROR_INVALID_PARAMETER; goto cleanupDelete; } if (!SetupDiSetDeviceInstallParamsW(DevInfo, DevInfoData, DevInstallParams)) { - LastError = LOG_LAST_ERROR(L"Setting device installation parameters failed"); + LastError = LOG_LAST_ERROR(L"Setting adapter %u device installation parameters failed", DevInfoData->DevInst); goto cleanupDelete; } if (!SetupDiBuildDriverInfoList(DevInfo, DevInfoData, SPDIT_COMPATDRIVER)) { - LastError = LOG_LAST_ERROR(L"Failed rebuilding driver info list"); + LastError = LOG_LAST_ERROR(L"Failed rebuilding adapter %u driver info list", DevInfoData->DevInst); goto cleanupDelete; } DestroyDriverInfoListOnCleanup = TRUE; SP_DRVINFO_DATA_W DrvInfoData = { .cbSize = sizeof(SP_DRVINFO_DATA_W) }; if (!SetupDiEnumDriverInfoW(DevInfo, DevInfoData, SPDIT_COMPATDRIVER, 0, &DrvInfoData)) { - LastError = LOG_LAST_ERROR(L"Failed to get driver"); + LastError = LOG_LAST_ERROR(L"Failed to get adapter %u driver", DevInfoData->DevInst); goto cleanupDelete; } if (!SetupDiSetSelectedDriverW(DevInfo, DevInfoData, &DrvInfoData)) { - LastError = LOG_LAST_ERROR(L"Failed to set driver"); + LastError = LOG_LAST_ERROR(L"Failed to set adapter %u driver", DevInfoData->DevInst); goto cleanupDelete; } LastError = ERROR_SUCCESS; @@ -1405,47 +1442,47 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( SP_DEVINSTALL_PARAMS_W DevInstallParams = { .cbSize = sizeof(SP_DEVINSTALL_PARAMS_W) }; if (!SetupDiGetDeviceInstallParamsW(DevInfo, &DevInfoData, &DevInstallParams)) { - LastError = LOG_LAST_ERROR(L"Retrieving device installation parameters failed"); + LastError = LOG_LAST_ERROR(L"Retrieving adapter %u device installation parameters failed", DevInfoData.DevInst); goto cleanupDevInfo; } DevInstallParams.Flags |= DI_QUIETINSTALL; if (!SetupDiSetDeviceInstallParamsW(DevInfo, &DevInfoData, &DevInstallParams)) { - LastError = LOG_LAST_ERROR(L"Setting device installation parameters failed"); + LastError = LOG_LAST_ERROR(L"Setting adapter %u device installation parameters failed", DevInfoData.DevInst); goto cleanupDevInfo; } if (!SetupDiSetSelectedDevice(DevInfo, &DevInfoData)) { - LastError = LOG_LAST_ERROR(L"Failed selecting device"); + LastError = LOG_LAST_ERROR(L"Failed selecting adapter %u device", DevInfoData.DevInst); goto cleanupDevInfo; } static const WCHAR Hwids[_countof(WINTUN_HWID) + 1 /*Multi-string terminator*/] = WINTUN_HWID; if (!SetupDiSetDeviceRegistryPropertyW(DevInfo, &DevInfoData, SPDRP_HARDWAREID, (const BYTE *)Hwids, sizeof(Hwids))) { - LastError = LOG_LAST_ERROR(L"Failed setting hardware ID"); + LastError = LOG_LAST_ERROR(L"Failed setting adapter %u hardware ID", DevInfoData.DevInst); goto cleanupDevInfo; } if (!SelectDriver(DevInfo, &DevInfoData, &DevInstallParams)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to select driver"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to select adapter %u driver", DevInfoData.DevInst); goto cleanupDevInfo; } HANDLE Mutex = NamespaceTakePoolMutex(Pool); if (!Mutex) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to take pool mutex"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to take %s pool mutex", Pool); goto cleanupDriverInfoList; } if (!SetupDiCallClassInstaller(DIF_REGISTERDEVICE, DevInfo, &DevInfoData)) { - LastError = LOG_LAST_ERROR(L"Registering device failed"); + LastError = LOG_LAST_ERROR(L"Registering adapter %u device failed", DevInfoData.DevInst); goto cleanupDevice; } if (!SetupDiCallClassInstaller(DIF_REGISTER_COINSTALLERS, DevInfo, &DevInfoData)) - LOG_LAST_ERROR(L"Registering coinstallers failed"); + LOG_LAST_ERROR(L"Registering adapter %u coinstallers failed", DevInfoData.DevInst); HKEY NetDevRegKey = INVALID_HANDLE_VALUE; const int PollTimeout = 50 /* ms */; @@ -1458,7 +1495,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( } if (NetDevRegKey == INVALID_HANDLE_VALUE) { - LastError = LOG_LAST_ERROR(L"Failed to open device-specific registry key"); + LastError = LOG_LAST_ERROR(L"Failed to open adapter %u device-specific registry key", DevInfoData.DevInst); goto cleanupDevice; } if (RequestedGUID) @@ -1473,17 +1510,19 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( StringFromGUID2(RequestedGUID, RequestedGUIDStr, _countof(RequestedGUIDStr)) * sizeof(WCHAR)); if (LastError != ERROR_SUCCESS) { - LOG_ERROR(L"Failed to set NetSetupAnticipatedInstanceId", LastError); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(NetDevRegKey, RegPath); + LOG_ERROR(LastError, L"Failed to set %.*s\\NetSetupAnticipatedInstanceId", MAX_REG_PATH, RegPath); goto cleanupNetDevRegKey; } } if (!SetupDiCallClassInstaller(DIF_INSTALLINTERFACES, DevInfo, &DevInfoData)) - LOG_LAST_ERROR(L"Installing interfaces failed"); + LOG_LAST_ERROR(L"Installing adapter %u interfaces failed", DevInfoData.DevInst); if (!SetupDiCallClassInstaller(DIF_INSTALLDEVICE, DevInfo, &DevInfoData)) { - LastError = LOG_LAST_ERROR(L"Installing device failed"); + LastError = LOG_LAST_ERROR(L"Installing adapter %u device failed", DevInfoData.DevInst); goto cleanupNetDevRegKey; } *RebootRequired = *RebootRequired || CheckReboot(DevInfo, &DevInfoData); @@ -1498,7 +1537,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( (DWORD)((wcslen(Pool) + 1) * sizeof(WCHAR)), 0)) { - LastError = LOG_LAST_ERROR(L"Failed to set adapter pool"); + LastError = LOG_LAST_ERROR(L"Failed to set adapter %u pool", DevInfoData.DevInst); goto cleanupNetDevRegKey; } if (!SetupDiSetDeviceRegistryPropertyW( @@ -1508,7 +1547,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( (const BYTE *)PoolDeviceTypeName, (DWORD)((wcslen(PoolDeviceTypeName) + 1) * sizeof(WCHAR)))) { - LastError = LOG_LAST_ERROR(L"Failed to set adapter description"); + LastError = LOG_LAST_ERROR(L"Failed to set adapter %u description", DevInfoData.DevInst); goto cleanupNetDevRegKey; } @@ -1517,26 +1556,32 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( WCHAR *DummyStr = RegistryQueryStringWait(NetDevRegKey, L"NetCfgInstanceId", WAIT_FOR_REGISTRY_TIMEOUT); if (!DummyStr) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get NetCfgInstanceId"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(NetDevRegKey, RegPath); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get %.*s\\NetCfgInstanceId", MAX_REG_PATH, RegPath); goto cleanupNetDevRegKey; } Free(DummyStr); DWORD DummyDWORD; if (!RegistryQueryDWORDWait(NetDevRegKey, L"NetLuidIndex", WAIT_FOR_REGISTRY_TIMEOUT, &DummyDWORD)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get NetLuidIndex"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(NetDevRegKey, RegPath); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get %.*s\\NetLuidIndex", MAX_REG_PATH, RegPath); goto cleanupNetDevRegKey; } if (!RegistryQueryDWORDWait(NetDevRegKey, L"*IfType", WAIT_FOR_REGISTRY_TIMEOUT, &DummyDWORD)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get *IfType"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(NetDevRegKey, RegPath); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get %.*s\\*IfType", MAX_REG_PATH, RegPath); goto cleanupNetDevRegKey; } Adapter = CreateAdapterData(Pool, DevInfo, &DevInfoData); if (!Adapter) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to create adapter data"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to create adapter %u data", DevInfoData.DevInst); goto cleanupNetDevRegKey; } @@ -1551,13 +1596,14 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( HKEY_LOCAL_MACHINE, TcpipAdapterRegPath, KEY_QUERY_VALUE | KEY_NOTIFY, WAIT_FOR_REGISTRY_TIMEOUT); if (!TcpipAdapterRegKey) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to open adapter-specific TCP/IP interface registry key"); + LastError = LOG( + WINTUN_LOG_ERR, L"Failed to open adapter-specific TCP/IP interface registry key %s", TcpipAdapterRegPath); goto cleanupAdapter; } DummyStr = RegistryQueryStringWait(TcpipAdapterRegKey, L"IpConfig", WAIT_FOR_REGISTRY_TIMEOUT); if (!DummyStr) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to get IpConfig"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to get %s\\IpConfig", TcpipAdapterRegPath); goto cleanupTcpipAdapterRegKey; } Free(DummyStr); @@ -1574,7 +1620,10 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( HKEY_LOCAL_MACHINE, TcpipInterfaceRegPath, KEY_QUERY_VALUE | KEY_SET_VALUE, WAIT_FOR_REGISTRY_TIMEOUT); if (!TcpipInterfaceRegKey) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to open interface-specific TCP/IP network registry key"); + LastError = + LOG(WINTUN_LOG_ERR, + L"Failed to open interface-specific TCP/IP network registry key %s", + TcpipInterfaceRegPath); goto cleanupTcpipAdapterRegKey; } @@ -1591,7 +1640,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( break; if (LastError != ERROR_TRANSACTION_NOT_ACTIVE) { - LOG_ERROR(L"Failed to set EnableDeadGWDetect", LastError); + LOG_ERROR(LastError, L"Failed to set %s\\EnableDeadGWDetect", TcpipInterfaceRegPath); goto cleanupTcpipAdapterRegKey; } Sleep(10); @@ -1599,7 +1648,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( if (!WintunSetAdapterName(Adapter, Name)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to set adapter name"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to set adapter name %s", Name); goto cleanupTcpipAdapterRegKey; } @@ -1622,7 +1671,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapter( _Analysis_assume_(LastError != ERROR_SUCCESS); if (ProblemStatus != STATUS_PNP_DEVICE_CONFIGURATION_PENDING || Tries == 999) { - LOG_ERROR(L"Failed to setup adapter", LastError); + LOG_ERROR(LastError, L"Failed to setup adapter (status: 0x%x)", ProblemStatus); goto cleanupTcpipAdapterRegKey; } Sleep(10); @@ -1673,7 +1722,7 @@ static _Return_type_success_(return != NULL) HANDLE Mutex = NamespaceTakePoolMutex(Pool); if (!Mutex) { - LOG(WINTUN_LOG_ERR, L"Failed to take pool mutex"); + LOG(WINTUN_LOG_ERR, L"Failed to take %s pool mutex", Pool); return NULL; } DWORD LastError; @@ -1682,11 +1731,16 @@ static _Return_type_success_(return != NULL) SP_DEVINFO_DATA DevInfoData; if (!GetDevInfoData(CfgInstanceID, &DevInfo, &DevInfoData)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to locate adapter"); + WCHAR Guid[MAX_GUID_STRING_LEN]; + LastError = + LOG(WINTUN_LOG_ERR, + L"Failed to locate adapter %.*s", + StringFromGUID2(CfgInstanceID, Guid, _countof(Guid)), + Guid); goto cleanupMutex; } Adapter = CreateAdapterData(Pool, DevInfo, &DevInfoData); - LastError = Adapter ? ERROR_SUCCESS : LOG(WINTUN_LOG_ERR, L"Failed to create adapter data"); + LastError = Adapter ? ERROR_SUCCESS : LOG(WINTUN_LOG_ERR, L"Failed to create adapter %u data", DevInfoData.DevInst); SetupDiDestroyDeviceInfoList(DevInfo); cleanupMutex: NamespaceReleaseMutex(Mutex); @@ -1750,7 +1804,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI WintunDeleteAdapter( HANDLE Mutex = NamespaceTakePoolMutex(Adapter->Pool); if (!Mutex) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to take pool mutex"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to take %s pool mutex", Adapter->Pool); goto cleanupToken; } @@ -1761,12 +1815,18 @@ _Return_type_success_(return != FALSE) BOOL WINAPI WintunDeleteAdapter( if ((LastError = GetLastError()) == ERROR_FILE_NOT_FOUND) LastError = ERROR_SUCCESS; else - LOG(WINTUN_LOG_ERR, L"Failed to get adapter info data"); + { + WCHAR Guid[MAX_GUID_STRING_LEN]; + LOG(WINTUN_LOG_ERR, + L"Failed to get adapter %.*s info data", + StringFromGUID2(&Adapter->CfgInstanceID, Guid, _countof(Guid)), + Guid); + } goto cleanupMutex; } if (ForceCloseSessions && !ForceCloseWintunAdapterHandle(DevInfo, &DevInfoData)) - LOG(WINTUN_LOG_WARN, L"Failed to force close adapter handles"); + LOG(WINTUN_LOG_WARN, L"Failed to force close adapter %u handles", DevInfoData.DevInst); SetQuietInstall(DevInfo, &DevInfoData); SP_REMOVEDEVICE_PARAMS Params = { .ClassInstallHeader = { .cbSize = sizeof(SP_CLASSINSTALL_HEADER), @@ -1776,7 +1836,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI WintunDeleteAdapter( !SetupDiCallClassInstaller(DIF_REMOVE, DevInfo, &DevInfoData)) && GetLastError() != ERROR_NO_SUCH_DEVINST) { - LastError = LOG_LAST_ERROR(L"Failed to remove existing adapter"); + LastError = LOG_LAST_ERROR(L"Failed to remove adapter %u", DevInfoData.DevInst); goto cleanupDevInfo; } LastError = ERROR_SUCCESS; @@ -1796,7 +1856,7 @@ static _Return_type_success_(return != FALSE) BOOL HANDLE Mutex = NamespaceTakePoolMutex(Pool); if (!Mutex) { - LOG(WINTUN_LOG_ERR, L"Failed to take pool mutex"); + LOG(WINTUN_LOG_ERR, L"Failed to take %s pool mutex", Pool); return FALSE; } DWORD LastError = ERROR_SUCCESS; @@ -1822,16 +1882,16 @@ static _Return_type_success_(return != FALSE) BOOL if (!IsOurAdapter(DevInfo, &DevInfoData) || !IsPoolMember(Pool, DevInfo, &DevInfoData)) continue; - LOG(WINTUN_LOG_INFO, L"Force closing all open handles for existing adapter"); + LOG(WINTUN_LOG_INFO, L"Force closing all adapter %u open handles", DevInfoData.DevInst); if (!ForceCloseWintunAdapterHandle(DevInfo, &DevInfoData)) - LOG(WINTUN_LOG_WARN, L"Failed to force close adapter handles"); + LOG(WINTUN_LOG_WARN, L"Failed to force close adapter %u handles", DevInfoData.DevInst); - LOG(WINTUN_LOG_INFO, L"Removing existing adapter"); + LOG(WINTUN_LOG_INFO, L"Removing adapter %u", DevInfoData.DevInst); if ((!SetupDiSetClassInstallParamsW(DevInfo, &DevInfoData, &Params.ClassInstallHeader, sizeof(Params)) || !SetupDiCallClassInstaller(DIF_REMOVE, DevInfo, &DevInfoData)) && GetLastError() != ERROR_NO_SUCH_DEVINST) { - LOG_LAST_ERROR(L"Failed to remove existing adapter"); + LOG_LAST_ERROR(L"Failed to remove adapter %u", DevInfoData.DevInst); LastError = LastError != ERROR_SUCCESS ? LastError : GetLastError(); } *RebootRequired = *RebootRequired || CheckReboot(DevInfo, &DevInfoData); @@ -1900,10 +1960,11 @@ _Return_type_success_(return != FALSE) BOOL WINAPI continue; if (!_wcsicmp(DriverDetail->HardwareID, WINTUN_HWID)) { - LOG(WINTUN_LOG_INFO, L"Removing existing driver"); - if (!SetupUninstallOEMInfW(PathFindFileNameW(DriverDetail->InfFileName), 0, NULL)) + LPCWSTR Path = PathFindFileNameW(DriverDetail->InfFileName); + LOG(WINTUN_LOG_INFO, L"Removing driver %s", Path); + if (!SetupUninstallOEMInfW(Path, 0, NULL)) { - LOG_LAST_ERROR(L"Unable to remove existing driver"); + LOG_LAST_ERROR(L"Unable to remove driver %s", Path); LastError = LastError != ERROR_SUCCESS ? LastError : GetLastError(); } } @@ -1925,7 +1986,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI HANDLE Mutex = NamespaceTakePoolMutex(Pool); if (!Mutex) { - LOG(WINTUN_LOG_ERR, L"Failed to take pool mutex"); + LOG(WINTUN_LOG_ERR, L"Failed to take %s pool mutex", Pool); return FALSE; } DWORD LastError = ERROR_SUCCESS; @@ -1952,7 +2013,7 @@ _Return_type_success_(return != FALSE) BOOL WINAPI WINTUN_ADAPTER *Adapter = CreateAdapterData(Pool, DevInfo, &DevInfoData); if (!Adapter) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to create adapter data"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to create adapter %u data", DevInfoData.DevInst); break; } Continue = Func(Adapter, Param); diff --git a/api/elevate.c b/api/elevate.c index c4474b0..c06dba7 100644 --- 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 index 0ebdd6e..7907437 100644 --- a/api/logger.c +++ b/api/logger.c @@ -4,7 +4,9 @@ */ #include "logger.h" +#include "ntdll.h" #include +#include #include static BOOL CALLBACK @@ -25,6 +27,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 +42,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 +52,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 +97,43 @@ 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""); + goto out; + } + if (_snwprintf_s(Path, MAX_REG_PATH, _TRUNCATE, L"0x%p", Key) == -1) + StrTruncate(Path, MAX_REG_PATH); + union + { + KEY_NAME_INFORMATION KeyNameInfo; + WCHAR Data[offsetof(KEY_NAME_INFORMATION, Name) + MAX_REG_PATH]; + } Buffer; + DWORD Size; + if (!NT_SUCCESS(NtQueryKey(Key, 3, &Buffer, sizeof(Buffer), &Size)) || + Size < offsetof(KEY_NAME_INFORMATION, Name) || Buffer.KeyNameInfo.NameLength >= MAX_REG_PATH * sizeof(WCHAR)) + goto out; + Buffer.KeyNameInfo.NameLength /= sizeof(WCHAR); + wmemcpy_s(Path, MAX_REG_PATH, Buffer.KeyNameInfo.Name, Buffer.KeyNameInfo.NameLength); + Path[Buffer.KeyNameInfo.NameLength] = L'\0'; +out: + SetLastError(LastError); +} diff --git a/api/logger.h b/api/logger.h index d0848a9..3ffda6e 100644 --- a/api/logger.h +++ b/api/logger.h @@ -7,7 +7,10 @@ #include "wintun.h" #include "entry.h" +#include "registry.h" #include +#include +#include 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 index 51fdb9d..34ade2c 100644 --- 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,10 +159,11 @@ _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: @@ -170,7 +171,7 @@ _Return_type_success_(return != NULL) HANDLE NamespaceTakePoolMutex(_In_z_ const 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; diff --git a/api/ntdll.h b/api/ntdll.h index e78a8b2..93b32a6 100644 --- a/api/ntdll.h +++ b/api/ntdll.h @@ -32,6 +32,12 @@ typedef struct _RTL_PROCESS_MODULES RTL_PROCESS_MODULE_INFORMATION Modules[1]; } RTL_PROCESS_MODULES, *PRTL_PROCESS_MODULES; +typedef struct _KEY_NAME_INFORMATION +{ + ULONG NameLength; + WCHAR Name[1]; +} KEY_NAME_INFORMATION, *PKEY_NAME_INFORMATION; + #define STATUS_INFO_LENGTH_MISMATCH ((NTSTATUS)0xC0000004L) // TODO: #include instead of this #define STATUS_PNP_DEVICE_CONFIGURATION_PENDING ((NTSTATUS)0xC0000495L) @@ -46,3 +52,12 @@ typedef struct _RTL_PROCESS_MODULES EXTERN_C DECLSPEC_IMPORT VOID NTAPI RtlGetNtVersionNumbers(_Out_opt_ DWORD *MajorVersion, _Out_opt_ DWORD *MinorVersion, _Out_opt_ DWORD *BuildNumber); + +EXTERN_C +DECLSPEC_IMPORT DWORD NTAPI +NtQueryKey( + _In_ HANDLE KeyHandle, + _In_ int KeyInformationClass, + _Out_bytecap_post_bytecount_(Length, *ResultLength) PVOID KeyInformation, + _In_ ULONG Length, + _Out_ PULONG ResultLength); diff --git a/api/registry.c b/api/registry.c index 695844a..94ae8d4 100644 --- a/api/registry.c +++ b/api/registry.c @@ -28,7 +28,9 @@ static _Return_type_success_(return != NULL) HKEY LastError = RegNotifyChangeKeyValue(Key, FALSE, REG_NOTIFY_CHANGE_NAME, Event, TRUE); if (LastError != ERROR_SUCCESS) { - LOG_ERROR(L"Failed to setup notification", LastError); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG_ERROR(LastError, L"Failed to setup registry key %.*s notification", MAX_REG_PATH, RegPath); break; } @@ -56,16 +58,26 @@ static _Return_type_success_(return != NULL) HKEY } if (LastError != ERROR_FILE_NOT_FOUND && LastError != ERROR_PATH_NOT_FOUND) { - LOG_ERROR(L"Failed to open", LastError); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG_ERROR(LastError, L"Failed to open registry key %.*s\\%s", MAX_REG_PATH, RegPath, Path); break; } LONGLONG TimeLeft = Deadline - GetTickCount64(); if (TimeLeft < 0) TimeLeft = 0; - if (WaitForSingleObject(Event, (DWORD)TimeLeft) != WAIT_OBJECT_0) + DWORD Result = WaitForSingleObject(Event, (DWORD)TimeLeft); + if (Result != WAIT_OBJECT_0) { - LOG(WINTUN_LOG_ERR, L"Timeout waiting"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG(WINTUN_LOG_ERR, + L"Timeout waiting for registry key %.*s\\%s (status: 0x%x)", + MAX_REG_PATH, + RegPath, + Path, + Result); break; } } @@ -80,7 +92,7 @@ _Return_type_success_(return != NULL) HKEY WCHAR Buf[MAX_REG_PATH]; if (wcsncpy_s(Buf, _countof(Buf), Path, _TRUNCATE) == STRUNCATE) { - LOG(WINTUN_LOG_ERR, L"Registry path too long"); + LOG(WINTUN_LOG_ERR, L"Registry path too long: %s", Path); SetLastError(ERROR_INVALID_PARAMETER); return NULL; } @@ -118,7 +130,7 @@ _Return_type_success_(return != FALSE) BOOL RegistryGetString(_Inout_ WCHAR **Bu DWORD Result = ExpandEnvironmentStringsW(*Buf, Expanded, Len); if (!Result) { - LOG_LAST_ERROR(L"Failed to expand environment variables"); + LOG_LAST_ERROR(L"Failed to expand environment variables: %s", *Buf); Free(Expanded); return FALSE; } @@ -204,7 +216,11 @@ static _Return_type_success_(return != NULL) void *RegistryQuery( if (LastError != ERROR_MORE_DATA) { if (Log) - LOG_ERROR(L"Querying value failed", LastError); + { + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG_ERROR(LastError, L"Querying registry value %.*s\\%s failed", MAX_REG_PATH, RegPath, Name); + } SetLastError(LastError); return NULL; } @@ -227,10 +243,18 @@ _Return_type_success_( return Value; LastError = GetLastError(); break; - default: - LOG(WINTUN_LOG_ERR, L"Value is not a string"); + default: { + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG(WINTUN_LOG_ERR, + L"Registry value %.*s\\%s is not a string (type: %u)", + MAX_REG_PATH, + RegPath, + Name, + ValueType); LastError = ERROR_INVALID_DATATYPE; } + } Free(Value); SetLastError(LastError); return NULL; @@ -252,7 +276,9 @@ _Return_type_success_( LastError = RegNotifyChangeKeyValue(Key, FALSE, REG_NOTIFY_CHANGE_LAST_SET, Event, TRUE); if (LastError != ERROR_SUCCESS) { - LOG_ERROR(L"Failed to setup notification", LastError); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG_ERROR(LastError, L"Failed to setup registry key %.*s notification", MAX_REG_PATH, RegPath); break; } WCHAR *Value = RegistryQueryString(Key, Name, FALSE); @@ -267,9 +293,17 @@ _Return_type_success_( LONGLONG TimeLeft = Deadline - GetTickCount64(); if (TimeLeft < 0) TimeLeft = 0; - if (WaitForSingleObject(Event, (DWORD)TimeLeft) != WAIT_OBJECT_0) + DWORD Result = WaitForSingleObject(Event, (DWORD)TimeLeft); + if (Result != WAIT_OBJECT_0) { - LOG(WINTUN_LOG_ERR, L"Timeout waiting"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG(WINTUN_LOG_ERR, + L"Timeout waiting for registry value %.*s\\%s (status: 0x%x)", + MAX_REG_PATH, + RegPath, + Name, + Result); break; } } @@ -286,19 +320,27 @@ _Return_type_success_(return != FALSE) BOOL if (LastError != ERROR_SUCCESS) { if (Log) - LOG_ERROR(L"Querying failed", LastError); + { + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG_ERROR(LastError, L"Querying registry value %.*s\\%s failed", MAX_REG_PATH, RegPath, Name); + } SetLastError(LastError); return FALSE; } if (ValueType != REG_DWORD) { - LOG(WINTUN_LOG_ERR, L"Value is not a DWORD"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG(WINTUN_LOG_ERR, L"Value %.*s\\%s is not a DWORD (type: %u)", MAX_REG_PATH, RegPath, Name, ValueType); SetLastError(ERROR_INVALID_DATATYPE); return FALSE; } if (Size != sizeof(DWORD)) { - LOG(WINTUN_LOG_ERR, L"Value size is not 4 bytes"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG(WINTUN_LOG_ERR, L"Value %.*s\\%s size is not 4 bytes (size: %u)", MAX_REG_PATH, RegPath, Name, Size); SetLastError(ERROR_INVALID_DATA); return FALSE; } @@ -321,7 +363,9 @@ _Return_type_success_(return != FALSE) BOOL LastError = RegNotifyChangeKeyValue(Key, FALSE, REG_NOTIFY_CHANGE_LAST_SET, Event, TRUE); if (LastError != ERROR_SUCCESS) { - LOG_ERROR(L"Failed to setup notification", LastError); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG_ERROR(LastError, L"Failed to setup registry key %.*s notification", MAX_REG_PATH, RegPath); break; } if (RegistryQueryDWORD(Key, Name, Value, FALSE)) @@ -335,9 +379,17 @@ _Return_type_success_(return != FALSE) BOOL LONGLONG TimeLeft = Deadline - GetTickCount64(); if (TimeLeft < 0) TimeLeft = 0; - if (WaitForSingleObject(Event, (DWORD)TimeLeft) != WAIT_OBJECT_0) + DWORD Result = WaitForSingleObject(Event, (DWORD)TimeLeft); + if (Result != WAIT_OBJECT_0) { - LOG(WINTUN_LOG_ERR, L"Timeout waiting"); + WCHAR RegPath[MAX_REG_PATH]; + LoggerGetRegistryKeyPath(Key, RegPath); + LOG(WINTUN_LOG_ERR, + L"Timeout waiting registry value %.*s\\%s (status: 0x%x)", + MAX_REG_PATH, + RegPath, + Name, + Result); break; } } diff --git a/api/resource.c b/api/resource.c index a73e9fc..9a7379c 100644 --- a/api/resource.c +++ b/api/resource.c @@ -14,25 +14,25 @@ _Return_type_success_(return != NULL) _Ret_bytecount_(*Size) const HRSRC FoundResource = FindResourceW(ResourceModule, ResourceName, RT_RCDATA); if (!FoundResource) { - LOG_LAST_ERROR(L"Failed to find resource"); + LOG_LAST_ERROR(L"Failed to find resource %s", ResourceName); return NULL; } *Size = SizeofResource(ResourceModule, FoundResource); if (!*Size) { - LOG_LAST_ERROR(L"Failed to query resource size"); + LOG_LAST_ERROR(L"Failed to query resource %s size", ResourceName); return NULL; } HGLOBAL LoadedResource = LoadResource(ResourceModule, FoundResource); if (!LoadedResource) { - LOG_LAST_ERROR(L"Failed to load resource"); + LOG_LAST_ERROR(L"Failed to load resource %s", ResourceName); return NULL; } BYTE *Address = LockResource(LoadedResource); if (!Address) { - LOG(WINTUN_LOG_ERR, L"Failed to lock resource"); + LOG(WINTUN_LOG_ERR, L"Failed to lock resource %s", ResourceName); SetLastError(ERROR_LOCK_FAILED); return NULL; } @@ -46,7 +46,7 @@ _Return_type_success_(return != FALSE) BOOL const void *LockedResource = ResourceGetAddress(ResourceName, &SizeResource); if (!LockedResource) { - LOG(WINTUN_LOG_ERR, L"Failed to locate resource"); + LOG(WINTUN_LOG_ERR, L"Failed to locate resource %s", ResourceName); return FALSE; } HANDLE DestinationHandle = CreateFileW( @@ -59,19 +59,23 @@ _Return_type_success_(return != FALSE) BOOL NULL); if (DestinationHandle == INVALID_HANDLE_VALUE) { - LOG_LAST_ERROR(L"Failed to create file"); + LOG_LAST_ERROR(L"Failed to create file %s", DestinationPath); return FALSE; } DWORD BytesWritten; DWORD LastError; if (!WriteFile(DestinationHandle, LockedResource, SizeResource, &BytesWritten, NULL)) { - LastError = LOG_LAST_ERROR(L"Failed to write file"); + LastError = LOG_LAST_ERROR(L"Failed to write file %s", DestinationPath); goto cleanupDestinationHandle; } if (BytesWritten != SizeResource) { - LOG(WINTUN_LOG_ERR, L"Incomplete write"); + LOG(WINTUN_LOG_ERR, + L"Incomplete write to %s (written: %u, expected: %u)", + DestinationPath, + BytesWritten, + SizeResource); LastError = ERROR_WRITE_FAULT; goto cleanupDestinationHandle; } diff --git a/api/rundll32_i.c b/api/rundll32_i.c index 0bb0f1b..01ba6b6 100644 --- a/api/rundll32_i.c +++ b/api/rundll32_i.c @@ -102,7 +102,7 @@ static _Return_type_success_(return != FALSE) BOOL ExecuteRunDll32( WCHAR RandomTempSubDirectory[MAX_PATH]; if (!CreateTemporaryDirectory(RandomTempSubDirectory)) { - LOG(WINTUN_LOG_ERR, L"Failed to create temporary folder"); + LOG(WINTUN_LOG_ERR, L"Failed to create temporary folder %s", RandomTempSubDirectory); return FALSE; } WCHAR DllPath[MAX_PATH] = { 0 }; @@ -121,13 +121,13 @@ static _Return_type_success_(return != FALSE) BOOL ExecuteRunDll32( WintunDllResourceName = L"wintun-arm64.dll"; break; default: - LOG(WINTUN_LOG_ERR, L"Unsupported platform"); + LOG(WINTUN_LOG_ERR, L"Unsupported platform 0x%x", NativeMachine); LastError = ERROR_NOT_SUPPORTED; goto cleanupDirectory; } if (!ResourceCopyToFile(DllPath, WintunDllResourceName)) { - LastError = LOG(WINTUN_LOG_ERR, L"Failed to copy resource"); + LastError = LOG(WINTUN_LOG_ERR, L"Failed to copy resource %s to %s", WintunDllResourceName, DllPath); goto cleanupDelete; } size_t CommandLineLen = 10 + MAX_PATH + 2 + wcslen(Arguments) + 1; @@ -184,7 +184,7 @@ static _Return_type_success_(return != FALSE) BOOL ExecuteRunDll32( } if (!CreateProcessAsUserW(ProcessToken, RunDll32Path, CommandLine, NULL, NULL, TRUE, 0, NULL, NULL, &si, &pi)) { - LastError = LOG_LAST_ERROR(L"Failed to create process"); + LastError = LOG_LAST_ERROR(L"Failed to create process: %s", CommandLine); goto cleanupToken; } LastError = ERROR_SUCCESS; @@ -210,7 +210,7 @@ cleanupThreads: if (!GetExitCodeThread(ThreadStdout, &ThreadResult)) LOG_LAST_ERROR(L"Failed to retrieve stdout reader result"); else if (ThreadResult != ERROR_SUCCESS) - LOG_ERROR(L"Failed to read process output", LastError); + LOG_ERROR(LastError, L"Failed to read process output"); CloseHandle(ThreadStdout); } cleanupPipes: @@ -252,7 +252,7 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapterViaRun WCHAR Response[8 + 1 + MAX_GUID_STRING_LEN + 1 + 8 + 1]; if (!ExecuteRunDll32(Arguments, Response, _countof(Response))) { - LOG(WINTUN_LOG_ERR, L"Error executing worker process"); + LOG(WINTUN_LOG_ERR, L"Error executing worker process: %s", Arguments); return NULL; } DWORD LastError; @@ -262,14 +262,14 @@ static _Return_type_success_(return != NULL) WINTUN_ADAPTER *CreateAdapterViaRun GUID CfgInstanceID; if (Argc < 3 || FAILED(CLSIDFromString(Argv[1], &CfgInstanceID))) { - LOG(WINTUN_LOG_ERR, L"Incomplete or invalid response"); + LOG(WINTUN_LOG_ERR, L"Incomplete or invalid response: %s", Response); LastError = ERROR_INVALID_PARAMETER; goto cleanupArgv; } LastError = wcstoul(Argv[0], NULL, 16); if (LastError == ERROR_SUCCESS && (Adapter = GetAdapter(Pool, &CfgInstanceID)) == NULL) { - LOG(WINTUN_LOG_ERR, L"Failed to get adapter"); + LOG(WINTUN_LOG_ERR, L"Failed to get adapter %s", Argv[1]); LastError = ERROR_FILE_NOT_FOUND; } if (wcstoul(Argv[2], NULL, 16)) @@ -305,14 +305,14 @@ static _Return_type_success_(return != FALSE) BOOL DeleteAdapterViaRundll32( DWORD LastError; if (!ExecuteRunDll32(Arguments, Response, _countof(Response))) { - LOG(WINTUN_LOG_ERR, L"Error executing worker process"); + LOG(WINTUN_LOG_ERR, L"Error executing worker process: %s", Arguments); return FALSE; } int Argc; WCHAR **Argv = CommandLineToArgvW(Response, &Argc); if (Argc < 2) { - LOG(WINTUN_LOG_ERR, L"Incomplete or invalid response"); + LOG(WINTUN_LOG_ERR, L"Incomplete or invalid response: %s", Response); LastError = ERROR_INVALID_PARAMETER; goto cleanupArgv; } @@ -340,14 +340,14 @@ static _Return_type_success_(return != FALSE) BOOL DWORD LastError; if (!ExecuteRunDll32(Arguments, Response, _countof(Response))) { - LOG(WINTUN_LOG_ERR, L"Error executing worker process"); + LOG(WINTUN_LOG_ERR, L"Error executing worker process: %s", Arguments); return FALSE; } int Argc; WCHAR **Argv = CommandLineToArgvW(Response, &Argc); if (Argc < 2) { - LOG(WINTUN_LOG_ERR, L"Incomplete or invalid response"); + LOG(WINTUN_LOG_ERR, L"Incomplete or invalid response: %s", Response); LastError = ERROR_INVALID_PARAMETER; goto cleanupArgv; } diff --git a/api/session.c b/api/session.c index c522ed9..ef65214 100644 --- a/api/session.c +++ b/api/session.c @@ -83,7 +83,7 @@ _Return_type_success_(return != NULL) TUN_SESSION *WINAPI BYTE *AllocatedRegion = VirtualAlloc(0, (size_t)RingSize * 2, MEM_COMMIT | MEM_RESERVE, PAGE_READWRITE); if (!AllocatedRegion) { - LastError = LOG_LAST_ERROR(L"Failed to allocate ring memory"); + LastError = LOG_LAST_ERROR(L"Failed to allocate ring memory (requested size: 0x%zx)", (size_t)RingSize * 2); goto cleanupRings; } if (!ElevateToSystem())