I am using FltQueueGenericWorkItem on preWrite callback to queue work item, that will log changes in some file.
I have a check there :
if (FlagOn(filterData.Flags, DATA_FLAG_PAUSED))
{
DebugTrace(DEBUG_TRACE_WARNING,
(“MyFilter!WriteChangesWorker: Write in paused state, skiping. Offset : %lld, Length: %lu\n”,
Context->ByteOffset.QuadPart,
Context->Length));
leave;
}
Now I got CLOCK_WATCHDOG_TIMEOUT (101):
An expected clock interrupt was not received on a secondary processor in an
MP system within the allocated interval. This indicates that the specified
processor is hung and not processing interrupts.
Arguments:
Arg1: 0000000000000060, Clock interrupt time out interval in nominal clock ticks.
Arg2: 0000000000000000, 0.
Arg3: ffffd00020800180, The PRCB address of the hung processor.
Arg4: 0000000000000001, 0.
Debugging Details:
BUGCHECK_STR: CLOCK_WATCHDOG_TIMEOUT_2_PROC
DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT
PROCESS_NAME: System
CURRENT_IRQL: d
ANALYSIS_VERSION: 6.3.9600.17029 (debuggers(dbg).140219-1702) amd64fre
STACK_TEXT:
fffff8023a35c4e8 fffff80238bdc7c6 : 0000000000000000 0000000000000000 fffff8023a35c650 fffff80238b01654 : nt!DbgBreakPointWithStatus
fffff8023a35c4f0 fffff80238bdc0d7 : 0000000000000003 0000000000000060 fffff80238b61070 0000000000000101 : nt!KiBugCheckDebugBreak+0x12
fffff8023a35c550 fffff80238b531a4 : fffff80238cf4180 fffff80238bc6cd7 fffff80238cf4180 00000001e0f21708 : nt!KeBugCheck2+0x8ab
fffff8023a35cc60 fffff80238b82c29 : 0000000000000101 0000000000000060 0000000000000000 ffffd00020800180 : nt!KeBugCheckEx+0x104
fffff8023a35cca0 fffff80238a7faec : 0000000000000000 0000000000000000 0000000000000000 fffff80238a03001 : nt! ?? ::FNODOBFM::string'+0x1f699 fffff8023a35cd30 fffff8023918ce5f : 0000000000000000 ffffe000012e7880 000003272cd797c7 fffff80238cf4180 : nt!KeClockInterruptNotify+0x77c fffff8023a35cf40 fffff80238a98703 : fffff802391d9900 0000000000000000 0000000000000001 0000000000000000 : hal!HalpTimerClockInterrupt+0x4f fffff8023a35cf70 fffff80238b5452a : fffff802391d9900 ffffe000012e7880 0000000000000000 ffffe000001f6040 : nt!KiCallInterruptServiceRoutine+0xa3 fffff8023a35cfb0 fffff80238b5490f : 0000000000000001 0000000000000001 ffffe000012ee010 fffff80238cf4180 : nt!KiInterruptSubDispatchNoLockNoEtw+0xea fffff8023a34ead0 fffff80238b56bc2 : fffff80238cf4180 fffff80238cf4180 fffff80238d4ca80 0000000000000000 : nt!KiInterruptDispatchLBControl+0x11f fffff8023a34ec60 0000000000000000 : fffff8023a34f000 fffff8023a349000 0000000000000000 00000000`00000000 : nt!KiIdleLoop+0x32
STACK_COMMAND: kb
SYMBOL_NAME: ANALYSIS_INCONCLUSIVE
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: Unknown_Module
IMAGE_NAME: Unknown_Image
DEBUG_FLR_IMAGE_TIMESTAMP: 0
IMAGE_VERSION:
FAILURE_BUCKET_ID: CLOCK_WATCHDOG_TIMEOUT_2_PROC_ANALYSIS_INCONCLUSIVE
BUCKET_ID: CLOCK_WATCHDOG_TIMEOUT_2_PROC_ANALYSIS_INCONCLUSIVE
ANALYSIS_SOURCE: KM
FAILURE_ID_HASH_STRING: km:clock_watchdog_timeout_2_proc_analysis_inconclusive
FAILURE_ID_HASH: {5f48d231-8e44-ce72-5515-b1876b99bd63}
Followup: MachineOwner
Arg3: ffffd00020800180 - referenced to 1st processor, here the stack:
0: kd> 1K
Child-SP RetAddr Call Site
ffffd0002301abf0 fffff80238b5491c nt!HvlEndSystemInterrupt+0x1e
ffffd0002301ac10 fffff80238bdee21 nt!KiInterruptDispatchLBControl+0x12c
ffffd0002301ada0 fffff8023905cd0b nt!KeThawExecution+0x119
ffffd0002301add0 fffff8023905ed25 nt!KdExitDebugger+0x77
ffffd0002301ae00 fffff8023905f07f nt!KdpPrint+0x121
ffffd0002301ae50 fffff80238ad166c nt!KdpTrap+0x113
ffffd0002301aea0 fffff80238b5ecc2 nt!KiDispatchException+0x610
ffffd0002301b590 fffff80238b5e333 nt!KiExceptionDispatch+0xc2
ffffd0002301b770 fffff80238b59cb5 nt!KiDebugServiceTrap+0xf3
ffffd0002301b908 fffff80238b01790 nt!DebugPrint+0x15
ffffd0002301b910 fffff80238b0161c nt!vDbgPrintExWithPrefixInternal+0x134
ffffd0002301ba10 fffff800025ce52e nt!DbgPrint+0x3c
ffffd0002301ba50 fffff8000099d59c MyFilter!WriteChangesWorker+0x13e [l:\gitrepos2\drivers - copy\myFilter.c @ 1046]
ffffd0002301bad0 fffff80238a3f3cd fltmgr!FltpProcessGenericWorkItem+0x6c
ffffd0002301bb50 fffff80238aea664 nt!ExpWorkerThread+0x2b5
ffffd0002301bc00 fffff80238b596c6 nt!PspSystemThreadStartup+0x58
ffffd0002301bc60 0000000000000000 nt!KiStartSystemThread+0x16
WriteChangesWorker+0x13e - that is:
DebugTrace(DEBUG_TRACE_WARNING,
(“MyFilter!WriteChangesWorker: Write in paused state, skiping. Offset : %lld, Length: %lu\n”,
Context->ByteOffset.QuadPart,
Context->Length));
Context->ByteOffset = 0x48181000
Context->Length = 0x1000
…
This was happens couple time(in couple monthes) on my test VM.
Can be the virtialized enviroment + intensive DebugTrace the reason?