Software Diagnostics Library » Crash Dump Patterns

10 Common Mistakes in Memory Analysis (Part 8)

Wednesday, June 16th, 2010

Yet another common mistake is not looking past the first found evidence. For example, not looking further to prove or disprove a hypothesis after finding a pattern. Let me illustrate this by a complete memory dump from a frozen system. Careful analysis of wait chains revealed a thread owning a mutant and blocking other threads from many processes:

THREAD 882e8730 Cid 0f64.2ce0 Teb: 7ff76000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable 89a76e08 SynchronizationEvent IRP List: 883fbba0: (0006,0220) Flags: 00000830 Mdl: 00000000 Not impersonating DeviceMap e1003880 Owning Process 89e264e8 Image: ProcessA.exe Attached Process N/A Image: N/A Wait Start TickCount 5090720 Ticks: 1981028 (0:08:35:53.562) Context Switch Count 8376 UserTime 00:00:00.000 KernelTime 00:00:00.015 Win32 Start Address 0×010d22a3 LPC Server thread working on message Id 10d22a3 Start Address kernel32!BaseThreadStartThunk (0×77e617ec) Stack Init b6e8b000 Current b6e8ac60 Base b6e8b000 Limit b6e88000 Call 0 Priority 10 BasePriority 10 PriorityDecrement 0 ChildEBP RetAddr b6e8ac78 8083d26e nt!KiSwapContext+0×26 b6e8aca4 8083dc5e nt!KiSwapThread+0×2e5 b6e8acec 8092cd88 nt!KeWaitForSingleObject+0×346 b6e8ad50 8083387f nt!NtWaitForSingleObject+0×9a b6e8ad50 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ b6e8ad64) 0408f910 7c827d29 ntdll!KiFastSystemCallRet 0408f914 77e61d1e ntdll!ZwWaitForSingleObject+0xc 0408f984 77e61c8d kernel32!WaitForSingleObjectEx+0xac 0408f998 027f0808 kernel32!WaitForSingleObject+0×12 0408f9bc 027588d4 DllA!DriverB_DependentFunction+0×86 […] 0408ffec 00000000 kernel32!BaseThreadStart+0×34

So we did found a culprit component, DllA, or not? Could this blockage result from earlier problems? We search stack trace collection for any other anomalous activity (Semantic Split) and we find indeed a recurrent stack trace pattern across process landscape:

THREAD 89edadb0 Cid 09fc.1050 Teb: 7ff54000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable 8a38b82c SynchronizationEvent IRP List: 893a7470: (0006,0094) Flags: 00000000 Mdl: 00000000 Not impersonating DeviceMap e16dc398 Owning Process 8a2ad5e0 Image: ProcessB.exe Attached Process N/A Image: N/A Wait Start TickCount 3704877 Ticks: 3366871 (0:14:36:47.359) Context Switch Count 121867 UserTime 00:00:25.093 KernelTime 00:00:01.968 Win32 Start Address MSVCR71!_threadstartex (0×7c3494f6) Start Address kernel32!BaseThreadStartThunk (0×77e617ec) Stack Init f3a9c000 Current f3a9b548 Base f3a9c000 Limit f3a99000 Call 0 Priority 8 BasePriority 8 PriorityDecrement 0 ChildEBP RetAddr f3a9b560 8083d26e nt!KiSwapContext+0×26 f3a9b58c 8083dc5e nt!KiSwapThread+0×2e5 f3a9b5d4 f6866255 nt!KeWaitForSingleObject+0×346 f3a9b5f4 f68663e3 DriverA!Block+0×1b f3a9b604 f5ba05f1 DriverA!BlockWithTracker+0×19 f3a9b634 f5b9ba24 DriverB!DoRequest+0xc2 f3a9b724 f5b9b702 DriverB!QueryInfo+0×392 […]

0: kd> !irp 893a7470 Irp is active with 1 stacks 1 is current (= 0×893a74e0) No Mdl: No System Buffer: Thread 89edadb0: Irp stack trace. cmd flg cl Device File Completion-Context >[ e, 0] 0 1 8a216f18 8a023f70 00000000-00000000 pending \Driver\DriverB Args: 0000015c 00000024 00120003 111af32c

We know that DllA!DriverB_DependentFunction will not work if DriverB device doesn’t function (for example, remote file system access without network access). The thread 89edadb0 had been waiting for more 14 hours and the originally found thread 882e8730 was waiting for less than 9 hours. This suggests looking first into DriverB / DriverA functions first.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Common Mistakes, Complete Memory Dump Analysis, Crash Dump Analysis, Crash Dump Patterns, Debugging | No Comments »

Icons for Memory Dump Analysis Patterns (Part 47)

Monday, June 14th, 2010

Today we introduce an icon for Coupled Processes (strong) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

IRP distribution anomaly, inconsistent dump, execution residue, hardware activity, coincidental symbolic information, not my version, virtualized system: pattern cooperation

Monday, June 7th, 2010

It was reported that a system had an abnormally high number of interrupt activity visible in various monitoring tools. A complete memory dump was collected. When we open it and look at an IRP list we find statistically higher number of IRPs belonging to Disk and DriverA device drivers:

0: kd> !irpfind Irp [ Thread ] irpStack: (Mj,Mn) DevObj [Driver] MDL Process […] 8a3d3008 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000 8a3d3340 [8acab888] irpStack: ( 3, 0) 8b4c6030 [ \FileSystem\Npfs] 8a3d4580 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000 8a403e00 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000 8a4047e0 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000 […] 8aa6ab28 [00000000] irpStack: ( f, 0) 8b192030 [ \Driver\DriverA] 0×00000000 8aa6ce28 [00000000] irpStack: ( f, 0) 8b192030 [ \Driver\DriverA] 0×00000000 […]

What we also notice is that the thread 8b56cb10 is also an active running thread so we look at its raw stack to find any executon residue providing hints to possible hardware activity.

0: kd> !stacks Proc.Thread .Thread Ticks ThreadState Blocker [8b57f7a8 System] 4.000070 8b579db0 ffffff42 Blocked +0x1 4.0000c0 8b5768d0 ffffff42 READY nt!KiAdjustQuantumThread+0x109 4.0000e4 8b56cb10 ffffff42 RUNNING +0xf6fb2044 […]

0: kd> !thread 8b56cb10 THREAD 8b56cb10 Cid 0004.00e4 Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0 Not impersonating DeviceMap e10018b8 Owning Process 8b57f7a8 Image: System Attached Process N/A Image: N/A Wait Start TickCount 24437735 Context Switch Count 33644 UserTime 00:00:00.000 KernelTime 00:00:07.843 Start Address nt!MiMappedPageWriter (0x80847ffe) Stack Init f70c4000 Current f70c3468 Base f70c4000 Limit f70c1000 Call 0 Priority 17 BasePriority 8 PriorityDecrement 0 ChildEBP RetAddr Args to Child f70c3470 00000000 000000be e1912bc0 e1912bc4 0xf6fb2044

However, WinDbg reports another current thread running on the same processor so we obviously have an inconsistent dump and should exercise caution:

0: kd> !thread THREAD 8089d8c0 Cid 0000.0000 Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0 Not impersonating Owning Process 8089db40 Image: Idle Attached Process N/A Image: N/A Wait Start TickCount 24437476 Ticks: 69 (0:00:00:01.078) Context Switch Count 72194391 UserTime 00:00:00.000 KernelTime 4 Days 08:57:56.171 Stack Init 8089a8b0 Current 8089a5fc Base 8089a8b0 Limit 808978b0 Call 0 Priority 0 BasePriority 0 PriorityDecrement 0 ChildEBP RetAddr Args to Child f3b30c5c 00000000 00000000 00000000 00000000 LiveKdD+0×1c07

0: kd> !running [...] Prcbs Current Next 0 ffdff120 8089d8c0 ……………. 1 f772f120 f7732090 …………….

0: kd> !thread f7732090 THREAD f7732090 Cid 0000.0000 Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 1 Not impersonating Owning Process 8089db40 Image: Idle Attached Process N/A Image: N/A Wait Start TickCount 0 Ticks: 24437545 (4:10:03:56.640) Context Switch Count 75624870 UserTime 00:00:00.000 KernelTime 4 Days 08:56:05.125 Stack Init f78b3000 Current f78b2d4c Base f78b3000 Limit f78b0000 Call 0 Priority 0 BasePriority 0 PriorityDecrement 0 ChildEBP RetAddr Args to Child f3b30c5c 00000000 00000000 00000000 00000000 LiveKdD+0×1c07

Let’s come back to the thread 8b56cb10. Its raw stack residue shows traces of SCSI activity:

0: kd> dps f70c1000 f70c4000 [...] f70c2f38 8b20100c f70c2f3c f70c2f9c f70c2f40 f72922a5 DriverA!BuildScatterGather+0×9b f70c2f44 8b20100c f70c2f48 8aa24dfc […] f70c337c 00000000 f70c3380 00000246 f70c3384 808a6228 nt!KiProcessorBlock+0×8 f70c3388 00000002 f70c338c 00000011 f70c3390 00000246 f70c3394 f70c33a4 f70c3398 80a62a73 hal!HalRequestIpi+0×13 f70c339c 00000002 f70c33a0 000000e1 f70c33a4 f70c33dc f70c33a8 8082e4db nt!KiIpiSend+0×27 f70c33ac 00000002 f70c33b0 f772fa7c f70c33b4 8b56bdb0 f70c33b8 ffdff120 f70c33bc 00000000 f70c33c0 00000002 f70c33c4 00000001 f70c33c8 00000000 f70c33cc 00000002 f70c33d0 00000002 f70c33d4 f70c33e4 f70c33d8 80a61456 hal!KfLowerIrql+0×62 f70c33dc 00000001 f70c33e0 00000002 f70c33e4 f70c3494 f70c33e8 f70c3450 f70c33ec 8b56cb10 f70c33f0 8b089100 f70c33f4 8a5abe01 f70c33f8 f70c3450 f70c33fc 8b089100 f70c3400 8a5abe01 f70c3404 8b089101 f70c3408 f70c3418 f70c340c 80a61456 hal!KfLowerIrql+0×62 f70c3410 8a5abe98 f70c3414 8b089101 f70c3418 f70c3450 f70c341c f70c3434 f70c3420 80819c10 nt!FsFilterPerformCompletionCallbacks+0×2e f70c3424 f70c3450 f70c3428 00000000 f70c342c 00000000 f70c3430 00000000 f70c3434 f70c3584 f70c3438 f70c3584 f70c343c 80815040 nt!FsRtlReleaseFileForModWrite+0×190 f70c3440 f70c3450 f70c3444 8b56cdc4 f70c3448 00010000 f70c344c 8b56cd68 f70c3450 00000024 f70c3454 8b56cbfc f70c3458 8abe10f0 f70c345c 8a5b4830 f70c3460 8b089100 f70c3464 80a613f4 hal!KfLowerIrql f70c3468 00000001 f70c346c 00000246 f70c3470 f6fb2044 f70c3474 00000000 f70c3478 000000be f70c347c e1912bc0 f70c3480 e1912bc4 f70c3484 8a4b7db8 f70c3488 00000011 f70c348c f70c34a4 f70c3490 8081610e nt!FsRtlLookupBaseMcbEntry+0×16 f70c3494 80887b75 nt!KiFlushTargetSingleTb+0xd f70c3498 f70c34d0 f70c349c 8082e431 nt!KiIpiServiceRoutine+0×4d f70c34a0 f772f121 f70c34a4 00000000 f70c34a8 e2894000 f70c34ac 00000000 f70c34b0 80872322 nt!WRITE_REGISTER_ULONG+0xa f70c34b4 8b20100c f70c34b8 80a6157e hal!HalEndSystemInterrupt+0×6e f70c34bc 8b20100c f70c34c0 f70c34d0 f70c34c4 80a5e902 hal!HalpIpiHandler+0xd2 f70c34c8 80816209 nt!FsRtlLookupLargeMcbEntry+0×4d f70c34cc 000000e1 f70c34d0 f70c3564 f70c34d4 80872322 nt!WRITE_REGISTER_ULONG+0xa f70c34d8 badb0d00 f70c34dc f6fb2040 f70c34e0 8b20100c f70c34e4 8b038fb4 f70c34e8 0000f000 f70c34ec f70c3510 f70c34f0 8b377e10 f70c34f4 8b20100c f70c34f8 8b038fb4 f70c34fc 00000000 f70c3500 00000000 f70c3504 8b377e64 f70c3508 00000007 f70c350c f6fb2040 f70c3510 8b201100 f70c3514 0b377e10 f70c3518 00000005 f70c351c ffdff120 f70c3520 ffdffa40 f70c3524 8b4eca09 f70c3528 8b20100c f70c352c ffdffa40 f70c3530 8b4eca09 f70c3534 ffdffa09 f70c3538 f70c3548 f70c353c 80a61456 hal!KfLowerIrql+0×62 f70c3540 8b4ecab4 f70c3544 ffdffa09 f70c3548 f70c356c f70c354c 80829f70 nt!KeInsertQueueDpc+0×1c4 f70c3550 8b4ecaf8 f70c3554 8b038fb4 f70c3558 8b192001 f70c355c ffdffa48 f70c3560 ffdff120 f70c3564 00000000 f70c3568 01092855 f70c356c f70c3580 f70c3570 f727221d SCSIPORT!SpRequestCompletionDpc+0×2d f70c3574 014ecab4 f70c3578 8b4ecab8 f70c357c 8b4ecaf8 f70c3580 8b4ecbf8 f70c3584 00000102 f70c3588 8b4eca40 f70c358c 8b4ecaf8 f70c3590 8b4ecbf8 f70c3594 8b038f02 f70c3598 f70c35a8 f70c359c 8b4ecbf8 f70c35a0 8b038f02 f70c35a4 8b4ecb02 f70c35a8 f70c35b8 f70c35ac 80a61456 hal!KfLowerIrql+0×62 f70c35b0 8b038f02 f70c35b4 8b4ecb02 f70c35b8 f70c35d8 f70c35bc 80a5f44b hal!KfReleaseSpinLock+0xb f70c35c0 f72737ae SCSIPORT!SpReceiveScatterGather+0×33b f70c35c4 8b56bb94 f70c35c8 00000000 f70c35cc 0cd8e000 f70c35d0 0000000f f70c35d4 0000000f f70c35d8 f70c3604 f70c35dc 80a60147 hal!HalBuildScatterGatherList+0×1c7 f70c35e0 8b4eca40 f70c35e4 8a5acd20 f70c35e8 8ab7aa98 f70c35ec 8ab7aa30 f70c35f0 8a5acd20 f70c35f4 8b4ecaf8 f70c35f8 8b038fb4 f70c35fc 00804001 f70c3600 00000000 f70c3604 f70c3650 f70c3608 f72733a6 SCSIPORT!ScsiPortStartIo+0×36a f70c360c 8ab7aa98 f70c3610 8b4eca40 f70c3614 8b56bb38 f70c3618 00000000 f70c361c 00010000 f70c3620 f72736b4 SCSIPORT!SpReceiveScatterGather f70c3624 8ab7aa30 f70c3628 00000000 f70c362c 8b4eca40 f70c3630 8a5acd20 f70c3634 00000002 f70c3638 8b4eca40 f70c363c f70c39e0 f70c3640 f70c3658 f70c3644 00000000 f70c3648 80a611ae hal!HalpDispatchSoftwareInterrupt+0×5e f70c364c 00000000 f70c3650 8a5acd00 f70c3654 00000202 f70c3658 f70c3674 f70c365c 80a613d9 hal!HalpCheckForSoftwareInterrupt+0×81 f70c3660 8b4ecb02 f70c3664 00000000 f70c3668 8b1920e8 f70c366c 8a5acd00 f70c3670 8b4ecb02 f70c3674 f70c3684 f70c3678 80a61456 hal!KfLowerIrql+0×62 f70c367c 8a5acd20 f70c3680 8b4ecb00 f70c3684 f70c36a8 f70c3688 f7273638 SCSIPORT!ScsiPortFdoDispatch+0×279 f70c368c 8b4ecaf8 f70c3690 8b41a228 f70c3694 8a5acd20 f70c3698 f70c36d0 f70c369c f70c36ac f70c36a0 8ab7aa30 f70c36a4 8b1920e8 f70c36a8 f70c36c4 f70c36ac f7273146 SCSIPORT!SpDispatchRequest+0×68 f70c36b0 8b4eca40 f70c36b4 005acdb4 f70c36b8 8b038fb4 f70c36bc 8b1920e8 f70c36c0 8a5acd20 f70c36c4 f70c36e0 f70c36c8 f7272dc3 SCSIPORT!ScsiPortPdoScsi+0×129 f70c36cc 8b1920e8 f70c36d0 8a5acd20 f70c36d4 8a581008 f70c36d8 8a5acd20 f70c36dc 8b192030 f70c36e0 f70c36f4 f70c36e4 f7272299 SCSIPORT!ScsiPortGlobalDispatch+0×1d f70c36e8 8b192030 f70c36ec 8a5acd20 f70c36f0 8b5441c8 f70c36f4 f70c3708 f70c36f8 8081df85 nt!IofCallDriver+0×45 f70c36fc 8b192030 f70c3700 8a5acd20 f70c3704 8b038f08 f70c3708 f70c3718 f70c370c f725f607 CLASSPNP!SubmitTransferPacket+0xbb f70c3710 8b038f08 f70c3714 00000000 f70c3718 f70c374c f70c371c f725f2b2 CLASSPNP!ServiceTransferRequest+0×1e4 f70c3720 8b038f08 f70c3724 8b1b80e8 f70c3728 8a581150 f70c372c 8a581008 f70c3730 24052000 f70c3734 00000001 f70c3738 00000001 f70c373c 00011000 f70c3740 00010000 f70c3744 00000000 f70c3748 00000001 f70c374c f70c3770 f70c3750 f725f533 CLASSPNP!ClassReadWrite+0×159 f70c3754 00000103 f70c3758 00000000 f70c375c 8a581008 f70c3760 8b57e218 f70c3764 8b055790 f70c3768 8b192030 f70c376c 00010000 f70c3770 f70c3784 f70c3774 8081df85 nt!IofCallDriver+0×45 f70c3778 8b1b8030 f70c377c 00000103 f70c3780 8b51d1c8 f70c3784 f70c3794 f70c3788 f74c80cf PartMgr!PmReadWrite+0×95 f70c378c 8b467e00 f70c3790 8a581174 f70c3794 f70c37a8 f70c3798 8081df85 nt!IofCallDriver+0×45 f70c379c 8b0556d8 f70c37a0 8a581008 f70c37a4 8a581198 f70c37a8 f70c37c4 f70c37ac f7317053 ftdisk!FtDiskReadWrite+0×1a9 f70c37b0 8a5811b4 f70c37b4 8b5570c8 f70c37b8 8b201c40 f70c37bc 24032000 f70c37c0 8b467d48 f70c37c4 f70c37d8 f70c37c8 8081df85 nt!IofCallDriver+0×45 f70c37cc 8b467d48 f70c37d0 8a581008 f70c37d4 8a5811d8 f70c37d8 f70c37f8 f70c37dc f72c0537 volsnap!VolSnapWrite+0×46f f70c37e0 8a581008 f70c37e4 8b5851c8 f70c37e8 e25b3668 f70c37ec fd800000 f70c37f0 8b201c40 f70c37f4 00000002 f70c37f8 f70c380c f70c37fc 8081df85 nt!IofCallDriver+0×45 f70c3800 8b201b88 f70c3804 8a581008 […]

There’s past DPC insertion activity but no pending DPCs:

0: kd> ub 80829f70 nt!KeInsertQueueDpc+0x1a9: 80829f55 6a02 push 2 80829f57 5a pop edx 80829f58 e857450000 call nt!KiIpiSend (8082e4b4) 80829f5d eb08 jmp nt!KeInsertQueueDpc+0x1bb (80829f67) 80829f5f b102 mov cl,2 80829f61 ff1598108080 call dword ptr [nt!_imp_HalRequestSoftwareInterrupt (80801098)] 80829f67 8a4dfe mov cl,byte ptr [ebp-2] 80829f6a ff1508118080 call dword ptr [nt!_imp_KfLowerIrql (80801108)]

0: kd> !dpcs CPU Type KDPC Function

dpcs: no pending DPCs found

We notice DriverA and see it also attached to Disk driver device:

0: kd> !irp 8a3d3008 Irp is active with 11 stacks 7 is current (= 0x8a3d3150) Mdl=8b56b6a0: No System Buffer: Thread 8b56cb10: Irp stack trace. cmd flg cl Device File Completion-Context [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 >[ 4,34] 0 e0 8b1b8030 00000000 f74c857e-8b0556d8 Success Error Cancel \Driver\Disk PartMgr!PmIoCompletion Args: 00010000 00000000 f457e000 00000002 [ 4, 0] 0 e1 8b0556d8 00000000 f7316558-8b467e00 Success Error Cancel pending \Driver\PartMgr ftdisk!FtpRefCountCompletionRoutine Args: 7274c6df 0002b74c f457e000 00000002 [ 4, 0] 0 e1 8b467d48 00000000 f72bf638-8b201c40 Success Error Cancel pending \Driver\Ftdisk volsnap!VspRefCountCompletionRoutine Args: 7274c5f4 0002b74c f456e000 00000002 [ 4, 0] 0 e1 8b201b88 00000000 f71814e8-8b206238 Success Error Cancel pending \Driver\VolSnap Ntfs!NtfsSingleAsyncCompletionRoutine Args: 00010000 00000000 f456e000 00000002 [ 4, 0] 0 0 8b36b020 8a5b4830 00000000-00000000 \FileSystem\Ntfs Args: 00010000 00000000 08710000 00000000

0: kd> !devobj 8b1b8030 Device object (8b1b8030) is for: DR0 \Driver\Disk DriverObject 8b57e218 Current Irp 00000000 RefCount 0 Type 00000007 Flags 00000050 Vpb 8b52f080 Dacl e13e397c DevExt 8b1b80e8 DevObjExt 8b1b8548 Dope 8b467828 ExtensionFlags (0000000000) AttachedDevice (Upper) 8b0556d8 \Driver\PartMgr AttachedTo (Lower) 8b192030 \Driver\DriverA Device queue is not busy.

0: kd> !devstack 8b1b8030 !DevObj !DrvObj !DevExt ObjectName 8b0556d8 \Driver\PartMgr 8b055790 > 8b1b8030 \Driver\Disk 8b1b80e8 DR0 8b192030 \Driver\DriverA 8b1920e8 DriverA1Port1Path0Target0Lun0 !DevNode 8b56f5d0 : DeviceInst is “SCSI\Disk&Ven_A&Prod_Virtual_disk&Rev_1.0\4&1588251b&0&000″ ServiceName is “disk”

Additionally we look at raw stack data of running threads 8089d8c0 and f7732090. We find the same hardware activity there and plus some network driver activity too. We also see “double fault” symbols:

[...] 8089a554 ffdffec0 8089a558 80a6157e hal!HalEndSystemInterrupt+0x6e 8089a55c ffdffec0 8089a560 8089a570 nt!KiDoubleFaultStack+0×2cc0 8089a564 80a5e902 hal!HalpIpiHandler+0xd2 8089a568 00000002 8089a56c 000000e1 8089a570 8089a600 nt!KiDoubleFaultStack+0×2d50 8089a574 f7549ca2 intelppm!AcpiC1Idle+0×12 8089a578 badb0d00 8089a57c 0002b74b 8089a580 00000000 8089a584 f7298da0 DriverA!DevScsiTimer 8089a588 00000000 8089a58c 00000000 8089a590 0005d373 8089a594 00000000 8089a598 8b4ecaf8 8089a59c 00000000 8089a5a0 8a4b1e20 8089a5a4 00000000 8089a5a8 8089a600 nt!KiDoubleFaultStack+0×2d50 8089a5ac 0002b74b 8089a5b0 ffdffee0 […]

But they seem to be coincidental:

0: kd> ub 8089a570 ^ Unable to find valid previous instruction for 'ub 8089a570'

0: kd> u 8089a570 nt!KiDoubleFaultStack+0x2cc0: 8089a570 00a68980a29c add byte ptr [esi-635D7F77h],ah 8089a576 54 push esp 8089a577 f7000ddbba4b test dword ptr [eax],4BBADB0Dh 8089a57d b702 mov bh,2 8089a57f 0000 add byte ptr [eax],al 8089a581 0000 add byte ptr [eax],al 8089a583 00a08d29f700 add byte ptr [eax+0F7298Dh],ah 8089a589 0000 add byte ptr [eax],al

0: kd> ub 8089a600 ^ Unable to find valid previous instruction for 'ub 8089a600'

0: kd> u 8089a600 nt!KiDoubleFaultStack+0x2d50: 8089a600 0100 add dword ptr [eax],eax 8089a602 0000 add byte ptr [eax],al 8089a604 ebde jmp nt!KiDoubleFaultStack+0x2d34 (8089a5e4) 8089a606 888000000000 mov byte ptr [eax],al 8089a60c 0e push cs 8089a60d 0000 add byte ptr [eax],al 8089a60f 0000 add byte ptr [eax],al 8089a611 0000 add byte ptr [eax],al

We find the system virtualized:

0: kd> !sysinfo machineid [...] SystemManufacturer = Virtualization Vendor A [...]

Looking at DriverA timestamp we notice it is much older than expected and Google search points to similar cases (but not for virtualized systems) where it was recommended to update that driver.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Complete Memory Dump Analysis, Crash Dump Analysis, Crash Dump Patterns | 2 Comments »

Crash Dump Analysis AntiPatterns (Part 14)

Friday, June 4th, 2010

An exercise in de-analysis

This anti-pattern is called Wild Explanation. This is a free floating explanation based on loose associations. Its extreme version uses Gödel incompleteness theorems (undecidable crashes and hangs), quantum mechanics (in small time delta any bug can appear and disappear without being caught) or hydrodynamics (code fluidity, turbulence around processor cores) for abnormal software behaviour explanation (similar to Fashionable Nonsense in philosophy, humanities and social sciences). Its milder version is slightly modified original analysis monologue I found when searching Google for stack traces (I provide my comments below):

“Two hints make me assume this can be a physical memory problem:”

PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by try-except,
it must be protected by a Probe. Typically the address is just plain bad or it
is pointing at freed memory.
Arguments:
Arg1: e37cc20e, memory referenced.
Arg2: 00000001, value 0 = read operation, 1 = write operation.
Arg3: 8083fe2c, If non-zero, the instruction address which referenced the bad memory
address.
Arg4: 00000000, (reserved)

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at “0x%08lx” referenced memory at “0x%08lx”. The memory could not be “%s”.

I wouldn’t be so quick. Check Hardware Error pattern post and comments there. So let’s de-analyze the analysis.

“c0000005 is Access Denied where C is virtual memory, meaning usually disk cache”

c is just STATUS_SEVERITY_ERROR (0×3 or 0y11) 11000000000000000000000000000101 and doesn’t have any connection to cache or crash beyond a mere coincidence. See NTSTATUS bit descriptions: http://msdn.microsoft.com/en-us/library/cc231200(PROT.10).aspx

“It could be RAM and/or it could be savrt.sys if you’re using something like an antivirus.
Check to see if you need updates for them, Norton, Symantec, McCaffee.”

Of course, it is either RAM or antivirus, what else? What about a virus? All household names.

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at “0x%08lx” referenced memory at “0x%08lx”. ”The memory could not be “%s”.” means there is something wrong with the debugger itself; those should be addresses, not percent signs and alphanumeric garbage.”

Now even a debugger is corrupt. RAM again? It is not a garbage, they’re format codes (like for printf C function) to print actual addresses.

“8083fe2c” this address called a pointer, that referenced “e37cc20e” again, that “e” has specific meaning, some virtual device or another, probably CD ROM, trying to transfer data to RAM. This implies either SCSI or PCI buss or DMA buss timing problems.”

RAM again… Evidence mounts stronger and stronger. Its all about timing. A bus buzzes.

“Which is usually caused by a bad driver, not RAM, but sometimes replacing the RAM “masks” out the failure.”

You never know… A bit of doubt?

“This normally happens with 64-bit machines that take advantage of the 64-bit superfast address access and indexing, known as Vector Indirect Addressing, which is, apparently, too fast for even recent Operating System code.”

I always suspected these machines run x64 times faster… I can only imagine horrors when Vector Indirect Addressing hits an old Operating System code. However, the crash under discussion is x86…

“A write to the “e” device; so, is it some kind of CDR or DVDR or other storage device?”

I guess that was a rhetorical question… or let me finish this thread of thought to connect dots, e-devices, virtual memory, disk cache and CD ROM. What if a page file was configured on a DVD-R?

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in AntiPatterns, Crash Dump Analysis, Crash Dump De-analysis, Crash Dump Patterns, Fun with Crash Dumps, Software Technical Support | No Comments »

Icons for Memory Dump Analysis Patterns (Part 46)

Friday, June 4th, 2010

Today we introduce an icon for Stack Trace Collection pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

Succession of Patterns (Part 2)

Thursday, June 3rd, 2010

Now I resume previously introduced memory analysis succession patterns post series. In this part I introduce a case study where Wait Chains (executive resources) and Swarm of Shared Locks were probably resulted from a Spiking Thread. We have these resource locks:

0: kd> !locks **** DUMP OF ALL RESOURCE OBJECTS ****

Resource @ 0x808a6860 Shared 9 owning threads Threads: 8e739b40-01<*> 8e07db58-01<*> 8e455d18-01<*> 8df72958-01<*> 8e356620-01<*> 8d7e9700-01<*> 8e73a660-01<*> 8dbb0af0-01<*> 8e01c9b8-01<*>

Resource @ 0xf7b6d5b0 Shared 2 owning threads Contention Count = 1 Threads: 8e741898-01<*> 8e73fb40-01<*>

Resource @ 0x8e5a1534 Shared 12 owning threads Contention Count = 76 NumberOfSharedWaiters = 7 NumberOfExclusiveWaiters = 1 Threads: 8e73fb40-01 8d80fc70-01<*> 8dc226c0-01<*> 8dc84db0-01<*> 8e416458-01<*> 8dbf1630-01<*> 8e740db0-01<*> 8d7e9700-01<*> 8d818420-01<*> 8e7413b8-01<*> 8e739020-01 8d80ac70-01<*> 8e30ec88-01<*> 8e7408d0-01 8dd022a8-01 8e59a2f8-01 8dc4d300-01 8dc36278-01<*> 8e060078-01 Threads Waiting On Exclusive Access: 8d818870

Resource @ 0x8e5a1368 Shared 3 owning threads Contention Count = 132 NumberOfExclusiveWaiters = 9 Threads: 8d7c5370-01<*> 8e416458-01<*> 8e72f480-01<*> Threads Waiting On Exclusive Access: 8d7e9700 8d80ac70 8e741b08 8dc84db0 8df72958 8e73e8d0 8dbe0388 8e7413b8 8e741898

Resource @ 0x8e74a3b0 Exclusively owned Contention Count = 11 NumberOfSharedWaiters = 2 NumberOfExclusiveWaiters = 1 Threads: 8dbe0388-01<*> 8e73e660-01 8e740020-01 Threads Waiting On Exclusive Access: 8d80fc70

Resource @ 0x8e54f810 Exclusively owned Contention Count = 118 NumberOfSharedWaiters = 1 NumberOfExclusiveWaiters = 2 Threads: 8e72f480-01<*> 8e73f8d0-01 Threads Waiting On Exclusive Access: 8d7c5370 8e416458

Resource @ 0x8e6db008 Shared 1 owning threads Threads: 8e73f8d0-01<*>

Resource @ 0x8e75e3c0 Exclusively owned Threads: 8d7e9700-01<*>

Resource @ 0x8e6f14b0 Exclusively owned Contention Count = 7 NumberOfSharedWaiters = 2 Threads: 8d80fc70-01<*> 8dbf1630-01 8e73f3f0-01

Resource @ 0x8e707618 Exclusively owned Threads: 8dc84db0-01<*>

Resource @ 0x8e6c1780 Shared 1 owning threads Contention Count = 3 NumberOfSharedWaiters = 1 NumberOfExclusiveWaiters = 1 Threads: 8e741b08-01<*> 8e73fdb0-01 Threads Waiting On Exclusive Access: 8dc36278

Resource @ 0x8e1fa370 Exclusively owned Threads: 8df72958-01<*>

Resource @ 0x8e290b38 Exclusively owned Threads: 8df72958-01<*>

Resource @ 0x8e692be0 Shared 1 owning threads Contention Count = 12 Threads: 8df72958-01<*>

Resource @ 0x8e3a03e0 Exclusively owned Contention Count = 4 NumberOfSharedWaiters = 1 NumberOfExclusiveWaiters = 1 Threads: 8dbe0388-01<*> 8e740660-01 Threads Waiting On Exclusive Access: 8e30ec88

Resource @ 0x8e33d6a8 Exclusively owned Contention Count = 1 Threads: 8dc36278-01<*>

Resource @ 0x8e33d640 Exclusively owned Contention Count = 1 Threads: 8dc36278-01<*>

Resource @ 0x8e17f890 Exclusively owned Contention Count = 2 NumberOfExclusiveWaiters = 1 Threads: 8dc84db0-01<*> Threads Waiting On Exclusive Access: 8e740db0

Resource @ 0x8e17f828 Exclusively owned Threads: 8dc84db0-01<*>

Resource @ 0x8e09fc40 Exclusively owned Contention Count = 3 NumberOfSharedWaiters = 2 Threads: 8e416458-01<*> 8e076770-01 8dbf5b70-01

Resource @ 0x8e09fbd8 Exclusively owned Threads: 8e416458-01<*>

Resource @ 0x8df021a0 Exclusively owned Threads: 8d7e9700-01<*>

Resource @ 0x8dffce50 Exclusively owned Contention Count = 2 NumberOfExclusiveWaiters = 1 Threads: 8dbf1630-01<*> Threads Waiting On Exclusive Access: 8dc226c0

Resource @ 0x8df147f8 Exclusively owned Contention Count = 4 NumberOfSharedWaiters = 1 Threads: 8dbf1630-01<*> 8e7403f0-01

Resource @ 0x8e599de8 Exclusively owned Threads: 8d7c5370-01<*>

Resource @ 0x8e324ee8 Shared 1 owning threads Contention Count = 1 Threads: 8d7c5370-01<*>

Resource @ 0x8e21bc60 Exclusively owned Threads: 8dbe0388-01<*>

Resource @ 0x8e446f18 Exclusively owned Threads: 8d80fc70-01<*>

Resource @ 0x8df65570 Shared 1 owning threads Contention Count = 3 Threads: 8dc5f698-01<*>

Resource @ 0x8e085100 Exclusively owned Contention Count = 1 Threads: 8e73e8d0-01<*>

Resource @ 0x8dbe51b8 Exclusively owned Threads: 8dbe0388-01<*>

Resource @ 0x8df458c8 Exclusively owned Contention Count = 1 NumberOfExclusiveWaiters = 1 Threads: 8d80ac70-01<*> Threads Waiting On Exclusive Access: 8d818420

Resource @ 0x8dfb9168 Shared 2 owning threads Threads: 8e7413b8-01<*> 8d862630-01<*>

Resource @ 0x8dfb9128 Exclusively owned Contention Count = 1 Threads: 8e7413b8-01<*>

Resource @ 0x8df86150 Shared 1 owning threads Threads: 8dba25d8-01<*>

Resource @ 0x8df86110 Exclusively owned Threads: 8e741b08-01<*>

Resource @ 0x8e3f17d0 Shared 1 owning threads Threads: 8dc84db0-01<*>

Resource @ 0x8dc9c008 Exclusively owned Threads: 8e72f480-01<*>

Resource @ 0x8dc9c1a8 Shared 1 owning threads Threads: 8e72f480-01<*>

Resource @ 0x8e3ec7a0 Shared 1 owning threads Threads: 8e7413b8-01<*>

Resource @ 0x8d85a218 Exclusively owned Threads: 8d80fc70-01<*>

Resource @ 0x8e2d1988 Shared 1 owning threads Threads: 8d7c5370-01<*>

Resource @ 0x8e3f1ac0 Shared 1 owning threads Threads: 8e416458-01<*>

Resource @ 0x8dc11798 Exclusively owned Contention Count = 1 Threads: 8e73f8d0-01<*>

Resource @ 0x8dc93298 Exclusively owned Threads: 8e73f8d0-01<*>

Resource @ 0x8e2bb198 Shared 1 owning threads Contention Count = 1 Threads: 8d80ac70-01<*>

Resource @ 0x8e06e6f8 Shared 1 owning threads Threads: 8e72f480-01<*>

4346 total locks, 47 locks currently held

We don’t see High Contention (executive resources) pattern. What we actually see is a runaway system thread:

0: kd> !running

System Processors f (affinity mask) Idle Processors d

Prcbs Current Next 1 f772f120 8e72f480 …………….

0: kd> !thread 8e72f480 THREAD 8e72f480 Cid 0004.00e4 Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 1 Not impersonating DeviceMap d66018c0 Owning Process 8e7437a8 Image: System Attached Process N/A Image: N/A Wait Start TickCount 78418 Ticks: 919192 (0:03:59:22.375) Context Switch Count 240 UserTime 00:00:00.000 KernelTime 03:59:29.203 Start Address 0×80848dbc Stack Init b2f94000 Current b2f93584 Base b2f94000 Limit b2f91000 Call 0 Priority 17 BasePriority 8 PriorityDecrement 0 ChildEBP RetAddr Args to Child [..] b2f93a14 f7b4dae0 8d802108 d78220d0 b2f93be8 ModuleA!bar+0×2a0 b2f93c14 f7b527d0 8d802108 8e28d218 8e574860 ModuleA!foo+0×1e27 […] b2f93ddc 8088fa7e 80848dbc 00000000 00000000 nt!PspSystemThreadStartup+0×2e 00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0×16

I highlighted in red this thread in the output of !locks command above. Many wait chains terminate at this thread (an example one is highlighted in blue above, 8d818870 -> 8d80fc70 -> 8dbe0388 -> 8e72f480). Stack trace collection shows ModuleA on top of stack traces of many threads (!stacks 0 ModuleA! filter command) but I don’t include its output here.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging | 1 Comment »

Icons for Memory Dump Analysis Patterns (Part 45)

Tuesday, June 1st, 2010

Today we introduce an icon for Virtualized Process (WOW64) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

Forthcoming Webinars: Complete Debugging and Crash Analysis for Windows

Sunday, May 30th, 2010

Finally, after careful consideration, I’ve come up with the topic that has been neglected so far but at the same time important for both camps (kernel space and user space, including managed space): complete memory dump and software trace analysis. I plan to publish the first webinar agenda early in July and deliver the webinar in August (the date should be finalized by mid July).

PS. Sailing memory spaces under an RGB flag

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Announcements, CDF Analysis Tips and Tricks, Crash Analysis Report Environment (CARE), Crash Dump Analysis, Crash Dump Patterns, Debugging, DumpAnalysis and TraceAnalysis Logos, Escalation Engineering, Software Behavior Patterns, Software Technical Support, Software Trace Analysis, Software Troubleshooting Patterns, Tools, Trace Analysis Patterns, Training and Seminars, WinDbg Scripts, WinDbg Tips and Tricks | 2 Comments »

Crash Dump Analysis Patterns (Part 99a)

Saturday, May 29th, 2010

Most of the time Incorrect Symbolic Information is associated with function names and offsets, for example, module!foo vs. module!foo+100. In some cases the module name is incorrect itself or absent altogether. This can happen in complete memory dumps when we forget to reload user space symbols after changing the process context, for example:

; previous process context of firefox.exe ; switching to winlogon.exe context

kd> .process fffffadfe718c040 Implicit process is now fffffadf`e718c040

kd> !process fffffadfe718c040 PROCESS fffffadfe718c040 SessionId: 0 Cid: 017c Peb: 7fffffd9000 ParentCid: 0130 DirBase: 01916000 ObjectTable: fffffa800099a890 HandleCount: 754. Image: winlogon.exe VadRoot fffffadfe75e91f0 Vads 190 Clone 0 Private 2905. Modified 10047. Locked 0. DeviceMap fffffa8000004950 Token fffffa800122a060 ElapsedTime 77 Days 02:14:26.109 UserTime 00:00:04.156 KernelTime 00:00:02.359 QuotaPoolUsage[PagedPool] 143128 QuotaPoolUsage[NonPagedPool] 191072 Working Set Sizes (now,min,max) (541, 50, 345) (2164KB, 200KB, 1380KB) PeakWorkingSetSize 6323 VirtualSize 108 Mb PeakVirtualSize 118 Mb PageFaultCount 212547 MemoryPriority BACKGROUND BasePriority 13 CommitCharge 3733

[...]

THREAD fffffadfe68f2040 Cid 017c.0198 Teb: 000007fffffd7000 Win32Thread: fffff97ff4a09010 WAIT: (Unknown) UserMode Non-Alertable fffffadfe7133160 Semaphore Limit 0x7fffffff fffffadfe68f20f8 NotificationTimer Not impersonating DeviceMap fffffa8000004950 Owning Process fffffadfe718c040 Image: winlogon.exe Attached Process N/A Image: N/A Wait Start TickCount 426298731 Ticks: 51 (0:00:00:00.796) Context Switch Count 2215076 LargeStack UserTime 00:00:00.187 KernelTime 00:00:00.468 Start Address 0×0000000077d6b6e0 Stack Init fffffadfe4481e00 Current fffffadfe4481860 Base fffffadfe4482000 Limit fffffadfe447a000 Call 0 Priority 14 BasePriority 13 PriorityDecrement 0 Child-SP RetAddr Call Site fffffadf`e44818a0 fffff800`0103b093 nt!KiSwapContext+0×85 fffffadf`e4481a20 fffff800`0103c433 nt!KiSwapThread+0xc3 fffffadf`e4481a60 fffff800`012d25ae nt!KeWaitForSingleObject+0×528 fffffadf`e4481af0 fffff800`0104113d nt!NtReplyWaitReceivePortEx+0×8c8 fffffadf`e4481c00 00000000`77ef0caa nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffadf`e4481c70) 00000000`00bcfb98 000007ff`7fd6ff61 ntdll!NtReplyWaitReceivePortEx+0xa 00000000`00bcfba0 00000000`000d2340 0×7ff`7fd6ff61 00000000`00bcfba8 00000000`00bcfde0 0xd2340 00000000`00bcfbb0 00000000`014cd220 0xbcfde0 00000000`00bcfbb8 00000000`000c1d30 0×14cd220 00000000`00bcfbc0 00000000`00bcfe18 0xc1d30 00000000`00bcfbc8 0000ffff`00001f80 0xbcfe18 00000000`00bcfbd0 00000000`006c0044 0xffff`00001f80 00000000`00bcfbd8 00000000`000006ec firefox+0×2c0044 00000000`00bcfbe0 00000000`000007b0 0×6ec 00000000`00bcfbe8 00000000`419b8385 0×7b0 00000000`00bcfbf0 00000000`00000000 0×419b8385

kd> lmu m firefox start end module name 00000000`00400000 00000000`00b67000 firefox T (no symbols)

We have the return address 00000000`006c0044 which is just firefox+0×2c0044 (00000000`00400000 + 2c0044). We correct that by reloading user space symbols.

kd> .reload /user

kd> !process fffffadfe718c040 [...] THREAD fffffadfe68f2040 Cid 017c.0198 Teb: 000007fffffd7000 Win32Thread: fffff97ff4a09010 WAIT: (Unknown) UserMode Non-Alertable fffffadfe7133160 Semaphore Limit 0x7fffffff fffffadfe68f20f8 NotificationTimer Not impersonating DeviceMap fffffa8000004950 Owning Process fffffadfe718c040 Image: winlogon.exe Attached Process N/A Image: N/A Wait Start TickCount 426298731 Ticks: 51 (0:00:00:00.796) Context Switch Count 2215076 LargeStack UserTime 00:00:00.187 KernelTime 00:00:00.468 Start Address kernel32!BaseThreadStart (0x0000000077d6b6e0) Stack Init fffffadfe4481e00 Current fffffadfe4481860 Base fffffadfe4482000 Limit fffffadfe447a000 Call 0 Priority 14 BasePriority 13 PriorityDecrement 0 Child-SP RetAddr Call Site fffffadf`e44818a0 fffff800`0103b093 nt!KiSwapContext+0x85 fffffadf`e4481a20 fffff800`0103c433 nt!KiSwapThread+0xc3 fffffadf`e4481a60 fffff800`012d25ae nt!KeWaitForSingleObject+0x528 fffffadf`e4481af0 fffff800`0104113d nt!NtReplyWaitReceivePortEx+0x8c8 fffffadf`e4481c00 00000000`77ef0caa nt!KiSystemServiceCopyEnd+0x3 (TrapFrame @ fffffadf`e4481c70) 00000000`00bcfb98 000007ff`7fd6ff61 ntdll!NtReplyWaitReceivePortEx+0xa 00000000`00bcfba0 000007ff`7fd45369 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0x2a5 00000000`00bcfeb0 000007ff`7fd65996 RPCRT4!RecvLotsaCallsWrapper+0x9 00000000`00bcfee0 000007ff`7fd65d51 RPCRT4!BaseCachedThreadRoutine+0xde 00000000`00bcff50 00000000`77d6b71a RPCRT4!ThreadStartRoutine+0x21 00000000`00bcff80 00000000`00000000 kernel32!BaseThreadStart+0x3a

Commands like .process /r /p fffffadfe718c040 or !process fffffadfe718c040 ff do that automatically.

Another case for incorrect module names is malformed unloaded modules information. This can happen sometimes:

0:000> lmt start end module name [...] 7c800000 7c907000 kernel32 Mon Apr 16 16:53:05 2007 (46239BE1) 7c910000 7c9c7000 ntdll Wed Aug 04 08:57:08 2004 (411096D4) 7c9d0000 7d1ef000 shell32 Tue Dec 19 21:49:37 2006 (45885E71) 7df20000 7dfc0000 urlmon Wed Aug 22 14:13:03 2007 (46CC365F) 7e360000 7e3f0000 user32 Thu Mar 08 15:36:30 2007 (45F02D7E) Missing image name, possible paged-out or corrupt data.

Unloaded modules: 00410053 008a00a3 Unknown_Module_00410053 Timestamp: Tue Mar 17 20:27:26 1970 (0064002E) Checksum: 006C006C 00010755 007407c5 l Timestamp: Wed Feb 04 21:26:01 1970 (002E0069) Checksum: 006C0064 00000011 411096d2 eme.dll Timestamp: Thu Apr 02 01:33:25 1970 (00780055) Checksum: 00680054 Missing image name, possible paged-out or corrupt data. 0064002e 00d0009a Unknown_Module_0064002e Timestamp: unavailable (00000000) Checksum: 00000000

Here parts of UNICODE module names appear in checksums and timestamps as well. Such partial module names can appear on thread stacks and raw stack data, for example:

0:000> kL ChildEBP RetAddr [...] 0015ef3c 0366afc2 ModuleA!Validation+0x5b WARNING: Frame IP not in any known module. Following frames may be wrong. 0015efcc 79e7c7a6 <Unloaded_ure.dll>+0x366afc1 03dc9b70 00000000 mscorwks!MethodDesc::CallDescr+0x1f

Default analysis falls victim too and suggests ure.dll you would try hard to find on your system:

MODULE_NAME: ure

IMAGE_NAME:　 ure.dll

DEBUG_FLR_IMAGE_TIMESTAMP:　 750063

FAILURE_BUCKET_ID:　 ure.dll!Unloaded_c0000005_APPLICATION_FAULT

Timestamp is suspiciously UNICODE-like. In such cases we can even reconstruct the module name:

00000011 411096d2 eme.dll Timestamp: Thu Apr 02 01:33:25 1970 (00780055) Checksum: 00680054

0:000> .formats 00780055 Evaluate expression: Hex: 00000000`00780055 Decimal: 7864405 Octal: 0000000000000036000125 Binary: 00000000 00000000 00000000 00000000 00000000 01111000 00000000 01010101 Chars: …..x.U Time: Thu Apr 02 01:33:25 1970 Float: low 1.10204e-038 high 0 Double: 3.88553e-317

0:000> .formats 00680054 Evaluate expression: Hex: 00680054 Decimal: 6815828 Octal: 00032000124 Binary: 00000000 01101000 00000000 01010100 Chars: .h.T Time: Fri Mar 20 21:17:08 1970 Float: low 9.55101e-039 high 0 Double: 3.36747e-317

We concatenate UNICODE Ux and Th with eme.dll to get UxTheme.dll which is a real DLL name we can find on a system.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging | No Comments »

Icons for Memory Dump Analysis Patterns (Part 44)

Friday, May 28th, 2010

Today we introduce an icon for Stack Trace pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

Icons for Memory Dump Analysis Patterns (Part 43)

Wednesday, May 26th, 2010

Today we introduce an icon for Coincidental Symbolic Information pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

Models for Memory and Trace Analysis Patterns (Part 2)

Sunday, May 23rd, 2010

We continue our modeling of software behaviour with the ubiquitous Memory Leak (process heap) pattern. Instead of leaking small heap allocations that are easy to debug with user mode stack trace database our model program leaks large heap allocations:

// MemoryLeak-ProcessHeap // Copyright (c) 2010 Dmitry Vostokov // GNU GENERAL PUBLIC LICENSE // http://www.gnu.org/licenses/gpl-3.0.txt

#include <windows.h>

int _tmain(int argc, _TCHAR* argv[]) { // create extra 25 heaps initially for (int i = 0; i < 25; ++i) HeapCreate(0, 0, 0);

// create a heap to leak within HANDLE hHeap = HeapCreate(0, 0, 0);

while (true) { HeapAlloc(hHeap, 0, 1024*1024); Sleep(1000); }

return 0; }

The program creates extra process heaps to simulate real life heap leaks that usually happen not in a default process heap. Then it slowly leaks 0×100000 bytes every second. The application can be downloaded from here (zip file contains source code, x86 and x64 binaries together with corresponding PDB files):

Download MemoryLeak-ProcessHeap.zip

Here I present the results from x64 Windows Server 2008 R2 but x86 variants (I tested on x86 Vista) should be the same.

First we run the application and save a dump of it after a few seconds (I used Task Manager). Heap statistics shows 9 virtual blocks for the last 0000000001e00000 heap:

0:000> !heap -s LFH Key : 0x000000d529c37801 Termination on corruption : ENABLED Heap Flags Reserv Commit Virt Free List UCR Virt Lock Fast (k) (k) (k) (k) length blocks cont. heap ————————————————————————————- 00000000002b0000 00000002 1024 164 1024 3 1 1 0 0 LFH 0000000000010000 00008000 64 4 64 1 1 1 0 0 0000000000020000 00008000 64 64 64 61 1 1 0 0 0000000000220000 00001002 1088 152 1088 3 2 2 0 0 LFH 0000000000630000 00001002 512 8 512 3 1 1 0 0 0000000000870000 00001002 512 8 512 3 1 1 0 0 0000000000ad0000 00001002 512 8 512 3 1 1 0 0 00000000007e0000 00001002 512 8 512 3 1 1 0 0 0000000000cc0000 00001002 512 8 512 3 1 1 0 0 0000000000ed0000 00001002 512 8 512 3 1 1 0 0 00000000010c0000 00001002 512 8 512 3 1 1 0 0 00000000005b0000 00001002 512 8 512 3 1 1 0 0 00000000009f0000 00001002 512 8 512 3 1 1 0 0 00000000004d0000 00001002 512 8 512 3 1 1 0 0 0000000000230000 00001002 512 8 512 3 1 1 0 0 0000000000700000 00001002 512 8 512 3 1 1 0 0 00000000012d0000 00001002 512 8 512 3 1 1 0 0 0000000000950000 00001002 512 8 512 3 1 1 0 0 0000000000b90000 00001002 512 8 512 3 1 1 0 0 00000000014c0000 00001002 512 8 512 3 1 1 0 0 0000000000e50000 00001002 512 8 512 3 1 1 0 0 0000000001020000 00001002 512 8 512 3 1 1 0 0 00000000016e0000 00001002 512 8 512 3 1 1 0 0 0000000001940000 00001002 512 8 512 3 1 1 0 0 0000000001b90000 00001002 512 8 512 3 1 1 0 0 0000000001200000 00001002 512 8 512 3 1 1 0 0 0000000000c20000 00001002 512 8 512 3 1 1 0 0 0000000000db0000 00001002 512 8 512 3 1 1 0 0 0000000000f50000 00001002 512 8 512 3 1 1 0 0 Virtual block: 0000000001350000 - 0000000001350000 (size 0000000000000000) Virtual block: 0000000001540000 - 0000000001540000 (size 0000000000000000) Virtual block: 0000000001760000 - 0000000001760000 (size 0000000000000000) Virtual block: 00000000019c0000 - 00000000019c0000 (size 0000000000000000) Virtual block: 0000000001c10000 - 0000000001c10000 (size 0000000000000000) Virtual block: 0000000001e80000 - 0000000001e80000 (size 0000000000000000) Virtual block: 0000000001f90000 - 0000000001f90000 (size 0000000000000000) Virtual block: 00000000020a0000 - 00000000020a0000 (size 0000000000000000) Virtual block: 00000000021b0000 - 00000000021b0000 (size 0000000000000000) 0000000001e00000 00001002 512 8 512 3 1 1 9 0 ————————————————————————————-

We then wait for a few minutes and save a memory dump again. Heap statistics clearly shows virtual block leaks because now we 276 of them instead of previous 9 (I skipped most of them in the output below):

0:000> !heap -s LFH Key : 0x000000d529c37801 Termination on corruption : ENABLED Heap Flags Reserv Commit Virt Free List UCR Virt Lock Fast (k) (k) (k) (k) length blocks cont. heap ————————————————————————————- 00000000002b0000 00000002 1024 164 1024 3 1 1 0 0 LFH 0000000000010000 00008000 64 4 64 1 1 1 0 0 0000000000020000 00008000 64 64 64 61 1 1 0 0 0000000000220000 00001002 1088 152 1088 3 2 2 0 0 LFH 0000000000630000 00001002 512 8 512 3 1 1 0 0 0000000000870000 00001002 512 8 512 3 1 1 0 0 0000000000ad0000 00001002 512 8 512 3 1 1 0 0 00000000007e0000 00001002 512 8 512 3 1 1 0 0 0000000000cc0000 00001002 512 8 512 3 1 1 0 0 0000000000ed0000 00001002 512 8 512 3 1 1 0 0 00000000010c0000 00001002 512 8 512 3 1 1 0 0 00000000005b0000 00001002 512 8 512 3 1 1 0 0 00000000009f0000 00001002 512 8 512 3 1 1 0 0 00000000004d0000 00001002 512 8 512 3 1 1 0 0 0000000000230000 00001002 512 8 512 3 1 1 0 0 0000000000700000 00001002 512 8 512 3 1 1 0 0 00000000012d0000 00001002 512 8 512 3 1 1 0 0 0000000000950000 00001002 512 8 512 3 1 1 0 0 0000000000b90000 00001002 512 8 512 3 1 1 0 0 00000000014c0000 00001002 512 8 512 3 1 1 0 0 0000000000e50000 00001002 512 8 512 3 1 1 0 0 0000000001020000 00001002 512 8 512 3 1 1 0 0 00000000016e0000 00001002 512 8 512 3 1 1 0 0 0000000001940000 00001002 512 8 512 3 1 1 0 0 0000000001b90000 00001002 512 8 512 3 1 1 0 0 0000000001200000 00001002 512 8 512 3 1 1 0 0 0000000000c20000 00001002 512 8 512 3 1 1 0 0 0000000000db0000 00001002 512 8 512 3 1 1 0 0 0000000000f50000 00001002 512 8 512 3 1 1 0 0 Virtual block: 0000000001350000 - 0000000001350000 (size 0000000000000000) Virtual block: 0000000001540000 - 0000000001540000 (size 0000000000000000) Virtual block: 0000000001760000 - 0000000001760000 (size 0000000000000000) Virtual block: 00000000019c0000 - 00000000019c0000 (size 0000000000000000) [… skipped …] Virtual block: 00000000131b0000 - 00000000131b0000 (size 0000000000000000) Virtual block: 00000000132c0000 - 00000000132c0000 (size 0000000000000000) Virtual block: 00000000133d0000 - 00000000133d0000 (size 0000000000000000) Virtual block: 00000000134e0000 - 00000000134e0000 (size 0000000000000000) Virtual block: 00000000135f0000 - 00000000135f0000 (size 0000000000000000) Virtual block: 0000000013700000 - 0000000013700000 (size 0000000000000000) Virtual block: 0000000013810000 - 0000000013810000 (size 0000000000000000) Virtual block: 0000000013920000 - 0000000013920000 (size 0000000000000000) Virtual block: 0000000013a30000 - 0000000013a30000 (size 0000000000000000) Virtual block: 0000000013b40000 - 0000000013b40000 (size 0000000000000000) Virtual block: 0000000013c50000 - 0000000013c50000 (size 0000000000000000) Virtual block: 0000000013d60000 - 0000000013d60000 (size 0000000000000000) 0000000001e00000 00001002 512 8 512 3 1 1 276 0 ————————————————————————————-

We see that size of these blocks is 0×101000 bytes (with hindsight, extra 1000 is probably bookkeeping info):

0:000> !address 0000000013d60000 ProcessParametrs 00000000002b1f20 in range 00000000002b0000 00000000002d9000 Environment 00000000002b1320 in range 00000000002b0000 00000000002d9000 0000000013d60000 : 0000000013d60000 - 0000000000101000 Type 00020000 MEM_PRIVATE Protect 00000004 PAGE_READWRITE State 00001000 MEM_COMMIT Usage RegionUsageHeap Handle 0000000001e00000

We want to know which thread allocates them and we search for the heap address 0000000001e00000 through virtual memory to find any execution residue on thread raw stacks:

0:000> s -q 0 LFFFFFF 0000000001e00000 00000000`001cf608 00000000`01e00000 00000000`01e00000 00000000`001cf610 00000000`01e00000 00000000`00000858 00000000`001cf630 00000000`01e00000 00000000`0000000a 00000000`001cf6c8 00000000`01e00000 00000000`00000000 00000000`001cf6e0 00000000`01e00000 00000000`01e00a80 00000000`001cf720 00000000`01e00000 00000000`00000020 00000000`001cf778 00000000`01e00000 00000000`01e00000 00000000`001cf780 00000000`01e00000 00000000`00000000 00000000`001cf798 00000000`01e00000 00000000`01e02000 00000000`001cf7b0 00000000`01e00000 02100301`00000000 00000000`001cf7c8 00000000`01e00000 00000000`01c10000 00000000`001cf808 00000000`01e00000 00000000`00000001 00000000`001cf830 00000000`01e00000 00000000`00000002 00000000`001cf940 00000000`01e00000 00000000`00000000 00000000`002d8378 00000000`01e00000 004c0044`005c0064 00000000`01e00028 00000000`01e00000 00000000`01e00000 00000000`01e00030 00000000`01e00000 00000000`00000080

Address range 00000000`001cfxxxx belongs to the main thread:

0:000> kL Child-SP RetAddr Call Site 00000000`001cf898 000007fe`fdd91203 ntdll!NtDelayExecution+0xa 00000000`001cf8a0 00000001`3f39104f KERNELBASE!SleepEx+0xab 00000000`001cf940 00000001`3f3911ea MemoryLeak_ProcessHeap!wmain+0×4f 00000000`001cf970 00000000`778cf56d MemoryLeak_ProcessHeap!__tmainCRTStartup+0×15a 00000000`001cf9b0 00000000`77b03281 kernel32!BaseThreadInitThunk+0xd 00000000`001cf9e0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

We dump the raw stack fragment now:

0:000> dps 00000000`001cf608 00000000`001cf940 00000000`001cf608 00000000`01e00000 00000000`001cf610 00000000`01e00000 00000000`001cf618 00000000`00000858 00000000`001cf620 00000000`00000000 00000000`001cf628 00000000`77b229ac ntdll!RtlAllocateHeap+0×16c 00000000`001cf630 00000000`01e00000 00000000`001cf638 00000000`0000000a 00000000`001cf640 00000000`00000858 00000000`001cf648 00000000`00000860 00000000`001cf650 00000000`00000000 00000000`001cf658 00000000`001cf740 00000000`001cf660 00000020`00001000 00000000`001cf668 fffff680`01000000 00000000`001cf670 00000001`3f390000 MemoryLeak_ProcessHeap!wmain <PERF> (MemoryLeak_ProcessHeap+0×0) 00000000`001cf678 01000000`00000080 00000000`001cf680 00000000`0000f000 00000000`001cf688 02100210`02100210 00000000`001cf690 00000001`3f390000 MemoryLeak_ProcessHeap!wmain <PERF> (MemoryLeak_ProcessHeap+0×0) 00000000`001cf698 00000000`0000f000 00000000`001cf6a0 00000000`01e01fd0 00000000`001cf6a8 00000000`77b07ff3 ntdll!RtlpCreateUCREntry+0xb3 00000000`001cf6b0 00000000`001cf6b8 00000000`001cf6b8 00000000`01e01fc0 00000000`001cf6c0 00000000`00000080 00000000`001cf6c8 00000000`01e00000 00000000`001cf6d0 00000000`00000000 00000000`001cf6d8 00000000`00000a00 00000000`001cf6e0 00000000`01e00000 00000000`001cf6e8 00000000`01e00a80 00000000`001cf6f0 00000000`0007e000 00000000`001cf6f8 00000000`77b0f2bb ntdll!RtlpInitializeHeapSegment+0×19b 00000000`001cf700 00000000`01e00208 00000000`001cf708 00000000`00000000 00000000`001cf710 00000000`01e00230 00000000`001cf718 00000000`00000000 00000000`001cf720 00000000`01e00000 00000000`001cf728 00000000`00000020 00000000`001cf730 00000000`00000000 00000000`001cf738 00000000`77b0f676 ntdll!RtlpInitializeUCRIndex+0×36 00000000`001cf740 000007ff`00000003 00000000`001cf748 00000000`00000100 00000000`001cf750 00000000`00000000 00000000`001cf758 00000000`00001002 00000000`001cf760 00000000`00001002 00000000`001cf768 00000000`77b0fec9 ntdll!RtlCreateHeap+0×8f7 00000000`001cf770 00000000`01e02000 00000000`001cf778 00000000`01e00000 00000000`001cf780 00000000`01e00000 00000000`001cf788 00000000`00000000 00000000`001cf790 03010301`00000000 00000000`001cf798 00000000`01e00000 00000000`001cf7a0 00000000`01e02000 00000000`001cf7a8 00000000`01e80000 00000000`001cf7b0 00000000`01e00000 00000000`001cf7b8 02100301`00000000 00000000`001cf7c0 00000000`001f0000 00000000`001cf7c8 00000000`01e00000 00000000`001cf7d0 00000000`01c10000 00000000`001cf7d8 00000000`01e02000 00000000`001cf7e0 00000000`00270000 00000000`001cf7e8 03020302`00000230 00000000`001cf7f0 00000000`77be7288 ntdll!RtlpInterceptorRoutines 00000000`001cf7f8 00000000`00000000 00000000`001cf800 00000000`00100010 00000000`001cf808 00000000`01e00000 00000000`001cf810 00000000`00000001 00000000`001cf818 00000000`00100000 00000000`001cf820 00000000`00000000 00000000`001cf828 00000000`77b229ac ntdll!RtlAllocateHeap+0×16c 00000000`001cf830 00000000`01e00000 00000000`001cf838 00000000`00000002 00000000`001cf840 00000000`00100000 00000000`001cf848 00000000`00101000 00000000`001cf850 00000000`00000000 00000000`001cf858 00000000`001cf940 00000000`001cf860 00000000`00000000 00000000`001cf868 0000f577`2bd1e0ff 00000000`001cf870 00000000`ffffffff 00000000`001cf878 00000000`10010011 00000000`001cf880 00000000`c00000bb 00000000`001cf888 00000000`00000000 00000000`001cf890 00000000`00000100 00000000`001cf898 000007fe`fdd91203 KERNELBASE!SleepEx+0xab 00000000`001cf8a0 00000000`001cf958 00000000`001cf8a8 00000000`00000000 00000000`001cf8b0 00000000`00000000 00000000`001cf8b8 00000000`00000012 00000000`001cf8c0 ffffffff`ff676980 00000000`001cf8c8 00000000`001cf8c0 00000000`001cf8d0 00000000`00000048 00000000`001cf8d8 00000000`00000001 00000000`001cf8e0 00000000`00000000 00000000`001cf8e8 00000000`00000000 00000000`001cf8f0 00000000`00000000 00000000`001cf8f8 00000000`00000000 00000000`001cf900 00000000`00000000 00000000`001cf908 00000000`00000000 00000000`001cf910 00000000`00000000 00000000`001cf918 00000000`00000000 00000000`001cf920 00000000`00000000 00000000`001cf928 00000000`00000001 00000000`001cf930 00000000`00000000 00000000`001cf938 00000001`3f39104f MemoryLeak_ProcessHeap!wmain+0×4f 00000000`001cf940 00000000`01e00000

We see traces of RtlAllocateHeap but it could be a coincidence (imagine that we don’t have access to source code and can’t do live debugging to put breakpoints). We advise to enable use mode stack trace database as explained for another example process: CTX106970. Then we launch our application again and save a new user dump. We repeat the same procedure to examine the raw stack:

0:000> !heap -s NtGlobalFlag enables following debugging aids for new heaps: stack back traces LFH Key : 0x000000c21e1b31e6 Termination on corruption : ENABLED Heap Flags Reserv Commit Virt Free List UCR Virt Lock Fast (k) (k) (k) (k) length blocks cont. heap ------------------------------------------------------------------------------------- 0000000001bc0000 08000002 1024 168 1024 5 1 1 0 0 LFH 0000000000010000 08008000 64 4 64 1 1 1 0 0 0000000000020000 08008000 64 64 64 61 1 1 0 0 0000000000100000 08001002 1088 152 1088 2 2 2 0 0 LFH 0000000001d90000 08001002 512 8 512 3 1 1 0 0 0000000001f90000 08001002 512 8 512 3 1 1 0 0 00000000021c0000 08001002 512 8 512 3 1 1 0 0 0000000002130000 08001002 512 8 512 3 1 1 0 0 0000000002370000 08001002 512 8 512 3 1 1 0 0 0000000001e80000 08001002 512 8 512 3 1 1 0 0 0000000000110000 08001002 512 8 512 3 1 1 0 0 0000000002510000 08001002 512 8 512 3 1 1 0 0 0000000002760000 08001002 512 8 512 3 1 1 0 0 0000000001cc0000 08001002 512 8 512 3 1 1 0 0 0000000002030000 08001002 512 8 512 3 1 1 0 0 0000000002960000 08001002 512 8 512 3 1 1 0 0 0000000002670000 08001002 512 8 512 3 1 1 0 0 0000000002b90000 08001002 512 8 512 3 1 1 0 0 00000000022f0000 08001002 512 8 512 3 1 1 0 0 00000000028b0000 08001002 512 8 512 3 1 1 0 0 0000000001f10000 08001002 512 8 512 3 1 1 0 0 0000000002450000 08001002 512 8 512 3 1 1 0 0 00000000025f0000 08001002 512 8 512 3 1 1 0 0 0000000002a40000 08001002 512 8 512 3 1 1 0 0 0000000002c90000 08001002 512 8 512 3 1 1 0 0 0000000002d90000 08001002 512 8 512 3 1 1 0 0 0000000002e80000 08001002 512 8 512 3 1 1 0 0 0000000002fc0000 08001002 512 8 512 3 1 1 0 0 00000000030b0000 08001002 512 8 512 3 1 1 0 0 Virtual block: 0000000003130000 - 0000000003130000 (size 0000000000000000) Virtual block: 0000000003240000 - 0000000003240000 (size 0000000000000000) Virtual block: 0000000003350000 - 0000000003350000 (size 0000000000000000) Virtual block: 0000000003460000 - 0000000003460000 (size 0000000000000000) Virtual block: 0000000003570000 - 0000000003570000 (size 0000000000000000) Virtual block: 0000000003680000 - 0000000003680000 (size 0000000000000000) Virtual block: 0000000003790000 - 0000000003790000 (size 0000000000000000) Virtual block: 00000000038a0000 - 00000000038a0000 (size 0000000000000000) Virtual block: 00000000039b0000 - 00000000039b0000 (size 0000000000000000) Virtual block: 0000000003ac0000 - 0000000003ac0000 (size 0000000000000000) Virtual block: 0000000003bd0000 - 0000000003bd0000 (size 0000000000000000) Virtual block: 0000000003ce0000 - 0000000003ce0000 (size 0000000000000000) 0000000002270000 08001002 512 8 512 3 1 1 12 0

0:000> s -q 0 LFFFFFF 0000000002270000 00000000`0029f648 00000000`02270000 00000000`000000a8 00000000`0029f660 00000000`02270000 00000000`77b99bc7 00000000`0029f6e8 00000000`02270000 00000000`02270000 00000000`0029f6f0 00000000`02270000 00000000`00000858 00000000`0029f710 00000000`02270000 00000000`0000000a 00000000`0029f758 00000000`02270000 00000000`0029f918 00000000`0029f7c0 00000000`02270000 00000000`03ce0040 00000000`0029f858 00000000`02270000 00000000`02270000 00000000`0029f860 00000000`02270000 00000000`00000000 00000000`0029f878 00000000`02270000 00000000`02272000 00000000`0029f890 00000000`02270000 02100301`00000000 00000000`0029f8f8 00000000`02270000 00000000`03ce0040 00000000`0029fa20 00000000`02270000 00000000`00000000 00000000`01be8a08 00000000`02270000 0064006e`00690057 00000000`02270028 00000000`02270000 00000000`02270000 00000000`02270030 00000000`02270000 00000000`00000080

0:000> dqs 00000000`0029f648 00000000`0029fa20 00000000`0029f648 00000000`02270000 00000000`0029f650 00000000`000000a8 00000000`0029f658 00000000`00000a80 00000000`0029f660 00000000`02270000 00000000`0029f668 00000000`77b99bc7 ntdll!RtlStdLogStackTrace+0x47 00000000`0029f670 00000000`002a0000 00000000`0029f678 00000000`0000007e 00000000`0029f680 00000000`02270a80 00000000`0029f688 00000000`00000000 00000000`0029f690 00000000`02270208 00000000`0029f698 00070000`77b99bc7 00000000`0029f6a0 00000000`77b6cd8a ntdll! ?? ::FNODOBFM::`string'+0xf35a 00000000`0029f6a8 00000000`77b0fd07 ntdll!RtlCreateHeap+0x56e 00000000`0029f6b0 000007fe`fdd9c6a4 KERNELBASE!HeapCreate+0x54 00000000`0029f6b8 00000001`3faa1030 MemoryLeak_ProcessHeap!wmain+0x30 00000000`0029f6c0 00000001`3faa11ea MemoryLeak_ProcessHeap!__tmainCRTStartup+0x15a 00000000`0029f6c8 00000000`778cf56d kernel32!BaseThreadInitThunk+0xd 00000000`0029f6d0 00000000`77be7288 ntdll!RtlpInterceptorRoutines 00000000`0029f6d8 00000000`00000000 00000000`0029f6e0 00000000`00000860 00000000`0029f6e8 00000000`02270000 00000000`0029f6f0 00000000`02270000 00000000`0029f6f8 00000000`00000858 00000000`0029f700 00000000`00000000 00000000`0029f708 00000000`77b229ac ntdll!RtlAllocateHeap+0x16c 00000000`0029f710 00000000`02270000 00000000`0029f718 00000000`0000000a 00000000`0029f720 00000000`00000858 00000000`0029f728 00000000`00000860 00000000`0029f730 00000000`00000000 00000000`0029f738 00000000`0029f820 00000000`0029f740 00000000`77be7288 ntdll!RtlpInterceptorRoutines 00000000`0029f748 00000000`00000002 00000000`0029f750 00000000`00100030 00000000`0029f758 00000000`02270000 00000000`0029f760 00000000`0029f918 00000000`0029f768 00000000`00000020 00000000`0029f770 00000000`00000002 00000000`0029f778 00000000`00000005 00000000`0029f780 00000000`000750f0 00000000`0029f788 00000000`77ba25b2 ntdll!RtlpRegisterStackTrace+0x92 00000000`0029f790 00000000`000750b8 00000000`0029f798 00000000`00000003 00000000`0029f7a0 00000000`00000000 00000000`0029f7a8 00000000`77ad7a0a ntdll!RtlCaptureStackBackTrace+0x4a 00000000`0029f7b0 00000000`00000002 00000000`0029f7b8 00000000`00100030 00000000`0029f7c0 00000000`02270000 00000000`0029f7c8 00000000`03ce0040 00000000`0029f7d0 00000000`00100020 00000000`0029f7d8 00000000`77ba2eb7 ntdll!RtlpStackTraceDatabaseLogPrefix+0x57 00000000`0029f7e0 00000000`03ce0040 00000000`0029f7e8 00000000`00000000 00000000`0029f7f0 00000000`00100020 00000000`0029f7f8 00000000`000750f0 00000000`0029f800 00000000`77b6ed2d ntdll! ?? ::FNODOBFM::`string’+0×1a81b 00000000`0029f808 00000001`3faa1044 MemoryLeak_ProcessHeap!wmain+0×44 00000000`0029f810 00000001`3faa11ea MemoryLeak_ProcessHeap!__tmainCRTStartup+0×15a 00000000`0029f818 00000000`778cf56d kernel32!BaseThreadInitThunk+0xd 00000000`0029f820 00000000`77b03281 ntdll!RtlUserThreadStart+0×1d 00000000`0029f828 00000000`00000100 00000000`0029f830 00000000`00000000 00000000`0029f838 00000000`08001002 00000000`0029f840 00000000`08001002 00000000`0029f848 00000000`77b0fec9 ntdll!RtlCreateHeap+0×8f7 00000000`0029f850 00000000`02272000 00000000`0029f858 00000000`02270000 00000000`0029f860 00000000`02270000 00000000`0029f868 00000000`00000000 00000000`0029f870 03010301`00000000 00000000`0029f878 00000000`02270000 00000000`0029f880 00000000`02272000 00000000`0029f888 00000000`022f0000 00000000`0029f890 00000000`02270000 00000000`0029f898 02100301`00000000 00000000`0029f8a0 00000000`00001000 00000000`0029f8a8 00000000`77b9a886 ntdll!RtlpSetupExtendedBlock+0xc6 00000000`0029f8b0 00000000`00000000 00000000`0029f8b8 00000000`02272000 00000000`0029f8c0 00000000`000b0000 00000000`0029f8c8 03020302`00000230 00000000`0029f8d0 00000000`77be7288 ntdll!RtlpInterceptorRoutines 00000000`0029f8d8 00000000`00000002 00000000`0029f8e0 00000000`77be7288 ntdll!RtlpInterceptorRoutines 00000000`0029f8e8 00000000`00000002 00000000`0029f8f0 00000000`00100030 00000000`0029f8f8 00000000`02270000 00000000`0029f900 00000000`03ce0040 00000000`0029f908 00000000`77b6ed6a ntdll! ?? ::FNODOBFM::`string’+0×1a858 00000000`0029f910 00000000`00000000 00000000`0029f918 00000000`00000000 00000000`0029f920 00000000`00100000 00000000`0029f928 00000000`00101000 00000000`0029f930 00000000`00000020 00000000`0029f938 00000000`00000002 00000000`0029f940 00000000`00000000 00000000`0029f948 0000f569`df709780 00000000`0029f950 00000000`ffffffff 00000000`0029f958 00000000`12010013 00000000`0029f960 00000000`c00000bb 00000000`0029f968 00000000`00000000 00000000`0029f970 00000000`00000100 00000000`0029f978 000007fe`fdd91203 KERNELBASE!SleepEx+0xab 00000000`0029f980 00000000`0029fa38 00000000`0029f988 00000000`00000000 00000000`0029f990 00000000`00000000 00000000`0029f998 00000000`00000012 00000000`0029f9a0 ffffffff`ff676980 00000000`0029f9a8 00000000`0029f9a0 00000000`0029f9b0 00000000`00000048 00000000`0029f9b8 00000000`00000001 00000000`0029f9c0 00000000`00000000 00000000`0029f9c8 00000000`00000000 00000000`0029f9d0 00000000`00000000 00000000`0029f9d8 00000000`00000000 00000000`0029f9e0 00000000`00000000 00000000`0029f9e8 00000000`00000000 00000000`0029f9f0 00000000`00000000 00000000`0029f9f8 00000000`00000000 00000000`0029fa00 00000000`00000000 00000000`0029fa08 00000000`00000001 00000000`0029fa10 00000000`00000000 00000000`0029fa18 00000001`3faa104f MemoryLeak_ProcessHeap!wmain+0×4f 00000000`0029fa20 00000000`02270000

Now we see this stack trace fragment from user mode stack trace database on the raw stack shown above:

00000000`0029f800 00000000`77b6ed2d ntdll! ?? ::FNODOBFM::`string'+0x1a81b 00000000`0029f808 00000001`3faa1044MemoryLeak_ProcessHeap!wmain+0×44 00000000`0029f810 00000001`3faa11ea MemoryLeak_ProcessHeap!__tmainCRTStartup+0×15a 00000000`0029f818 00000000`778cf56d kernel32!BaseThreadInitThunk+0xd 00000000`0029f820 00000000`77b03281 ntdll!RtlUserThreadStart+0×1d

And it looks like HeapAlloc was called from wmain indeed with 0×100000 parameter:

0:000> ub 00000001`3faa1044 MemoryLeak_ProcessHeap!wmain+0x26: 00000001`3faa1026 xor edx,edx 00000001`3faa1028 xor ecx,ecx 00000001`3faa102a call qword ptr [MemoryLeak_ProcessHeap!_imp_HeapCreate (00000001`3faa7000)] 00000001`3faa1030 mov rbx,rax 00000001`3faa1033 xor edx,edx 00000001`3faa1035 mov r8d,100000h 00000001`3faa103b mov rcx,rbx 00000001`3faa103e call qword ptr [MemoryLeak_ProcessHeap!_imp_HeapAlloc (00000001`3faa7008)]

0:000> dps 00000001`3faa7008 L1 00000001`3faa7008 00000000`77b21b70 ntdll!RtlAllocateHeap

The stack trace fragment from x86 Vista user dump even more straightforward:

0040fa00 77946e0c ntdll!RtlAllocateHeap+0×1e3 0040fa04 0022103a MemoryLeak_ProcessHeap!wmain+0×3a 0040fa08 7677d0e9 kernel32!BaseThreadInitThunk+0xe 0040fa0c 779219bb ntdll!__RtlUserThreadStart+0×23 0040fa10 7792198e ntdll!_RtlUserThreadStart+0×1b 0040fa14 7798924f ntdll!RtlpLogCapturedStackTrace+0×103

Of course, we could simply disassemble wmain after identifying our thread but in real life functions are longer and leaking allocations could have happened from frames not present on current stack traces.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Models, Software Behavior Patterns, Software Defect Construction | No Comments »

Icons for Memory Dump Analysis Patterns (Part 42)

Wednesday, May 19th, 2010

Today we introduce an icon for Double Free (kernel pool) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

Icons for Memory Dump Analysis Patterns (Part 41)

Tuesday, May 18th, 2010

Today we introduce an icon for Double Free (process heap) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

Icons for Memory Dump Analysis Patterns (Part 40)

Monday, May 17th, 2010

Today we introduce an icon for Unknown Component pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Icons, Visual Dump Analysis | No Comments »

Models for Memory and Trace Analysis Patterns (Part 1)

Sunday, May 16th, 2010

Due to many requests for memory dumps corresponding to crash dump analysis patterns I’ve started modeling software behaviour and defects. Every pattern will have an example application(s), service(s) or driver(s) or combination of them. Their execution results in memory layout that corresponds to memory or trace analysis patterns. Today we introduce an example model for Multiple Exceptions (user mode) pattern. The following source code models 3 threads each having an exception during their execution on Windows XP, Windows 7 and Windows Server 2008 R2:

// MultipleExceptions-UserMode // Copyright (c) 2010 Dmitry Vostokov // GNU GENERAL PUBLIC LICENSE // http://www.gnu.org/licenses/gpl-3.0.txt

#include <windows.h> #include <process.h>

void thread_one(void *) { *(int *)NULL = 0; }

void thread_two(void *) { *(int *)NULL = 0; }

int main(int argc, WCHAR* argv[]) { _beginthread(thread_two, 0, NULL); _beginthread(thread_one, 0, NULL);

DebugBreak();

return 0; }

In fact, thread_one and thread_two can be replaced with just one function because they are identical. Visual C++ compiler does that during code optimization. On Windows 7 and W2K8 R2 I created LocalDumps registry key to save full crash dumps. On Windows XP I set Dr. Watson as a postmortem debugger (via drwtsn32 -i command and configured it to save full user dumps via drwtsn32 command that brings Dr. Watson GUI). Vista had some peculiar behaviour so I postponed its discussion for another post. The application can be downloaded from here (zip file contains source code, x86 and x64 binaries together with corresponding PDB files):

Download MultipleExceptions-UserMode.zip

Now I provide modeling results for x64 W2K8 R2 running on 2 processor machine. Windows 7 and Windows XP results are very similar. If we run x64 executable it crashes and a dump file is saved (x86 crash dump is similar). Default analysis command gives these results:

0:000> !analyze -v

[...]

FAULTING_IP: MultipleExceptions_UserMode!thread_two+0 00000001`3f8b1000 c704250000000000000000 mov dword ptr [0],0

EXCEPTION_RECORD: ffffffffffffffff -- (.exr 0xffffffffffffffff) ExceptionAddress: 000007fefddc2442 (KERNELBASE!DebugBreak+0x0000000000000002) ExceptionCode: 80000003 (Break instruction exception) ExceptionFlags: 00000000 NumberParameters: 1 Parameter[0]: 0000000000000000

[...]

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION} Breakpoint A breakpoint has been reached.

[...]

PRIMARY_PROBLEM_CLASS: STATUS_BREAKPOINT

[...]

STACK_TEXT: 00000001`3f8b1000 MultipleExceptions_UserMode!thread_two+0x0 00000001`3f8b10eb MultipleExceptions_UserMode!_callthreadstart+0x17 00000001`3f8b1195 MultipleExceptions_UserMode!_threadstart+0x95 00000000`778cf56d kernel32!BaseThreadInitThunk+0xd 00000000`77b03281 ntdll!RtlUserThreadStart+0x1d

[...]

We see debug break on the first thread:

0:000> kL Child-SP RetAddr Call Site 00000000`002eec78 000007fe`fdd913a6 ntdll!NtWaitForMultipleObjects+0xa 00000000`002eec80 00000000`778d3143 KERNELBASE!WaitForMultipleObjectsEx+0xe8 00000000`002eed80 00000000`77949025 kernel32!WaitForMultipleObjectsExImplementation+0xb3 00000000`002eee10 00000000`779491a7 kernel32!WerpReportFaultInternal+0x215 00000000`002eeeb0 00000000`779491ff kernel32!WerpReportFault+0x77 00000000`002eeee0 00000000`7794941c kernel32!BasepReportFault+0x1f 00000000`002eef10 00000000`77b6573c kernel32!UnhandledExceptionFilter+0x1fc 00000000`002eeff0 00000000`77ae5148 ntdll! ?? ::FNODOBFM::`string'+0x2365 00000000`002ef020 00000000`77b0554d ntdll!_C_specific_handler+0x8c 00000000`002ef090 00000000`77ae5d1c ntdll!RtlpExecuteHandlerForException+0xd 00000000`002ef0c0 00000000`77b1fe48 ntdll!RtlDispatchException+0x3cb 00000000`002ef7a0 000007fe`fddc2442 ntdll!KiUserExceptionDispatcher+0x2e 00000000`002efd58 00000001`3f8b103c KERNELBASE!DebugBreak+0×2 00000000`002efd60 00000001`3f8b13fb MultipleExceptions_UserMode!main+0×2c 00000000`002efd90 00000000`778cf56d MultipleExceptions_UserMode!__tmainCRTStartup+0×15b 00000000`002efdd0 00000000`77b03281 kernel32!BaseThreadInitThunk+0xd 00000000`002efe00 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

2 other threads show exception processing too:

0:000> ~1s; kL ntdll!NtDelayExecution+0xa: 00000000`77b201fa c3 ret Child-SP RetAddr Call Site 00000000`0076ef78 000007fe`fdd91203 ntdll!NtDelayExecution+0xa 00000000`0076ef80 00000000`77949175 KERNELBASE!SleepEx+0xab 00000000`0076f020 00000000`779491ff kernel32!WerpReportFault+0×45 00000000`0076f050 00000000`7794941c kernel32!BasepReportFault+0×1f 00000000`0076f080 00000000`77b6573c kernel32!UnhandledExceptionFilter+0×1fc 00000000`0076f160 00000000`77ae5148 ntdll! ?? ::FNODOBFM::`string’+0×2365 00000000`0076f190 00000000`77b0554d ntdll!_C_specific_handler+0×8c 00000000`0076f200 00000000`77ae5d1c ntdll!RtlpExecuteHandlerForException+0xd 00000000`0076f230 00000000`77b1fe48 ntdll!RtlDispatchException+0×3cb 00000000`0076f910 00000001`3f8b1000 ntdll!KiUserExceptionDispatcher+0×2e 00000000`0076fec8 00000001`3f8b10eb MultipleExceptions_UserMode!thread_two 00000000`0076fed0 00000001`3f8b1195 MultipleExceptions_UserMode!_callthreadstart+0×17 00000000`0076ff00 00000000`778cf56d MultipleExceptions_UserMode!_threadstart+0×95 00000000`0076ff30 00000000`77b03281 kernel32!BaseThreadInitThunk+0xd 00000000`0076ff60 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

0:001> ~2s; kL ntdll!NtDelayExecution+0xa: 00000000`77b201fa c3 ret Child-SP RetAddr Call Site 00000000`0086e968 000007fe`fdd91203 ntdll!NtDelayExecution+0xa 00000000`0086e970 00000000`77949175 KERNELBASE!SleepEx+0xab 00000000`0086ea10 00000000`779491ff kernel32!WerpReportFault+0×45 00000000`0086ea40 00000000`7794941c kernel32!BasepReportFault+0×1f 00000000`0086ea70 00000000`77b6573c kernel32!UnhandledExceptionFilter+0×1fc 00000000`0086eb50 00000000`77ae5148 ntdll! ?? ::FNODOBFM::`string’+0×2365 00000000`0086eb80 00000000`77b0554d ntdll!_C_specific_handler+0×8c 00000000`0086ebf0 00000000`77ae5d1c ntdll!RtlpExecuteHandlerForException+0xd 00000000`0086ec20 00000000`77b1fe48 ntdll!RtlDispatchException+0×3cb 00000000`0086f300 00000001`3f8b1000 ntdll!KiUserExceptionDispatcher+0×2e 00000000`0086f8b8 00000001`3f8b10eb MultipleExceptions_UserMode!thread_two 00000000`0086f8c0 00000001`3f8b1195 MultipleExceptions_UserMode!_callthreadstart+0×17 00000000`0086f8f0 00000000`778cf56d MultipleExceptions_UserMode!_threadstart+0×95 00000000`0086f920 00000000`77b03281 kernel32!BaseThreadInitThunk+0xd 00000000`0086f950 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

We look at unhandled exception filter parameter to get exception pointers information:

0:002> kv Child-SP RetAddr : Args to Child : Call Site [...] 00000000`0086ea70 00000000`77b6573c : 00000000`0086ebb0 00000000`00000006 00000001`00000000 00000000`00000001 : kernel32!UnhandledExceptionFilter+0×1fc

0:002> .exptr 00000000`0086ebb0

----- Exception record at 00000000`0086f7f0: ExceptionAddress: 000000013f8b1000 (MultipleExceptions_UserMode!thread_two) ExceptionCode: c0000005 (Access violation) ExceptionFlags: 00000000 NumberParameters: 2 Parameter[0]: 0000000000000001 Parameter[1]: 0000000000000000 Attempt to write to address 0000000000000000

----- Context record at 00000000`0086f300: rax=00000000000ef0b0 rbx=00000000000ef0b0 rcx=0000000000000000 rdx=0000000000000000 rsi=0000000000000000 rdi=0000000000000000 rip=000000013f8b1000 rsp=000000000086f8b8 rbp=0000000000000000 r8=000007fffffda000 r9=0000000000000000 r10=0000000000000045 r11=000007fffffd9328 r12=0000000000000000 r13=0000000000000000 r14=0000000000000000 r15=0000000000000000 iopl=0 nv up ei pl nz na pe nc cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010202 MultipleExceptions_UserMode!thread_two: 00000001`3f8b1000 c704250000000000000000 mov dword ptr [0],0 ds:00000000`00000000=????????

What we now see that default analysis command showed the break instruction exception record and error code from the first thread but IP and stack trace from other threads having NULL pointer access violation exception.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging, Pattern Models, Software Behavior Patterns, Software Defect Construction | No Comments »