@@ -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);
}
@@ -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" />
@@ -169,9 +170,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>
@@ -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">
@@ -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;
}
new file mode 100644
@@ -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
+*/