From 94703dca9f49e02a1b770f9149607f3d94eb41d2 Mon Sep 17 00:00:00 2001 From: Lev Stipakov Date: Thu, 2 Feb 2023 12:10:52 +0200 Subject: [PATCH] Improve logging In order to investigate "stuck on boot" issue https://github.com/OpenVPN/ovpn-dco-win/issues/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 --- Driver.cpp | 86 ++++++++++++++++++++++++++++++++++++++-- PropertySheet.props | 2 +- README.md | 20 +++++----- adapter.cpp | 4 ++ ovpn-dco-autologger.reg | Bin 0 -> 1112 bytes peer.cpp | 31 +++++++++++++-- trace.h | 20 ++++++++++ 7 files changed, 144 insertions(+), 19 deletions(-) create mode 100644 ovpn-dco-autologger.reg diff --git a/Driver.cpp b/Driver.cpp index 2b16e47..143c2c6 100644 --- a/Driver.cpp +++ b/Driver.cpp @@ -99,6 +99,8 @@ DriverEntry(_In_ PDRIVER_OBJECT driverObject, _In_ PUNICODE_STRING registryPath) } } + LOG_EXIT(); + return status; } @@ -275,9 +277,9 @@ 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); @@ -285,13 +287,15 @@ VOID OvpnEvtFileCleanup(WDFFILEOBJECT fileObject) { 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,6 +308,67 @@ 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; @@ -311,7 +376,7 @@ 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 index c264c21..0fb9732 100644 --- a/PropertySheet.props +++ b/PropertySheet.props @@ -4,7 +4,7 @@ 0 8 - 3 + 4 diff --git a/README.md b/README.md index ffb1bb2..8204d80 100644 --- 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 index 1d70240..6614170 100644 --- 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 new file mode 100644 index 0000000000000000000000000000000000000000..9dcb28c1ce5bd570efb093c66d55a513f2582c0a GIT binary patch literal 1112 zcmd6m+e!ja6o&unpm&hDDrjOnr3GEsq$O%WRuUOvo?+6^$&~Qbt8ecqu^a6wVzFlL zb=vD+hxvG~X`rFn8tGLN#dM{Pdgvw!HP#$W9_s*UgdEc?_A%B0@(?+#eR2W8NN;$+vHt{38W;b$qWgRjngs%QLN(6^8tEILPLx*_URj*j6sWmM1!RUAMbHy7I>r^hV? zx&q`{>{(rI=O*tOd@Nx=bj+>A_}xUBw|+ zk9=EJ*HMz%yTA0_S|W lWzi1x(ap3&6}w-1w`aHRH{YnD)h?8IZ3+h)x{+RP%qOd_r$Yb$ literal 0 HcmV?d00001 diff --git a/peer.cpp b/peer.cpp index 88f7326..3164b87 100644 --- 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,6 +96,8 @@ OvpnPeerNew(POVPN_DEVICE device, WDFREQUEST request) } done: + LOG_EXIT(); + return status; } @@ -101,13 +105,13 @@ _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,6 +209,7 @@ NTSTATUS OvpnPeerSet(POVPN_DEVICE device, WDFREQUEST request) } done: + LOG_EXIT(); return status; } @@ -208,6 +217,8 @@ _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,6 +244,8 @@ OvpnPeerGetStats(POVPN_DEVICE device, WDFREQUEST request, ULONG_PTR* bytesReturn *bytesReturned = sizeof(OVPN_STATS); done: + LOG_EXIT(); + return status; } @@ -240,15 +253,17 @@ _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; } @@ -256,6 +271,8 @@ _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,6 +285,8 @@ OvpnPeerNewKey(POVPN_DEVICE device, WDFREQUEST request) GOTO_IF_NOT_NT_SUCCESS(done, status, OvpnCryptoNewKey(&device->CryptoContext, cryptoData)); done: + LOG_EXIT(); + return status; } @@ -275,6 +294,8 @@ _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; @@ -282,5 +303,7 @@ OvpnPeerSwapKeys(POVPN_DEVICE device) OvpnCryptoSwapKeys(&device->CryptoContext); + LOG_EXIT(); + return STATUS_SUCCESS; } diff --git a/trace.h b/trace.h index 51f4812..6d7bb68 100644 --- 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, \