Archive for June 19th, 2008

Crash Dump Analysis Patterns (Part 65)

Thursday, June 19th, 2008

Not My Version is another basic pattern of DLL Hell variety. It is when we look at the component timestamps and paths and realize that that one of the modules from the production environment is older than we had during development and testing. The lmft WinDbg command will produce the necessary output. If there are many modules we might want to create a CAD graph (Component Age Diagram) to spot anomalies. Component version check is one of the basic troubleshooting and system administration activities that will be fully illustrated in the forthcoming book “Crash Dump Analysis for System Administrators and Support Engineers” (ISBN-13: 978-1-906717-02-5). Here is one example (module start and end load addresses are removed for visual clarity):

0:000> kL
Child-SP          RetAddr           Call Site
00000000`0012fed8 00000001`40001093 MyDLL!fnMyDLL
00000000`0012fee0 00000001`40001344 2DLLs+0×1093
00000000`0012ff10 00000000`773acdcd 2DLLs+0×1344
00000000`0012ff60 00000000`774fc6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

0:000> lmft
module name
MyDLL    C:\OLD\MyDLL.dll Wed Jun 18 14:49:13 2004
user32   C:\Windows\System32\user32.dll Thu Feb 15 05:22:33 2007
kernel32 C:\Windows\System32\kernel32.dll Thu Nov 02 11:14:48 2006
ntdll    C:\Windows\System32\ntdll.dll Thu Nov 02 11:16:02 2006
2DLLs    C:\2DLLs\2DLLs.exe Thu Jun 19 10:46:44 2008 (485A2B04)
uxtheme  C:\Windows\System32\uxtheme.dll Thu Nov 02 11:15:07 2006
rpcrt4   C:\Windows\System32\rpcrt4.dll Tue Jul 17 05:21:15 2007
lpk      C:\Windows\System32\lpk.dll Thu Nov 02 11:12:33 2006
oleaut32 C:\Windows\System32\oleaut32.dll Thu Dec 06 05:09:35 2007
usp10    C:\Windows\System32\usp10.dll Thu Nov 02 11:15:03 2006
ole32    C:\Windows\System32\ole32.dll Thu Nov 02 11:14:31 2006
advapi32 C:\Windows\System32\advapi32.dll Thu Nov 02 11:11:35 2006
gdi32    C:\Windows\System32\gdi32.dll Thu Feb 21 04:40:51 2008
msvcrt   C:\Windows\System32\msvcrt.dll Thu Nov 02 11:13:37 2006
imm32    C:\Windows\System32\imm32.dll Thu Nov 02 11:13:15 2006
msctf    C:\Windows\System32\msctf.dll Thu Nov 02 11:13:42 2006

This pattern should be checked when we have instances of Module Variety and, especially, Duplicated Module. Note that this pattern can also easily become an anti-pattern when applied to an unknown component: Alien Component.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 64)

Thursday, June 19th, 2008

In addition to Module Variety there is another DLL Hell pattern that I call Duplicated Module. Here the same module is loaded at least twice and we can detect this when we see the module load address appended to its name in the output of lm commands (this is done to make the name of the module unique):

0:000> lm
start    end        module name
00b20000 0147f000   MSO_b20000
30000000 309a7000   EXCEL
30c90000 31848000   mso
71c20000 71c32000   tsappcmp
745e0000 7489e000   msi  
76290000 762ad000   imm32 
76b70000 76b7b000   psapi            
76f50000 76f63000   secur32            
77380000 77411000   user32
77670000 777a9000   ole32
77ba0000 77bfa000   msvcrt
77c00000 77c48000   gdi32          
77c50000 77cef000   rpcrt4           
77da0000 77df2000   shlwapi            
77e40000 77f42000   kernel32
77f50000 77feb000   advapi32           
7c800000 7c8c0000   ntdll

Usually his happens when the DLL is loaded from different locations. It can be exactly the same DLL version. The problems usually surface when there are different DLL versions and the new code loads the old version of the DLL and uses it. This may result in interface incompatibility issues and ultimately in application fault like an access violation.

In order to provide a dump to play with I created a small toy program called 2DLLs to model the worst case scenario similar to the one I encountered in a production environment a couple of days ago. The program periodically loads MyDLL module to call one of its functions. Unfortunately in one place it uses hardcoded relative path:

HMODULE hLib = LoadLibrary(L".\\DLL\\MyDLL.dll");

and in another place it relies on DLL search order:

hLib = LoadLibrary(L".\\MyDLL.dll");

PATH variable directories are used for search if this DLL was not found in other locations specified by DLL search order. We see that the problem can happen when another application is installed which uses the old version of that DLL and modifies PATH variable to point to its location. To model interface incompatibility I compiled the version of MyDLL that causes NULL pointer access violation when the same function is called from it. The DLL was placed into a separate folder and the PATH variable was modified to reference that folder:

C:\>set PATH=C:\OLD;%PATH%

The application crashes and the installed default postmortem debugger (CDB) saves its crash dump. If we open it we would see that it crashed in MyDLL_1e60000 module which should trigger suspicion:

0:000> r
rax=0000000001e61010 rbx=0000000000000000 rcx=0000775dcac00000
rdx=0000000000000000 rsi=0000000000000006 rdi=0000000000001770
rip=0000000001e61010 rsp=000000000012fed8 rbp=0000000000000000
 r8=0000000000000000  r9=000000000012fd58 r10=0000000000000001
r11=000000000012fcc0 r12=0000000000000000 r13=0000000000000002
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=00010200
MyDLL_1e60000!fnMyDLL:
00000000`01e61010 c704250000000000000000 mov dword ptr [0],0 ds:00000000`00000000=????????

0:000> kL
Child-SP          RetAddr           Call Site
00000000`0012fed8 00000001`40001093 MyDLL_1e60000!fnMyDLL
00000000`0012fee0 00000001`40001344 2DLLs+0×1093
00000000`0012ff10 00000000`773acdcd 2DLLs+0×1344
00000000`0012ff60 00000000`774fc6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

Looking at the list of modules we see two versions of MyDLL loaded from two different folders:

0:000> lm
start             end                 module name
00000000`01e60000 00000000`01e71000   MyDLL_1e60000
00000000`772a0000 00000000`7736a000   user32
00000000`77370000 00000000`774a1000   kernel32
00000000`774b0000 00000000`7762a000   ntdll
00000001`40000000 00000001`40010000   2DLLs
00000001`80000000 00000001`80011000   MyDLL
000007fe`fc9e0000 000007fe`fca32000   uxtheme
000007fe`fe870000 000007fe`fe9a9000   rpcrt4
000007fe`fe9b0000 000007fe`fe9bc000   lpk
000007fe`fea10000 000007fe`feae8000   oleaut32
000007fe`fecd0000 000007fe`fed6a000   usp10
000007fe`fedd0000 000007fe`fefb0000   ole32
000007fe`fefb0000 000007fe`ff0af000   advapi32
000007fe`ff0d0000 000007fe`ff131000   gdi32
000007fe`ff2e0000 000007fe`ff381000   msvcrt
000007fe`ff390000 000007fe`ff3b8000   imm32
000007fe`ff4b0000 000007fe`ff5b4000   msctf

0:000> lmv m MyDLL_1e60000
start             end                 module name
00000000`01e60000 00000000`01e71000   MyDLL_1e60000
    Loaded symbol image file: MyDLL.dll
    Image path: C:\OLD\MyDLL.dll
    Image name: MyDLL.dll
    Timestamp:        Wed Jun 18 14:49:13 2008 (48591259)
[…]

0:000> lmv m MyDLL
start             end                 module name
00000001`80000000 00000001`80011000   MyDLL
    Image path: C:\2DLLs\DLL\MyDLL.dll
    Image name: MyDLL.dll
    Timestamp:        Wed Jun 18 14:50:56 2008 (485912C0)
[...]

We can also see that the old version of MyDLL was the last loaded DLL:

0:000> !dlls -l

0x002c2680: C:\2DLLs\2DLLs.exe
      Base   0x140000000  EntryPoint  0x1400013b0  Size        0x00010000
      Flags  0x00004000  LoadCount   0x0000ffff  TlsIndex    0x00000000
             LDRP_ENTRY_PROCESSED

[...]

0x002ea9b0: C:\2DLLs\DLL\MyDLL.dll
      Base   0x180000000  EntryPoint  0x1800013d0  Size        0x00011000
      Flags  0x00084004  LoadCount   0x00000001  TlsIndex    0x00000000
             LDRP_IMAGE_DLL
             LDRP_ENTRY_PROCESSED
             LDRP_PROCESS_ATTACH_CALLED

[...]

0x002ec430: C:\OLD\MyDLL.dll
      Base   0×01e60000  EntryPoint  0×01e613e0  Size        0×00011000
      Flags  0×00284004  LoadCount   0×00000001  TlsIndex    0×00000000
             LDRP_IMAGE_DLL
             LDRP_ENTRY_PROCESSED
             LDRP_PROCESS_ATTACH_CALLED
             LDRP_IMAGE_NOT_AT_BASE

We can also see that the PATH variable points to its location and this might explain why it was loaded:

0:000> !peb
PEB at 000007fffffd6000
[...]
Path=C:\OLD;C:\Windows\system32;C:\Windows;[…]
[…]

We might think that the module having address in its name was loaded the last but this is not true. If we save another copy of the dump from the existing one using .dump command and load the new dump file we would see that order of the module names is reversed:

0:000> kL
Child-SP          RetAddr           Call Site
00000000`0012fed8 00000001`40001093 MyDLL!fnMyDLL
00000000`0012fee0 00000001`40001344 2DLLs+0×1093
00000000`0012ff10 00000000`773acdcd 2DLLs+0×1344
00000000`0012ff60 00000000`774fc6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

0:000> lm
start             end                 module name
00000000`01e60000 00000000`01e71000   MyDLL
00000000`772a0000 00000000`7736a000   user32
00000000`77370000 00000000`774a1000   kernel32
00000000`774b0000 00000000`7762a000   ntdll
00000001`40000000 00000001`40010000   2DLLs
00000001`80000000 00000001`80011000   MyDLL_180000000
000007fe`fc9e0000 000007fe`fca32000   uxtheme
000007fe`fe870000 000007fe`fe9a9000   rpcrt4
000007fe`fe9b0000 000007fe`fe9bc000   lpk
000007fe`fea10000 000007fe`feae8000   oleaut32
000007fe`fecd0000 000007fe`fed6a000   usp10
000007fe`fedd0000 000007fe`fefb0000   ole32
000007fe`fefb0000 000007fe`ff0af000   advapi32
000007fe`ff0d0000 000007fe`ff131000   gdi32
000007fe`ff2e0000 000007fe`ff381000   msvcrt
000007fe`ff390000 000007fe`ff3b8000   imm32
000007fe`ff4b0000 000007fe`ff5b4000   msctf

0:000> !dlls -l

[...]

0x002ec430: C:\OLD\MyDLL.dll
      Base   0×01e60000  EntryPoint  0×01e613e0  Size        0×00011000
      Flags  0×00284004  LoadCount   0×00000001  TlsIndex    0×00000000
             LDRP_IMAGE_DLL
             LDRP_ENTRY_PROCESSED
             LDRP_PROCESS_ATTACH_CALLED
             LDRP_IMAGE_NOT_AT_BASE

The postprocessed dump file can be downloaded from FTP to play with:

ftp://dumpanalysis.org/pub/CDAPatternDuplicatedModule.zip 

- Dmitry Vostokov @ DumpAnalysis.org -