diff mbox series

[kmods,v2,4/4] windows/virt2phys: add tracing

Message ID 20210526210147.1287-5-dmitry.kozliuk@gmail.com (mailing list archive)
State Superseded, archived
Delegated to: Thomas Monjalon
Headers show
Series windows/virt2phys: fix paging issue | expand

Checks

Context Check Description
ci/Intel-compilation warning apply issues
ci/checkpatch warning coding style issues

Commit Message

Dmitry Kozlyuk May 26, 2021, 9:01 p.m. UTC
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.kozliuk@gmail.com>
---
Comment at the bottom of virt2phys_trace.h is consumed by WPP code
generator, which is the reason it has no leading asterisks.

 windows/virt2phys/virt2phys.c               | 18 +++++++-
 windows/virt2phys/virt2phys.vcxproj         |  5 ++-
 windows/virt2phys/virt2phys.vcxproj.filters |  3 ++
 windows/virt2phys/virt2phys_logic.c         | 35 ++++++++++++---
 windows/virt2phys/virt2phys_trace.h         | 50 +++++++++++++++++++++
 5 files changed, 101 insertions(+), 10 deletions(-)
 create mode 100644 windows/virt2phys/virt2phys_trace.h

Comments

Menon, Ranjit Sept. 30, 2021, 10:07 p.m. UTC | #1
Hi Dmitry,

On 5/26/2021 2:01 PM, Dmitry Kozlyuk wrote:
> 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.kozliuk@gmail.com>
> ---
> <snip!>
diff --git a/windows/virt2phys/virt2phys.vcxproj 
b/windows/virt2phys/virt2phys.vcxproj
> index b462493..c9f884a 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" />
> @@ -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>

This change is also required for the 'Release|x64' configuration, 
otherwise 'Release' builds fail.

<snip!>

Also, it appears the newer version of the compiler (combined with the 
new version of WDK/SDK), requires that the driver signing process 
mandate a File Digest Algorithm (using the /fd option). It is a warning 
today, but they claim it could become a requirement in the future.

To fix this, we can include the following in the project file:

<DriverSign>
   <FileDigestAlgorithm>SHA256</FileDigestAlgorithm>
</DriverSign>

Or set the above, using project 'Properties'->Driver Signing->File 
Digest Algorithm = 256.

(This will need to be fixed in the netuio driver project also)

thanks,

ranjit m.
Menon, Ranjit Sept. 30, 2021, 10:13 p.m. UTC | #2
Typo below:

On 9/30/2021 3:07 PM, Menon, Ranjit wrote:
> Hi Dmitry,
>
> On 5/26/2021 2:01 PM, Dmitry Kozlyuk wrote:
>> 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.kozliuk@gmail.com>
>> ---
>> <snip!>
> diff --git a/windows/virt2phys/virt2phys.vcxproj 
> b/windows/virt2phys/virt2phys.vcxproj
>> index b462493..c9f884a 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" />
>> @@ -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>
>
> This change is also required for the 'Release|x64' configuration, 
> otherwise 'Release' builds fail.
>
> <snip!>
>
> Also, it appears the newer version of the compiler (combined with the 
> new version of WDK/SDK), requires that the driver signing process 
> mandate a File Digest Algorithm (using the /fd option). It is a 
> warning today, but they claim it could become a requirement in the 
> future.
>
> To fix this, we can include the following in the project file:
>
> <DriverSign>
>   <FileDigestAlgorithm>SHA256</FileDigestAlgorithm>
> </DriverSign>
>
> Or set the above, using project 'Properties'->Driver Signing->File 
> Digest Algorithm = 256.

Should be:

"Or set the above, using project 'Properties'->Driver Signing->File 
Digest Algorithm = SHA256"

>
> (This will need to be fixed in the netuio driver project also)
>
> thanks,
>
> ranjit m.
>
Dmitry Kozlyuk Oct. 1, 2021, 7:10 a.m. UTC | #3
2021-09-30 15:07 (UTC-0700), Menon, Ranjit:
> [...]
> >     <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>  
> 
> This change is also required for the 'Release|x64' configuration, 
> otherwise 'Release' builds fail.

Thanks Ranjit, will fix in v3.

> <snip!>
> 
> Also, it appears the newer version of the compiler (combined with the 
> new version of WDK/SDK), requires that the driver signing process 
> mandate a File Digest Algorithm (using the /fd option). It is a warning 
> today, but they claim it could become a requirement in the future.

Yes, it started with WDK 22000.1. On my system it's an error, not a warning.
I think I'll create a separate series with trivial fixes like this, so that
it can be merged quickly and fix the build with newer WDK.
diff mbox series

Patch

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, &params);
 
 	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 b462493..c9f884a 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" />
@@ -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>
diff --git a/windows/virt2phys/virt2phys.vcxproj.filters b/windows/virt2phys/virt2phys.vcxproj.filters
index acd159f..6afff72 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
+*/