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> --- windows/virt2phys/virt2phys.c | 18 +++++++- windows/virt2phys/virt2phys.vcxproj | 5 ++- windows/virt2phys/virt2phys.vcxproj.filters | 3 ++ windows/virt2phys/virt2phys_logic.c | 8 ++++ windows/virt2phys/virt2phys_trace.h | 49 +++++++++++++++++++++ 5 files changed, 79 insertions(+), 4 deletions(-) create mode 100644 windows/virt2phys/virt2phys_trace.h diff --git a/windows/virt2phys/virt2phys.c b/windows/virt2phys/virt2phys.c index 0c05fe3..54f4bc0 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; @@ -46,6 +48,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; } @@ -53,11 +57,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_ @@ -79,12 +83,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; } @@ -109,12 +116,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; } @@ -122,6 +131,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; } @@ -129,6 +139,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; } @@ -136,6 +147,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 294f086..a3e18dc 100644 --- a/windows/virt2phys/virt2phys.vcxproj +++ b/windows/virt2phys/virt2phys.vcxproj @@ -41,6 +41,7 @@ <ItemGroup> <ClInclude Include="virt2phys.h" /> <ClInclude Include="virt2phys_logic.h" /> + <ClInclude Include="virt2phys_trace.h" /> </ItemGroup> <ItemGroup> <Inf Include="virt2phys.inf" /> @@ -170,9 +171,9 @@ </ItemDefinitionGroup> <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> 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 155d34f..7d5bf02 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; @@ -37,6 +39,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); @@ -63,6 +67,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); @@ -185,6 +191,8 @@ virt2phys_add_block(struct virt2phys_process *process, { struct virt2phys_process *existing; + TraceInfo("ID = %p, VA = %p", process->id, block->mdl->StartVa); + existing = virt2phys_process_find(process->id); if (existing == NULL) InsertHeadList(&g_processes, &process->next); diff --git a/windows/virt2phys/virt2phys_trace.h b/windows/virt2phys/virt2phys_trace.h new file mode 100644 index 0000000..ebd7618 --- /dev/null +++ b/windows/virt2phys/virt2phys_trace.h @@ -0,0 +1,49 @@ +/* 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
