search

OpenVPN / ovpn-dco-win

OpenVPN Data Channel Offload driver for Windows
MIT License
47 stars 22 forks source link

Memory leak caused KMDF verifier bug check on uninstall #25

Open lstipakov opened 1 year ago

lstipakov commented 1 year ago

I once managed to trigger a bug check on uninstall.

 # Child-SP          RetAddr               Call Site
00 ffffc182`daf9e258 fffff801`4a8142fa     nt!KeBugCheckEx
01 ffffc182`daf9e260 fffff801`4a7ce51f     nt!PspSystemThreadStartup$filt$0+0x44
02 ffffc182`daf9e2a0 fffff801`4a8039bf     nt!_C_specific_handler+0x9f
03 ffffc182`daf9e310 fffff801`4a677a77     nt!RtlpExecuteHandlerForException+0xf
04 ffffc182`daf9e340 fffff801`4a676676     nt!RtlDispatchException+0x297
05 ffffc182`daf9ea60 fffff801`4a80d46c     nt!KiDispatchException+0x186
06 ffffc182`daf9f120 fffff801`4a8064d0     nt!KiExceptionDispatch+0x12c
07 ffffc182`daf9f300 fffff801`4a802851     nt!KiBreakpointTrap+0x310
08 ffffc182`daf9f498 fffff801`4c9fdd5c     nt!DbgBreakPoint+0x1
09 (Inline Function) --------`--------     Wdf01000!Mx::MxDbgBreakPoint+0xc [minkernel\wdf\framework\shared\inc\primitives\km\MxGeneralKm.h @ 156] 
0a ffffc182`daf9f4a0 fffff801`4ca28493     Wdf01000!FxVerifierDbgBreakPoint+0x50 [minkernel\wdf\framework\shared\inc\private\common\fxverifier.h @ 103] 
0b ffffc182`daf9f4e0 fffff801`4ca264f2     Wdf01000!FxPoolDump+0x17b [minkernel\wdf\framework\shared\object\wdfpool.cpp @ 545] 
0c (Inline Function) --------`--------     Wdf01000!FxPoolDestroy+0x42 [minkernel\wdf\framework\shared\object\wdfpool.cpp @ 648] 
0d (Inline Function) --------`--------     Wdf01000!FxPoolPackageDestroy+0x46 [minkernel\wdf\framework\shared\object\wdfpool.cpp @ 707] 
0e ffffc182`daf9f580 fffff801`4ca236e7     Wdf01000!FxDestroy+0xa6 [minkernel\wdf\framework\shared\object\globals.cpp @ 1167] 
*** WARNING: Unable to verify timestamp for ovpn-dco.sys
0f ffffc182`daf9f5c0 fffff801`5a099682     Wdf01000!FxDriver::Unload+0xe7 [minkernel\wdf\framework\shared\core\fxdriver.cpp @ 202] 
10 ffffc182`daf9f610 ffff8d05`402ece30     ovpn_dco+0x9682
11 ffffc182`daf9f618 ffffc182`daf9f7a0     0xffff8d05`402ece30
12 ffffc182`daf9f620 00000000`c0000001     0xffffc182`daf9f7a0
13 ffffc182`daf9f628 ffffe70b`2ea45880     0xc0000001
14 ffffc182`daf9f630 00000000`00000000     0xffffe70b`2ea45880

It seems that WDF detected a leak (from wdfpool.cpp):

if (leak) {
    FxVerifierDbgBreakPoint(FxDriverGlobals);
    return STATUS_MORE_ENTRIES;
}

Normally this doesn't cause a bug check, but since I have KMDF verifier on, here we are.

I was unable to reproduce it anymore.

lstipakov commented 1 year ago

I have spent some time trying to reproduce it and monitoring pool usage with poolmon -inpvo without success - at driver removal all pool allocations are freed. Will keep an eye on it.

lstipakov commented 1 year ago

I managed to reproduce it again on the same machine while upgrading from beta2 to rc1.

1: kd> !wdfcrashdump
Retrieving crashdump log information...
Local buffer 0x000001A1C17DAB60, bufferSize 4096
Driver: ovpn-dco
Trace searchpath is: 

Trace format prefix is: %7!u!: %!FUNC! - 
Trying to extract TMF information from - c:\temp\ovpn-dco 0.8.3\signed\amd64\win10\Wdf01000.pdb\6948A828801BE167AC9E65B7605CBF611\Wdf01000.pdb
There are 94 log entries for ovpn-dco
--- start of log ---
11903: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power idle state FxIdleGoingToDx from FxIdleDisabled
11904: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power idle state FxIdleInDx from FxIdleGoingToDx
11905: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering Power State WdfDevStatePowerStopped from WdfDevStatePowerGotoD3Stopped
11906: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power policy state WdfDevStatePwrPolStoppingSendStatus from WdfDevStatePwrPolStopping
11907: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power idle state FxIdleInDxStopped from FxIdleInDx
11908: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power idle state FxIdleStopped from FxIdleInDxStopped
11909: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power policy state WdfDevStatePwrPolStopped from WdfDevStatePwrPolStoppingSendStatus
11910: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering PnP State WdfDevStatePnpRemovingDisableInterfaces from WdfDevStatePnpQueriedRemoving
11911: FxPkgIo::StopProcessingForPower - Perform FxIoStopProcessingForPowerPurgeManaged for all queues of WDFDEVICE 0x000030F06D2DDFC8
11912: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D386518 requests cancelled
11913: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D386518
11914: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D386518
11915: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D386518
11916: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D386518 Power Transition State 0x00000007(FxIoQueuePowerPurge)
11917: FxIoQueue::ProcessPowerEvents - Power purge: WDFQUEUE 0x000030F06D386518 is purging without in-flight requests
11918: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D386518 Power Transition State 0x00000008(FxIoQueuePowerPurgeNotifyingDriver)
11919: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D386518 Power Transition State 0x00000009(FxIoQueuePowerPurgeDriverNotified)
11920: FxIoQueue::ProcessPowerEvents - Power Stop: WDFQUEUE 0x000030F06D386518 is now powered off with no in-flight requests
11921: FxIoQueue::StopProcessingForPower - Waiting for all inflight requests to be acknowledged  on WDFQUEUE 0x000030F06D386518
11922: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D3A8518 requests cancelled
11923: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D3A8518
11924: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3A8518
11925: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3A8518
11926: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3A8518 Power Transition State 0x00000007(FxIoQueuePowerPurge)
11927: FxIoQueue::ProcessPowerEvents - Power purge: WDFQUEUE 0x000030F06D3A8518 is purging without in-flight requests
11928: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3A8518 Power Transition State 0x00000008(FxIoQueuePowerPurgeNotifyingDriver)
11929: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3A8518 Power Transition State 0x00000009(FxIoQueuePowerPurgeDriverNotified)
11930: FxIoQueue::ProcessPowerEvents - Power Stop: WDFQUEUE 0x000030F06D3A8518 is now powered off with no in-flight requests
11931: FxIoQueue::StopProcessingForPower - Waiting for all inflight requests to be acknowledged  on WDFQUEUE 0x000030F06D3A8518
11932: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D3CA518 requests cancelled
11933: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D3CA518
11934: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3CA518
11935: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3CA518
11936: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3CA518 Power Transition State 0x00000007(FxIoQueuePowerPurge)
11937: FxIoQueue::ProcessPowerEvents - Power purge: WDFQUEUE 0x000030F06D3CA518 is purging without in-flight requests
11938: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3CA518 Power Transition State 0x00000008(FxIoQueuePowerPurgeNotifyingDriver)
11939: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3CA518 Power Transition State 0x00000009(FxIoQueuePowerPurgeDriverNotified)
11940: FxIoQueue::ProcessPowerEvents - Power Stop: WDFQUEUE 0x000030F06D3CA518 is now powered off with no in-flight requests
11941: FxIoQueue::StopProcessingForPower - Waiting for all inflight requests to be acknowledged  on WDFQUEUE 0x000030F06D3CA518
11942: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D3EE508 requests cancelled
11943: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D3EE508
11944: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3EE508
11945: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3EE508
11946: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3EE508 Power Transition State 0x00000007(FxIoQueuePowerPurge)
11947: FxIoQueue::ProcessPowerEvents - Power purge: WDFQUEUE 0x000030F06D3EE508 is purging without in-flight requests
11948: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3EE508 Power Transition State 0x00000008(FxIoQueuePowerPurgeNotifyingDriver)
11949: FxIoQueue::DispatchEvents - WDFQUEUE 0x000030F06D3EE508 Power Transition State 0x00000009(FxIoQueuePowerPurgeDriverNotified)
11950: FxIoQueue::ProcessPowerEvents - Power Stop: WDFQUEUE 0x000030F06D3EE508 is now powered off with no in-flight requests
11951: FxIoQueue::StopProcessingForPower - Waiting for all inflight requests to be acknowledged  on WDFQUEUE 0x000030F06D3EE508
11952: FxSelfManagedIoMachine::ProcessEvent - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering self managed io state FxSelfManagedIoFlushing from FxSelfManagedIoStopped
11953: FxSelfManagedIoMachine::ProcessEvent - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering self managed io state FxSelfManagedIoFlushed from FxSelfManagedIoFlushing
11954: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power policy state WdfDevStatePwrPolStoppedRemoving from WdfDevStatePwrPolStopped
11955: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering power policy state WdfDevStatePwrPolRemoved from WdfDevStatePwrPolStoppedRemoving
11956: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering PnP State WdfDevStatePnpRemoved from WdfDevStatePnpRemovingDisableInterfaces
11957: FxChildList::NotifyDeviceRemove - WDFCHILDLIST 000030F06D323208:  removing children
11958: FxChildList::ProcessModificationsLocked - Begin processing modifications on WDFCHILDLIST 000030F06D323208
11959: FxChildList::ProcessModificationsLocked - end processing modifications on WDFCHILDLIST 000030F06D323208
11960: FxChildList::ProcessModificationsLocked - Begin processing modifications on WDFCHILDLIST 000030F06D323208
11961: FxChildList::ProcessModificationsLocked - end processing modifications on WDFCHILDLIST 000030F06D323208
11962: FxChildList::ProcessModificationsLocked - Begin processing modifications on WDFCHILDLIST 000030F06D323208
11963: FxChildList::ProcessModificationsLocked - end processing modifications on WDFCHILDLIST 000030F06D323208
11964: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering PnP State WdfDevStatePnpRemovedChildrenRemoved from WdfDevStatePnpRemoved
11965: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering PnP State WdfDevStatePnpFdoRemoved from WdfDevStatePnpRemovedChildrenRemoved
11966: FxPkgIo::StopProcessingForPower - Perform FxIoStopProcessingForPowerPurgeNonManaged for all queues of WDFDEVICE 0x000030F06D2DDFC8
11967: FxSelfManagedIoMachine::ProcessEvent - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering self managed io state FxSelfManagedIoCleanup from FxSelfManagedIoFlushed
11968: FxSelfManagedIoMachine::ProcessEvent - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering self managed io state FxSelfManagedIoFinal from FxSelfManagedIoCleanup
11969: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D3EE508 requests cancelled
11970: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D3EE508
11971: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3EE508
11972: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3EE508
11973: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D3CA518 requests cancelled
11974: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D3CA518
11975: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3CA518
11976: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3CA518
11977: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D3A8518 requests cancelled
11978: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D3A8518
11979: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3A8518
11980: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D3A8518
11981: FxIoQueue::QueuePurge - All WDFQUEUE 0x000030F06D386518 requests cancelled
11982: FxIoQueue::QueuePurge - All driver cancellable requests cancelled  in WDFQUEUE 0x000030F06D386518
11983: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D386518
11984: FxIoQueue::DispatchEvents - Thread FFFFCF0FA7AD7040 is processing WDFQUEUE 0x000030F06D386518
11985: FxPkgPnp::RemoveChildList - Removing FxChildList FFFFCF0F92CDCDF0, WDFCHILDLIST 000030F06D323208
11986: FxIoTarget::WaitForDisposeEvent - WDFIOTARGET 000030F06D538248, Waiting on Dispose event FFFFB786B99CF0E0
11987: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x000030F06D2DDFC8 !devobj 0xFFFFCF0F92ADF540 entering PnP State WdfDevStatePnpFinal from WdfDevStatePnpFdoRemoved
11988: FxPkgPnp::_PnpRemoveDevice - WDFDEVICE 000030F06D2DDFC8, !devobj FFFFCF0F92ADF540 waiting for remove event to finish processing
11989: FxPkgPnp::CleanupStateMachines - WDFDEVICE 000030F06D2DDFC8, !devobj FFFFCF0F92ADF540 waiting for pnp state machine to finish
11990: FxDevice::Destroy - Deleting !devobj FFFFCF0F92ADF540, WDFDEVICE 000030F06D2DDFC8, attached to !devobj FFFFCF0F8D1F2DA0
11991: FxPkgIo::~FxPkgIo - Destroyed FxPkgIo 0xFFFFCF0F92ACA090
11992: FxDriver::Unload - Unloading WDFDRIVER 000030F06D2F0268, PDRIVER_OBJECT_UM FFFFCF0F92C7CE30
11993: FxDriver::Unload - Driver unload routine Exit WDFDRIVER 000030F06D2F0268, PDRIVER_OBJECT_UM FFFFCF0F92C7CE30
11994: FxPoolDestroy - Destroying Pool 0xFFFFCF0F92C95E48
11995: FxPoolDump - FxPoolDump: NonPagedBytes 136, PagedBytes 0, NonPagedAllocations 1, PagedAllocations 0,PeakNonPagedBytes 33748, PeakPagedBytes 392,FxPoolDump: PeakNonPagedAllocations 131, PeakPagedAllocations 10
11996: FxPoolDump - FX_POOL 0xFFFFCF0F92C95E48 leaked non-paged memory alloc 0xFFFFCF0FB5044A50 (tracking block FFFFCF0FB5044A10)
---- end of log ----