Improve logging

In order to investigate "stuck on boot" issue #24 add additional logging and attach reg file to enable AutoLogger to diagnose boot issues. Bump version to 0.8.4 Signed-off-by: Lev Stipakov <[email protected]>
OpenVPN · Feb 3, 2023 · 94703dc · 94703dc
1 parent 8dec0bb
commit 94703dc
Show file tree

Hide file tree

Showing 7 changed files with 144 additions and 19 deletions.
diff --git a/Driver.cpp b/Driver.cpp
@@ -99,6 +99,8 @@ DriverEntry(_In_ PDRIVER_OBJECT driverObject, _In_ PUNICODE_STRING registryPath)
         }
     }
 
+    LOG_EXIT();
+
     return status;
 }
 
@@ -275,23 +277,25 @@ EVT_WDF_FILE_CLEANUP OvpnEvtFileCleanup;
 
 _Use_decl_annotations_
 VOID OvpnEvtFileCleanup(WDFFILEOBJECT fileObject) {
-    POVPN_DEVICE device = OvpnGetDeviceContext(WdfFileObjectGetDevice(fileObject));
+    LOG_ENTER();
 
-    LOG_INFO("Uninitializing device");
+    POVPN_DEVICE device = OvpnGetDeviceContext(WdfFileObjectGetDevice(fileObject));
 
     // peer might already be deleted
     (VOID)OvpnPeerDel(device);
 
     InterlockedExchange(&device->UserspacePid, 0);
 
     OvpnAdapterSetLinkState(OvpnGetAdapterContext(device->Adapter), MediaConnectStateDisconnected);
+
+    LOG_EXIT();
 }
 
 EVT_WDF_DEVICE_CONTEXT_CLEANUP OvpnEvtDeviceCleanup;
 
 _Use_decl_annotations_
 VOID OvpnEvtDeviceCleanup(WDFOBJECT obj) {
-    LOG_INFO("");
+    LOG_ENTER();
 
     OVPN_DEVICE* device = OvpnGetDeviceContext(obj);
 
@@ -304,14 +308,75 @@ VOID OvpnEvtDeviceCleanup(WDFOBJECT obj) {
     KIRQL irql = ExAcquireSpinLockExclusive(&device->SpinLock);
     device->Adapter = WDF_NO_HANDLE;
     ExReleaseSpinLockExclusive(&device->SpinLock, irql);
+
+    LOG_EXIT();
+}
+
+EVT_WDF_DEVICE_PREPARE_HARDWARE OvpnEvtDevicePrepareHardware;
+EVT_WDF_DEVICE_RELEASE_HARDWARE OvpnEvtDeviceReleaseHardware;
+_No_competing_thread_ EVT_WDF_DEVICE_D0_ENTRY OvpnEvtDeviceD0Entry;
+_No_competing_thread_ EVT_WDF_DEVICE_D0_EXIT OvpnEvtDeviceD0Exit;
+
+_Use_decl_annotations_
+NTSTATUS
+OvpnEvtDevicePrepareHardware(_In_ WDFDEVICE wdfDevice, _In_ WDFCMRESLIST resourcesRaw, _In_ WDFCMRESLIST resourcesTranslated)
+{
+    UNREFERENCED_PARAMETER(wdfDevice);
+    UNREFERENCED_PARAMETER(resourcesRaw);
+    UNREFERENCED_PARAMETER(resourcesTranslated);
+
+    LOG_ENTER();
+    LOG_EXIT();
+    return STATUS_SUCCESS;
+}
+
+_Use_decl_annotations_
+NTSTATUS
+OvpnEvtDeviceReleaseHardware(_In_ WDFDEVICE wdfDevice, _In_ WDFCMRESLIST resourcesTranslated)
+{
+    UNREFERENCED_PARAMETER(wdfDevice);
+    UNREFERENCED_PARAMETER(resourcesTranslated);
+
+    LOG_ENTER();
+    LOG_EXIT();
+    return STATUS_SUCCESS;
+}
+
+_Use_decl_annotations_
+NTSTATUS
+OvpnEvtDeviceD0Entry(_In_ WDFDEVICE wdfDevice, WDF_POWER_DEVICE_STATE previousState)
+{
+    UNREFERENCED_PARAMETER(wdfDevice);
+
+    LOG_ENTER();
+
+    LOG_INFO("PreviousState", TraceLoggingUInt32(previousState, "PreviousState"));
+
+    LOG_EXIT();
+
+    return STATUS_SUCCESS;
+}
+
+_Use_decl_annotations_
+NTSTATUS
+OvpnEvtDeviceD0Exit(_In_ WDFDEVICE Device, _In_ WDF_POWER_DEVICE_STATE TargetState)
+{
+    UNREFERENCED_PARAMETER(Device);
+
+    LOG_ENTER();
+
+    LOG_INFO("TargetState", TraceLoggingUInt32(TargetState, "TargetState"));
+
+    LOG_EXIT();
+    return STATUS_SUCCESS;
 }
 
 EVT_WDF_DRIVER_DEVICE_ADD OvpnEvtDeviceAdd;
 
 _Use_decl_annotations_
 NTSTATUS
 OvpnEvtDeviceAdd(WDFDRIVER wdfDriver, PWDFDEVICE_INIT deviceInit) {
-    LOG_INFO("");
+    LOG_ENTER();
 
     // make sure only one app can access driver at time
     WdfDeviceInitSetExclusive(deviceInit, TRUE);
@@ -326,6 +391,15 @@ OvpnEvtDeviceAdd(WDFDRIVER wdfDriver, PWDFDEVICE_INIT deviceInit) {
     NTSTATUS status;
     GOTO_IF_NOT_NT_SUCCESS(done, status, NetDeviceInitConfig(deviceInit));
 
+    WDF_PNPPOWER_EVENT_CALLBACKS pnpPowerCallbacks;
+    WDF_PNPPOWER_EVENT_CALLBACKS_INIT(&pnpPowerCallbacks);
+    pnpPowerCallbacks.EvtDevicePrepareHardware = OvpnEvtDevicePrepareHardware;
+    pnpPowerCallbacks.EvtDeviceReleaseHardware = OvpnEvtDeviceReleaseHardware;
+    pnpPowerCallbacks.EvtDeviceD0Entry = OvpnEvtDeviceD0Entry;
+    pnpPowerCallbacks.EvtDeviceD0Exit = OvpnEvtDeviceD0Exit;
+
+    WdfDeviceInitSetPnpPowerEventCallbacks(deviceInit, &pnpPowerCallbacks);
+
     WDF_OBJECT_ATTRIBUTES objAttributes;
     WDF_OBJECT_ATTRIBUTES_INIT_CONTEXT_TYPE(&objAttributes, OVPN_DEVICE);
     // BCryptOpenAlgorithmProvider with BCRYPT_PROV_DISPATCH returns STATUS_NOT_SUPPORTED if sync scope is WdfSynchronizationScopeDevice
@@ -368,8 +442,10 @@ OvpnEvtDeviceAdd(WDFDRIVER wdfDriver, PWDFDEVICE_INIT deviceInit) {
 
     POVPN_DRIVER driver = OvpnGetDriverContext(wdfDriver);
 
+    LOG_INFO("Before calling WskCaptureProviderNPI()");
     // Capture the WSK Provider NPI. If WSK subsystem is not ready yet, wait until it becomes ready.
     GOTO_IF_NOT_NT_SUCCESS(done, status, WskCaptureProviderNPI(&driver->WskRegistration, WSK_INFINITE_WAIT, &driver->WskProviderNpi));
+    LOG_INFO("After calling WskCaptureProviderNPI()");
 
     GOTO_IF_NOT_NT_SUCCESS(done, status, OvpnTxBufferPoolCreate(&device->TxBufferPool, device));
     GOTO_IF_NOT_NT_SUCCESS(done, status, OvpnRxBufferPoolCreate(&device->RxBufferPool));
@@ -380,5 +456,7 @@ OvpnEvtDeviceAdd(WDFDRIVER wdfDriver, PWDFDEVICE_INIT deviceInit) {
     LOG_IF_NOT_NT_SUCCESS(status = OvpnAdapterCreate(device));
 
 done:
+    LOG_EXIT();
+
     return status;
 }
diff --git a/PropertySheet.props b/PropertySheet.props
@@ -4,7 +4,7 @@
   <PropertyGroup Label="UserMacros">
     <OVPN_DCO_VERSION_MAJOR>0</OVPN_DCO_VERSION_MAJOR>
     <OVPN_DCO_VERSION_MINOR>8</OVPN_DCO_VERSION_MINOR>
-    <OVPN_DCO_VERSION_PATCH>3</OVPN_DCO_VERSION_PATCH>
+    <OVPN_DCO_VERSION_PATCH>4</OVPN_DCO_VERSION_PATCH>
   </PropertyGroup>
   <PropertyGroup />
   <ItemDefinitionGroup>

diff --git a/README.md b/README.md
@@ -6,16 +6,16 @@
 
 ovpn-dco-win stands for "OpenVPN Data Channel Offload for Windows". It is a modern Windows driver, which functions as virtual network adapter and implements required functionality to handle the OpenVPN data channel. When using ovpn-dco-win, the OpenVPN software doesn't send data traffic back and forth between user and kernel space (for encryption, decryption and routing), but operations on payload take place in Windows kernel. The driver is being developed using modern frameworks - WDF and NetAdapterCx. Because of that, the code is easier to read and maintain comparison to existing NDIS miniport drivers. Speed-wise the new driver performs significantly better comparison to tap-windows6, so it should eliminate the bottleneck which hampers the performance of OpenVPN on Windows.
 
+ovpn-dco-win is a default driver starting from OpenVPN 2.6.
 
 ### Installation
 
-To use the driver, you must install it first. By default Windows doesn't load test-signed driver. To make Windows load the driver, run following command as Administrator:
+You can just install the latest [OpenVPN 2.6 release](https://openvpn.net/community-downloads/), which includes signed driver.
 
-```
-Bcdedit.exe -set TESTSIGNING ON
-```
 
-and restart. Then install the driver using devcon tool (available as part of WDK):
+Alternatively you can get releases from [GitHub](https://github.com/OpenVPN/ovpn-dco-win/releases).
+
+You can use devcon tool (available as part of WDK) to install the driver:
 
 ```
 devcon install ovpn-dco.inf ovpn-dco
@@ -88,8 +88,7 @@ To send and receive control channel packets, client uses Read/WriteFile calls. I
 
 ### OpenVPN support
 
-ovpn-dco-win driver is already used by default in openvpn2 master and will be part of 2.6 release.
-MSI installers, build from master branch commits, could be found at https://build.openvpn.net/downloads/snapshots/github-actions/openvpn2/.
+ovpn-dco-win driver is used by default OpenVPN starting from 2.6 release.
 
 OpenVPN3 also supports ovpn-dco-win in the latest master branch.
 
@@ -116,6 +115,9 @@ To see logs in attached debbuger (windbg), use `tracelog.exe` in administrator c
 
 * `tracelog -start MyTrace -guid #4970F9cf-2c0c-4f11-b1cc-e3a1e9958833 -rt -kd`
 
+If you experience boot issues, you might want to enable AutoLogger session. Run `ovpn-dco-autologger.reg` file, which will create neccessary registry keys, and then reboot.
+
+Driver logs will be stored in `%SystemRoot%\System32\LogFiles\WMI\ovpn-dco.etl`.
 
 ### Reproducible builds
 
@@ -138,9 +140,7 @@ If you have obtained a ovpn-dco.sys file, you can verify it as follows:
 ### Limitations
 
 * Minimum supported Windows version is Windows 10 20H1.
-* The driver is under development and the code is not production quality yet.
-* Supported cipher are "none" (for testing only) and AES-128(-192-256)-GCM.
-* Driver is test-signed (properly signed binaries will be provided later).
+* Supported cipher are AES-128(-192-256)-GCM and ChaCha20-Poly1305 (starting from Windows 11 / Server 2022)
 
 
 ### Questions

diff --git a/adapter.cpp b/adapter.cpp
@@ -155,6 +155,8 @@ NTSTATUS
 OvpnAdapterCreate(OVPN_DEVICE * device) {
     NTSTATUS status = STATUS_SUCCESS;
 
+    LOG_ENTER();
+
     NETADAPTER_INIT* adapterInit = NetAdapterInitAllocate(device->WdfDevice);
     if (adapterInit == NULL) {
         LOG_ERROR("NetAdapterInitAllocate() failed");
@@ -200,6 +202,8 @@ OvpnAdapterCreate(OVPN_DEVICE * device) {
     adapterInit = NULL;
 
 done:
+    LOG_EXIT();
+
     return status;
 }
 

diff --git a/ovpn-dco-autologger.reg b/ovpn-dco-autologger.reg
diff --git a/peer.cpp b/peer.cpp
@@ -48,6 +48,8 @@ _Use_decl_annotations_
 NTSTATUS
 OvpnPeerNew(POVPN_DEVICE device, WDFREQUEST request)
 {
+    LOG_ENTER();
+
     POVPN_NEW_PEER peer = NULL;
     NTSTATUS status;
     GOTO_IF_NOT_NT_SUCCESS(done, status, WdfRequestRetrieveInputBuffer(request, sizeof(OVPN_NEW_PEER), (PVOID*)&peer, nullptr));
@@ -94,20 +96,22 @@ OvpnPeerNew(POVPN_DEVICE device, WDFREQUEST request)
     }
 
 done:
+    LOG_EXIT();
+
     return status;
 }
 
 _Use_decl_annotations_
 NTSTATUS
 OvpnPeerDel(POVPN_DEVICE device)
 {
+    LOG_ENTER();
+
     if (InterlockedCompareExchange(&device->UserspacePid, 0, 0) == 0) {
         LOG_INFO("Peer not added.");
         return STATUS_INVALID_DEVICE_REQUEST;
     }
 
-    LOG_INFO("Deleting peer, keeping adapter connected");
-
     BCRYPT_ALG_HANDLE aesAlgHandle = NULL, chachaAlgHandle = NULL;
 
     KIRQL kirql = ExAcquireSpinLockExclusive(&device->SpinLock);
@@ -149,12 +153,16 @@ OvpnPeerDel(POVPN_DEVICE device)
         WdfRequestCompleteWithInformation(request, STATUS_CANCELLED, bytesCopied);
     }
 
+    LOG_EXIT();
+
     return STATUS_SUCCESS;
 }
 
 _Use_decl_annotations_
 NTSTATUS OvpnPeerSet(POVPN_DEVICE device, WDFREQUEST request)
 {
+    LOG_ENTER();
+
     if (InterlockedCompareExchange(&device->UserspacePid, 0, 0) == 0) {
         LOG_ERROR("Peer not added");
         return STATUS_INVALID_DEVICE_REQUEST;
@@ -201,13 +209,16 @@ NTSTATUS OvpnPeerSet(POVPN_DEVICE device, WDFREQUEST request)
     }
 
 done:
+    LOG_EXIT();
     return status;
 }
 
 _Use_decl_annotations_
 NTSTATUS
 OvpnPeerGetStats(POVPN_DEVICE device, WDFREQUEST request, ULONG_PTR* bytesReturned)
 {
+    LOG_ENTER();
+
     if (InterlockedCompareExchange(&device->UserspacePid, 0, 0) == 0) {
         LOG_ERROR("Peer not added");
         return STATUS_INVALID_DEVICE_REQUEST;
@@ -233,29 +244,35 @@ OvpnPeerGetStats(POVPN_DEVICE device, WDFREQUEST request, ULONG_PTR* bytesReturn
     *bytesReturned = sizeof(OVPN_STATS);
 
 done:
+    LOG_EXIT();
+
     return status;
 }
 
 _Use_decl_annotations_
 NTSTATUS
 OvpnPeerStartVPN(POVPN_DEVICE device)
 {
+    LOG_ENTER();
+
     if (InterlockedCompareExchange(&device->UserspacePid, 0, 0) == 0) {
         LOG_ERROR("Peer not added");
         return STATUS_INVALID_DEVICE_REQUEST;
     }
 
-    LOG_INFO("Start VPN");
-
     OvpnAdapterSetLinkState(OvpnGetAdapterContext(device->Adapter), MediaConnectStateConnected);
 
+    LOG_EXIT();
+
     return STATUS_SUCCESS;
 }
 
 _Use_decl_annotations_
 NTSTATUS
 OvpnPeerNewKey(POVPN_DEVICE device, WDFREQUEST request)
 {
+    LOG_ENTER();
+
     if (InterlockedCompareExchange(&device->UserspacePid, 0, 0) == 0) {
         LOG_ERROR("Peer not added");
         return STATUS_INVALID_DEVICE_REQUEST;
@@ -268,19 +285,25 @@ OvpnPeerNewKey(POVPN_DEVICE device, WDFREQUEST request)
     GOTO_IF_NOT_NT_SUCCESS(done, status, OvpnCryptoNewKey(&device->CryptoContext, cryptoData));
 
 done:
+    LOG_EXIT();
+
     return status;
 }
 
 _Use_decl_annotations_
 NTSTATUS
 OvpnPeerSwapKeys(POVPN_DEVICE device)
 {
+    LOG_ENTER();
+
     if (InterlockedCompareExchange(&device->UserspacePid, 0, 0) == 0) {
         LOG_ERROR("Peer not added");
         return STATUS_INVALID_DEVICE_REQUEST;
     }
 
     OvpnCryptoSwapKeys(&device->CryptoContext);
 
+    LOG_EXIT();
+
     return STATUS_SUCCESS;
 }
diff --git a/trace.h b/trace.h
@@ -65,6 +65,26 @@ TRACELOGGING_DECLARE_PROVIDER(g_hOvpnEtwProvider);
             __VA_ARGS__); \
 } while (0,0)
 
+#define LOG_ENTER() do {\
+        TraceLoggingWrite( \
+            g_hOvpnEtwProvider, \
+            "Info", \
+            TraceLoggingLevel(TRACE_LEVEL_INFORMATION), \
+            TraceLoggingFunctionName(), \
+            TraceLoggingUInt32(__LINE__, "Line"), \
+            TraceLoggingValue("Enter", "Msg")); \
+} while (0,0)
+
+#define LOG_EXIT() do {\
+        TraceLoggingWrite( \
+            g_hOvpnEtwProvider, \
+            "Info", \
+            TraceLoggingLevel(TRACE_LEVEL_INFORMATION), \
+            TraceLoggingFunctionName(), \
+            TraceLoggingUInt32(__LINE__, "Line"), \
+            TraceLoggingValue("Exit", "Msg")); \
+} while (0,0)
+
 #define LOG_INFO(Info, ...) do {\
         TraceLoggingWrite( \
             g_hOvpnEtwProvider, \