WPP tracing [1] allows kernel drivers to print logs that can be viewed without attaching a debugger to the running system. Traces are colelcted only when enabled. Instrument virt2phys with traces: * ERROR: failures that prevent the driver from working. * WARNING: incorrect calls to the driver. * INFO: starting or completing operations with memory.
[1]: https://docs.microsoft.com/en-us/windows-hardware/drivers/devtest/wpp-software-tracing Signed-off-by: Dmitry Kozlyuk <dmitry.kozl...@gmail.com> Acked-by: Ranjit Menon <ranjit.me...@intel.com> --- windows/virt2phys/virt2phys.c | 18 +++++++- windows/virt2phys/virt2phys.vcxproj | 9 ++-- windows/virt2phys/virt2phys.vcxproj.filters | 3 ++ windows/virt2phys/virt2phys_logic.c | 35 ++++++++++++--- windows/virt2phys/virt2phys_trace.h | 50 +++++++++++++++++++++ 5 files changed, 103 insertions(+), 12 deletions(-) create mode 100644 windows/virt2phys/virt2phys_trace.h diff --git a/windows/virt2phys/virt2phys.c b/windows/virt2phys/virt2phys.c index 44204c9..f4d5298 100644 --- a/windows/virt2phys/virt2phys.c +++ b/windows/virt2phys/virt2phys.c @@ -8,6 +8,8 @@ #include "virt2phys.h" #include "virt2phys_logic.h" +#include "virt2phys_trace.h" +#include "virt2phys.tmh" DRIVER_INITIALIZE DriverEntry; EVT_WDF_DRIVER_UNLOAD virt2phys_driver_unload; @@ -66,6 +68,8 @@ DriverEntry(PDRIVER_OBJECT driver_object, PUNICODE_STRING registry_path) if (!NT_SUCCESS(status)) return status; + WPP_INIT_TRACING(driver_object, registry_path); + return status; } @@ -131,11 +135,11 @@ _Use_decl_annotations_ VOID virt2phys_driver_unload(WDFDRIVER driver) { - UNREFERENCED_PARAMETER(driver); - PsSetCreateProcessNotifyRoutine(virt2phys_on_process_event, TRUE); virt2phys_cleanup(); + + WPP_CLEANUP(WdfDriverWdmGetDriverObject(driver)); } _Use_decl_annotations_ @@ -157,12 +161,15 @@ virt2phys_driver_EvtDeviceAdd(WDFDRIVER driver, PWDFDEVICE_INIT init) status = WdfDeviceCreate(&init, &attributes, &device); if (!NT_SUCCESS(status)) { + TraceError("WdfDriverCreate() = %!STATUS!", status); return status; } status = WdfDeviceCreateDeviceInterface( device, &GUID_DEVINTERFACE_VIRT2PHYS, NULL); if (!NT_SUCCESS(status)) { + TraceError("WdfDeviceCreateDeviceInterface() = %!STATUS!", + status); return status; } @@ -187,12 +194,14 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) WdfRequestGetParameters(request, ¶ms); if (params.Type != WdfRequestTypeDeviceControl) { + TraceWarning("Bogus IO request type %lu", params.Type); WdfRequestComplete(request, STATUS_NOT_SUPPORTED); return; } code = params.Parameters.DeviceIoControl.IoControlCode; if (code != IOCTL_VIRT2PHYS_TRANSLATE) { + TraceWarning("Bogus IO control code %lx", code); WdfRequestComplete(request, STATUS_NOT_SUPPORTED); return; } @@ -200,6 +209,7 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) status = WdfRequestRetrieveInputBuffer( request, sizeof(*virt), (PVOID *)&virt, &size); if (!NT_SUCCESS(status)) { + TraceWarning("Retrieving input buffer: %!STATUS!", status); WdfRequestComplete(request, status); return; } @@ -207,6 +217,7 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) status = WdfRequestRetrieveOutputBuffer( request, sizeof(*phys), (PVOID *)&phys, &size); if (!NT_SUCCESS(status)) { + TraceWarning("Retrieving output buffer: %!STATUS!", status); WdfRequestComplete(request, status); return; } @@ -214,6 +225,9 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) status = virt2phys_translate(*virt, phys); if (NT_SUCCESS(status)) WdfRequestSetInformation(request, sizeof(*phys)); + + TraceInfo("Translate %p to %llx: %!STATUS!", + virt, phys->QuadPart, status); WdfRequestComplete(request, status); } diff --git a/windows/virt2phys/virt2phys.vcxproj b/windows/virt2phys/virt2phys.vcxproj index 656b1f2..fd168b1 100644 --- a/windows/virt2phys/virt2phys.vcxproj +++ b/windows/virt2phys/virt2phys.vcxproj @@ -17,6 +17,7 @@ <ItemGroup> <ClInclude Include="virt2phys.h" /> <ClInclude Include="virt2phys_logic.h" /> + <ClInclude Include="virt2phys_trace.h" /> </ItemGroup> <ItemGroup> <Inf Include="virt2phys.inf" /> @@ -63,9 +64,9 @@ </PropertyGroup> <ItemDefinitionGroup Condition="'$(Configuration)|$(Platform)'=='Debug|x64'"> <ClCompile> - <WppEnabled>false</WppEnabled> + <WppEnabled>true</WppEnabled> <WppRecorderEnabled>true</WppRecorderEnabled> - <WppScanConfigurationData Condition="'%(ClCompile.ScanConfigurationData)' == ''">trace.h</WppScanConfigurationData> + <WppScanConfigurationData Condition="'%(ClCompile.ScanConfigurationData)' == ''">virt2phys_trace.h</WppScanConfigurationData> <WppKernelMode>true</WppKernelMode> </ClCompile> <Link> @@ -80,9 +81,9 @@ </ItemDefinitionGroup> <ItemDefinitionGroup Condition="'$(Configuration)|$(Platform)'=='Release|x64'"> <ClCompile> - <WppEnabled>false</WppEnabled> + <WppEnabled>true</WppEnabled> <WppRecorderEnabled>true</WppRecorderEnabled> - <WppScanConfigurationData Condition="'%(ClCompile.ScanConfigurationData)' == ''">trace.h</WppScanConfigurationData> + <WppScanConfigurationData Condition="'%(ClCompile.ScanConfigurationData)' == ''">virt2phys_trace.h</WppScanConfigurationData> <WppKernelMode>true</WppKernelMode> </ClCompile> <DriverSign> diff --git a/windows/virt2phys/virt2phys.vcxproj.filters b/windows/virt2phys/virt2phys.vcxproj.filters index 6b65d71..b2f6776 100644 --- a/windows/virt2phys/virt2phys.vcxproj.filters +++ b/windows/virt2phys/virt2phys.vcxproj.filters @@ -30,6 +30,9 @@ <ClInclude Include="virt2phys_logic.h"> <Filter>Header Files</Filter> </ClInclude> + <ClInclude Include="virt2phys_trace.h"> + <Filter>Header Files</Filter> + </ClInclude> </ItemGroup> <ItemGroup> <ClCompile Include="virt2phys.c"> diff --git a/windows/virt2phys/virt2phys_logic.c b/windows/virt2phys/virt2phys_logic.c index 37b4dd4..e3ff293 100644 --- a/windows/virt2phys/virt2phys_logic.c +++ b/windows/virt2phys/virt2phys_logic.c @@ -6,6 +6,8 @@ #include <ntddk.h> #include "virt2phys_logic.h" +#include "virt2phys_trace.h" +#include "virt2phys_logic.tmh" struct virt2phys_process { HANDLE id; @@ -38,6 +40,8 @@ virt2phys_block_create(PMDL mdl) static void virt2phys_block_free(struct virt2phys_block *block, BOOLEAN unmap) { + TraceInfo("VA = %p, unmap = %!bool!", block->mdl->StartVa, unmap); + if (unmap) MmUnlockPages(block->mdl); @@ -76,6 +80,8 @@ virt2phys_process_free(struct virt2phys_process *process, BOOLEAN unmap) PSINGLE_LIST_ENTRY node; struct virt2phys_block *block; + TraceInfo("ID = %p, unmap = %!bool!", process->id, unmap); + node = process->blocks.Next; while (node != NULL) { block = CONTAINING_RECORD(node, struct virt2phys_block, next); @@ -208,6 +214,8 @@ virt2phys_add_block(struct virt2phys_process *process, struct virt2phys_process *existing; size_t size; + TraceInfo("ID = %p, VA = %p", process->id, block->mdl->StartVa); + existing = virt2phys_process_find(process->id); *process_exists = existing != NULL; if (existing == NULL) { @@ -217,8 +225,11 @@ virt2phys_add_block(struct virt2phys_process *process, * because decrement is done without holding the lock. */ if (virt2phys_exceeeds(g_process_count + 1, - g_params.process_count_limit)) + g_params.process_count_limit)) { + TraceWarning("Process count limit reached (%lu)", + g_params.process_count_limit); return STATUS_QUOTA_EXCEEDED; + } InsertHeadList(&g_processes, &process->next); InterlockedIncrement(&g_process_count); @@ -227,8 +238,11 @@ virt2phys_add_block(struct virt2phys_process *process, size = MmGetMdlByteCount(block->mdl); if (virt2phys_exceeeds(process->memory + size, - g_params.process_memory_limit)) + g_params.process_memory_limit)) { + TraceWarning("Process %p memory limit reached (%llu bytes)", + process->id, g_params.process_memory_limit); return STATUS_QUOTA_EXCEEDED; + } PushEntryList(&process->blocks, &block->next); process->memory += size; @@ -277,8 +291,10 @@ virt2phys_check_memory(PMDL mdl) size_t size; NTSTATUS status; - if (!virt2phys_is_contiguous(mdl)) + if (!virt2phys_is_contiguous(mdl)) { + TraceWarning("Locked region is not physycally contiguous"); return STATUS_UNSUCCESSFUL; + } virt = MmGetMdlVirtualAddress(mdl); size = MmGetMdlByteCount(mdl); @@ -288,12 +304,19 @@ virt2phys_check_memory(PMDL mdl) if (!NT_SUCCESS(status)) return status; - if (info.AllocationBase != virt || info.RegionSize != size) + if (info.AllocationBase != virt || info.RegionSize != size) { + TraceWarning("Race for the region: supplied %p (%llu bytes), locked %p (%llu bytes)", + virt, size, info.AllocationBase, info.RegionSize); return STATUS_UNSUCCESSFUL; - if (info.State != MEM_COMMIT) + } + if (info.State != MEM_COMMIT) { + TraceWarning("Attempt to lock uncommitted memory"); return STATUS_UNSUCCESSFUL; - if (info.Type != MEM_PRIVATE) + } + if (info.Type != MEM_PRIVATE) { + TraceWarning("Attempt to lock shared memory"); return STATUS_UNSUCCESSFUL; + } return status; } diff --git a/windows/virt2phys/virt2phys_trace.h b/windows/virt2phys/virt2phys_trace.h new file mode 100644 index 0000000..df863cb --- /dev/null +++ b/windows/virt2phys/virt2phys_trace.h @@ -0,0 +1,50 @@ +/* SPDX-License-Identifier: BSD-3-Clause + * Copyright 2021 Dmitry Kozlyuk + */ + +/* Tracing GUID: C5C835BB-5CFB-4757-B1D4-9DD74662E212 */ +#define WPP_CONTROL_GUIDS \ + WPP_DEFINE_CONTROL_GUID( \ + VIRT2PHYS_TRACE_GUID, \ + (C5C835BB, 5CFB, 4757, B1D4, 9DD74662E212), \ + WPP_DEFINE_BIT(TRACE_GENERAL)) + +#define WPP_FLAG_LEVEL_LOGGER(flag, level) \ + WPP_LEVEL_LOGGER(flag) + +#define WPP_FLAG_LEVEL_ENABLED(flag, level) \ + (WPP_LEVEL_ENABLED(flag) && \ + WPP_CONTROL(WPP_BIT_ ## flag).Level >= level) + +#define WPP_LEVEL_FLAGS_LOGGER(lvl, flags) \ + WPP_LEVEL_LOGGER(flags) + +#define WPP_LEVEL_FLAGS_ENABLED(lvl, flags) \ + (WPP_LEVEL_ENABLED(flags) && \ + WPP_CONTROL(WPP_BIT_ ## flags).Level >= lvl) + +/* + * WPP orders static parameters before dynamic parameters. + * To support trace functions defined below which sets FLAGS and LEVEL, + * a custom macro must be defined to reorder the arguments + * to what the .tpl configuration file expects. + */ +#define WPP_RECORDER_FLAGS_LEVEL_ARGS(flags, lvl) \ + WPP_RECORDER_LEVEL_FLAGS_ARGS(lvl, flags) +#define WPP_RECORDER_FLAGS_LEVEL_FILTER(flags, lvl) \ + WPP_RECORDER_LEVEL_FLAGS_FILTER(lvl, flags) + +/* +begin_wpp config + +USEPREFIX(TraceError, "[%!FUNC!] "); +FUNC TraceError{FLAGS=TRACE_GENERAL, LEVEL=TRACE_LEVEL_ERROR}(MSG, ...); + +USEPREFIX(TraceWarning, "[%!FUNC!] "); +FUNC TraceWarning{FLAGS=TRACE_GENERAL, LEVEL=TRACE_LEVEL_WARNING}(MSG, ...); + +USEPREFIX(TraceInfo, "[%!FUNC!] "); +FUNC TraceInfo{FLAGS=TRACE_GENERAL, LEVEL=TRACE_LEVEL_INFORMATION}(MSG, ...); + +end_wpp +*/ -- 2.29.3
