Thursday, January 21, 2010

WinDbg for beginners

A few days ago I have encountered a strange problem. When I copied IronPython.Modules.dll to my application's folder, it freezed. Strange. It looked like a bug in IronPython for me but it wasn't. With Dino Viehland help, I have found the bug in Delphi code. Dino used WinDbg to discover what is going on in the code. I show you it is not so hard to use it.

WinDbg is part of Debuging Tolls for Windows. Download and install appropriate version for your Windows (32 or 64 bit). And download the bugged application.

The IpyTest.exe is Delphi 7 application that creates the CLR and runs function Add3 from Host.dll inside the CLR. The Add3 function creates IronPython engine and returns result of adding number 3 to the input variabl. So when you run IpyTest.exe you should see

C:\IronPythonBug\Delphi>IpyTest.exe
CLRVersion = v2.0.50727
8 + 3 = 11

You may actually see it because this bug does not appear on all computers. But on mine, I see just the CLRVersion. Then the program freezes.

Let's debug the application in WinDbg:

"C:\Program Files\Debugging Tools for Windows (x86)\windbg.exe" C:\IronPythonBug\Delphi\IpyTest.exe

When WinDbg and IpyTest.exe start, you see this:


Enter the following commands:

0:000> sxe clr
0:000> sxe av
0:000> .symfix
0:000> .reload
Reloading current modules
............

If you want to know what these commands do, check the help :-) Then run the debugger with g command. It runs for a while and then it freezes with the following output:

0:000> g
ModLoad: 76390000 763ad000   C:\WINDOWS\system32\IMM32.DLL
ModLoad: 79000000 79046000   C:\WINDOWS\system32\mscoree.dll
ModLoad: 77f60000 77fd6000   C:\WINDOWS\system32\SHLWAPI.dll
ModLoad: 79e70000 7a400000   c:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll
ModLoad: 78130000 781cb000   C:\WINDOWS\WinSxS\x86_Microsoft.VC80.CRT_1fc8b3b9a1e18e3b_8.0.50727.3053_x-ww_b80fa8ca\MSVCR80.dll
ModLoad: 7c9c0000 7d1d7000   C:\WINDOWS\system32\shell32.dll
ModLoad: 773d0000 774d3000   C:\WINDOWS\WinSxS\x86_Microsoft.Windows.Common-Controls_6595b64144ccf1df_6.0.2600.5512_x-ww_35d4ce83\comctl32.dll
ModLoad: 5d090000 5d12a000   C:\WINDOWS\system32\comctl32.dll
ModLoad: 790c0000 79bb7000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\mscorlib\6d667f19d687361886990f3ca0f49816\mscorlib.ni.dll
ModLoad: 79060000 790bb000   c:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorjit.dll
ModLoad: 33200000 3322c000   Microsoft.Scripting.dll
ModLoad: 68000000 68036000   C:\WINDOWS\system32\rsaenh.dll
ModLoad: 64020000 64033000   c:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorsec.dll
ModLoad: 76c30000 76c5e000   C:\WINDOWS\system32\WINTRUST.dll
ModLoad: 77a80000 77b15000   C:\WINDOWS\system32\CRYPT32.dll
ModLoad: 77b20000 77b32000   C:\WINDOWS\system32\MSASN1.dll
ModLoad: 76c90000 76cb8000   C:\WINDOWS\system32\IMAGEHLP.dll
ModLoad: 74e30000 74e9d000   C:\WINDOWS\system32\RichEd20.dll
ModLoad: 04a30000 04cf5000   C:\WINDOWS\system32\xpsp2res.dll
ModLoad: 769c0000 76a74000   C:\WINDOWS\system32\userenv.dll
ModLoad: 5b860000 5b8b5000   C:\WINDOWS\system32\netapi32.dll
ModLoad: 75e60000 75e73000   C:\WINDOWS\system32\cryptnet.dll
ModLoad: 76bf0000 76bfb000   C:\WINDOWS\system32\PSAPI.DLL
ModLoad: 722b0000 722b5000   C:\WINDOWS\system32\SensApi.dll
ModLoad: 4d4f0000 4d549000   C:\WINDOWS\system32\WINHTTP.dll
ModLoad: 76f60000 76f8c000   C:\WINDOWS\system32\WLDAP32.dll
ModLoad: 33200000 3322c000   C:\IronPythonBug\Delphi\Microsoft.Scripting.dll
ModLoad: 34700000 34860000   IronPython.dll
ModLoad: 34700000 34860000   C:\IronPythonBug\Delphi\IronPython.dll
ModLoad: 33000000 33064000   Microsoft.Scripting.Core.dll
ModLoad: 33000000 33064000   C:\IronPythonBug\Delphi\Microsoft.Scripting.Core.dll
ModLoad: 7a440000 7abc5000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System\80978a322d7dd39f0a71be1251ae395a\System.ni.dll
ModLoad: 33400000 334dc000   Microsoft.Dynamic.dll
ModLoad: 33400000 334dc000   C:\IronPythonBug\Delphi\Microsoft.Dynamic.dll
ModLoad: 73000000 73008000   Microsoft.Scripting.ExtensionAttribute.dll
ModLoad: 73000000 73008000   C:\IronPythonBug\Delphi\Microsoft.Scripting.ExtensionAttribute.dll
ModLoad: 34c10000 34c80000   IronPython.Modules.dll
ModLoad: 34c10000 34c80000   C:\IronPythonBug\Delphi\IronPython.Modules.dll
ModLoad: 64890000 64981000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System.Configuration\b82c00e2d24305ad6cb08556e3779b75\System.Configuration.ni.dll
ModLoad: 637a0000 63cd6000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System.Xml\773a9786013451d3baaeff003dc4230f\System.Xml.ni.dll
(b6c.ef0): Unknown exception - code c0000091 (first chance)

>>> many lines omitted <<<

(b6c.ef0): Unknown exception - code c0000091 (first chance)

The IpyTest.exe window contains just a text: CLRVersion = v2.0.50727. Break the debugger with Ctrl-Break. We see there is an unknown exception with code c0000091. Let's restart the program and tell WinDbg to stop on this exception with the following commands:

.restart
sxe c0000091
.symfix
.reload
g

Here is the output:

0:003> .restart
CommandLine: C:\IronPythonBug\Delphi\IpyTest.exe
Symbol search path is: srv*
Executable search path is: 
ModLoad: 00400000 00455000   image00400000
ModLoad: 7c900000 7c9af000   ntdll.dll
ModLoad: 7c800000 7c8f6000   C:\WINDOWS\system32\kernel32.dll
ModLoad: 7e410000 7e4a1000   C:\WINDOWS\system32\user32.dll
ModLoad: 77f10000 77f59000   C:\WINDOWS\system32\GDI32.dll
ModLoad: 77dd0000 77e6b000   C:\WINDOWS\system32\advapi32.dll
ModLoad: 77e70000 77f02000   C:\WINDOWS\system32\RPCRT4.dll
ModLoad: 77fe0000 77ff1000   C:\WINDOWS\system32\Secur32.dll
ModLoad: 77120000 771ab000   C:\WINDOWS\system32\oleaut32.dll
ModLoad: 77c10000 77c68000   C:\WINDOWS\system32\msvcrt.dll
ModLoad: 774e0000 7761d000   C:\WINDOWS\system32\ole32.dll
ModLoad: 77c00000 77c08000   C:\WINDOWS\system32\version.dll
(ea8.a14): Break instruction exception - code 80000003 (first chance)
eax=00351ec4 ebx=7ffd4000 ecx=00000004 edx=00000010 esi=00351f98 edi=00351ec4
eip=7c90120e esp=0012fb20 ebp=0012fc94 iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202
ntdll!DbgBreakPoint:
7c90120e cc              int     3
0:000> sxe c0000091
0:000> .symfix
0:000> .reload
Reloading current modules
............
0:000> g
ModLoad: 76390000 763ad000   C:\WINDOWS\system32\IMM32.DLL
ModLoad: 79000000 79046000   C:\WINDOWS\system32\mscoree.dll
ModLoad: 77f60000 77fd6000   C:\WINDOWS\system32\SHLWAPI.dll
ModLoad: 79e70000 7a400000   c:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll
ModLoad: 78130000 781cb000   C:\WINDOWS\WinSxS\x86_Microsoft.VC80.CRT_1fc8b3b9a1e18e3b_8.0.50727.3053_x-ww_b80fa8ca\MSVCR80.dll
ModLoad: 7c9c0000 7d1d7000   C:\WINDOWS\system32\shell32.dll
ModLoad: 773d0000 774d3000   C:\WINDOWS\WinSxS\x86_Microsoft.Windows.Common-Controls_6595b64144ccf1df_6.0.2600.5512_x-ww_35d4ce83\comctl32.dll
ModLoad: 5d090000 5d12a000   C:\WINDOWS\system32\comctl32.dll
ModLoad: 790c0000 79bb7000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\mscorlib\6d667f19d687361886990f3ca0f49816\mscorlib.ni.dll
ModLoad: 79060000 790bb000   c:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorjit.dll
ModLoad: 33200000 3322c000   Microsoft.Scripting.dll
ModLoad: 68000000 68036000   C:\WINDOWS\system32\rsaenh.dll
ModLoad: 64020000 64033000   c:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorsec.dll
ModLoad: 76c30000 76c5e000   C:\WINDOWS\system32\WINTRUST.dll
ModLoad: 77a80000 77b15000   C:\WINDOWS\system32\CRYPT32.dll
ModLoad: 77b20000 77b32000   C:\WINDOWS\system32\MSASN1.dll
ModLoad: 76c90000 76cb8000   C:\WINDOWS\system32\IMAGEHLP.dll
ModLoad: 74e30000 74e9d000   C:\WINDOWS\system32\RichEd20.dll
ModLoad: 04a30000 04cf5000   C:\WINDOWS\system32\xpsp2res.dll
ModLoad: 769c0000 76a74000   C:\WINDOWS\system32\userenv.dll
ModLoad: 5b860000 5b8b5000   C:\WINDOWS\system32\netapi32.dll
ModLoad: 75e60000 75e73000   C:\WINDOWS\system32\cryptnet.dll
ModLoad: 76bf0000 76bfb000   C:\WINDOWS\system32\PSAPI.DLL
ModLoad: 722b0000 722b5000   C:\WINDOWS\system32\SensApi.dll
ModLoad: 4d4f0000 4d549000   C:\WINDOWS\system32\WINHTTP.dll
ModLoad: 76f60000 76f8c000   C:\WINDOWS\system32\WLDAP32.dll
ModLoad: 33200000 3322c000   C:\IronPythonBug\Delphi\Microsoft.Scripting.dll
ModLoad: 34700000 34860000   IronPython.dll
ModLoad: 34700000 34860000   C:\IronPythonBug\Delphi\IronPython.dll
ModLoad: 33000000 33064000   Microsoft.Scripting.Core.dll
ModLoad: 33000000 33064000   C:\IronPythonBug\Delphi\Microsoft.Scripting.Core.dll
ModLoad: 7a440000 7abc5000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System\80978a322d7dd39f0a71be1251ae395a\System.ni.dll
ModLoad: 33400000 334dc000   Microsoft.Dynamic.dll
ModLoad: 33400000 334dc000   C:\IronPythonBug\Delphi\Microsoft.Dynamic.dll
ModLoad: 73000000 73008000   Microsoft.Scripting.ExtensionAttribute.dll
ModLoad: 73000000 73008000   C:\IronPythonBug\Delphi\Microsoft.Scripting.ExtensionAttribute.dll
ModLoad: 34c10000 34c80000   IronPython.Modules.dll
ModLoad: 34c10000 34c80000   C:\IronPythonBug\Delphi\IronPython.Modules.dll
ModLoad: 64890000 64981000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System.Configuration\b82c00e2d24305ad6cb08556e3779b75\System.Configuration.ni.dll
ModLoad: 637a0000 63cd6000   C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System.Xml\773a9786013451d3baaeff003dc4230f\System.Xml.ni.dll
(ea8.a14): Unknown exception - code c0000091 (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=ffffff00 ebx=02643d64 ecx=02640010 edx=02648e3c esi=02643bd4 edi=02640010
eip=79098f48 esp=0012ce30 ebp=0012ce34 iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023  ds=0023  es=0023  fs=0038  gs=0000             efl=00010202
mscorjit!Compiler::FlatFPIsSameAsFloat+0xa:
79098f48 d945fc          fld     dword ptr [ebp-4]    ss:0023:0012ce30=02640010

WinDbg stopped on the exception. Nice. And what now? Analyze the exception!

0:000> !analyze -v
*******************************************************************************
*                                                                             *
*                        Exception Analysis                                   *
*                                                                             *
*******************************************************************************

*** WARNING: Unable to verify checksum for C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\mscorlib\6d667f19d687361886990f3ca0f49816\mscorlib.ni.dll
*** WARNING: Unable to verify checksum for image00400000
*** ERROR: Module load completed but symbols could not be loaded for image00400000
*** ERROR: Module load completed but symbols could not be loaded for C:\WINDOWS\system32\xpsp2res.dll
*** ERROR: Module load completed but symbols could not be loaded for C:\IronPythonBug\Delphi\Microsoft.Scripting.Core.dll
*** ERROR: Module load completed but symbols could not be loaded for C:\IronPythonBug\Delphi\Microsoft.Scripting.dll
*** ERROR: Module load completed but symbols could not be loaded for C:\IronPythonBug\Delphi\Microsoft.Dynamic.dll
*** ERROR: Module load completed but symbols could not be loaded for C:\IronPythonBug\Delphi\IronPython.dll
*** ERROR: Module load completed but symbols could not be loaded for C:\IronPythonBug\Delphi\IronPython.Modules.dll
*** WARNING: Unable to verify checksum for C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System.Xml\773a9786013451d3baaeff003dc4230f\System.Xml.ni.dll
*** WARNING: Unable to verify checksum for C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System.Configuration\b82c00e2d24305ad6cb08556e3779b75\System.Configuration.ni.dll
*** ERROR: Module load completed but symbols could not be loaded for C:\IronPythonBug\Delphi\Microsoft.Scripting.ExtensionAttribute.dll
*** WARNING: Unable to verify checksum for C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\System\80978a322d7dd39f0a71be1251ae395a\System.ni.dll
*************************************************************************
***                                                                   ***
***                                                                   ***
***    Your debugger is not using the correct symbols                 ***
***                                                                   ***
***    In order for this command to work properly, your symbol path   ***
***    must point to .pdb files that have full type information.      ***
***                                                                   ***
***    Certain .pdb files (such as the public OS symbols) do not      ***
***    contain the required information.  Contact the group that      ***
***    provided you with these symbols if you need this command to    ***
***    work.                                                          ***
***                                                                   ***
***    Type referenced: kernel32!pNlsUserInfo                         ***
***                                                                   ***
*************************************************************************
*************************************************************************
***                                                                   ***
***                                                                   ***
***    Your debugger is not using the correct symbols                 ***
***                                                                   ***
***    In order for this command to work properly, your symbol path   ***
***    must point to .pdb files that have full type information.      ***
***                                                                   ***
***    Certain .pdb files (such as the public OS symbols) do not      ***
***    contain the required information.  Contact the group that      ***
***    provided you with these symbols if you need this command to    ***
***    work.                                                          ***
***                                                                   ***
***    Type referenced: kernel32!pNlsUserInfo                         ***
***                                                                   ***
*************************************************************************

FAULTING_IP: 
mscorjit!Compiler::FlatFPIsSameAsFloat+7
79098f45 d95dfc          fstp    dword ptr [ebp-4]

EXCEPTION_RECORD:  ffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 79098f45 (mscorjit!Compiler::FlatFPIsSameAsFloat+0x00000007)
   ExceptionCode: c0000091
  ExceptionFlags: 00000000
NumberParameters: 1
   Parameter[0]: 00000000

FAULTING_THREAD:  00000a14

DEFAULT_BUCKET_ID:  WRONG_SYMBOLS

PROCESS_NAME:  image00400000

ERROR_CODE: (NTSTATUS) 0xc0000091 - {EXCEPTION}  Floating-point overflow.

EXCEPTION_CODE: (NTSTATUS) 0xc0000091 - {EXCEPTION}  Floating-point overflow.

EXCEPTION_PARAMETER1:  00000000

NTGLOBALFLAG:  2000000

APPLICATION_VERIFIER_FLAGS:  0

MANAGED_STACK: 
(TransitionMU)
0012E0F8 02657F5C IronPython!IronPython.Runtime.PythonContext.InitializeSystemState()+0xec
0012E108 026532E7 IronPython!IronPython.Runtime.PythonContext..ctor(Microsoft.Scripting.Runtime.ScriptDomainManager, System.Collections.Generic.IDictionary`2)+0x247
(TransitionUM)
(TransitionMU)
0012E60C 792EF7C0 mscorlib_ni!System.RuntimeMethodHandle.InvokeConstructor(System.Object[], System.SignatureStruct, System.RuntimeTypeHandle)+0x10
0012E640 792EF55A mscorlib_ni!System.Reflection.RuntimeConstructorInfo.Invoke(System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)+0xfa
0012E6D0 79288D96 mscorlib_ni!System.RuntimeType.CreateInstanceImpl(System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo, System.Object[])+0x3e6
0012E730 79280E10 mscorlib_ni!System.Activator.CreateInstance(System.Type, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo, System.Object[])+0x70
0012E754 02652BA1 Microsoft_Scripting!Microsoft.Scripting.Runtime.LanguageConfiguration.LoadLanguageContext(Microsoft.Scripting.Runtime.ScriptDomainManager, Boolean ByRef)+0x
LAST_CONTROL_TRANSFER:  from 790a40fa to 79098f48

PRIMARY_PROBLEM_CLASS:  WRONG_SYMBOLS

BUGCHECK_STR:  APPLICATION_FAULT_WRONG_SYMBOLS

STACK_TEXT:  
79098f45 mscorjit!Compiler::FlatFPIsSameAsFloat+0x7


FOLLOWUP_IP: 
mscorjit!Compiler::FlatFPIsSameAsFloat+7
79098f45 d95dfc          fstp    dword ptr [ebp-4]

SYMBOL_STACK_INDEX:  0

SYMBOL_NAME:  mscorjit!Compiler::FlatFPIsSameAsFloat+7

FOLLOWUP_NAME:  MachineOwner

MODULE_NAME: mscorjit

IMAGE_NAME:  mscorjit.dll

DEBUG_FLR_IMAGE_TIMESTAMP:  492b8341

STACK_COMMAND:  dds 79098f45 ; kb

FAILURE_BUCKET_ID:  WRONG_SYMBOLS_c0000091_mscorjit.dll!Compiler::FlatFPIsSameAsFloat

BUCKET_ID:  APPLICATION_FAULT_WRONG_SYMBOLS_mscorjit!Compiler::FlatFPIsSameAsFloat+7

Followup: MachineOwner
---------

Floating-point overflow in Delphi when working with foreign .dlls? Ask uncle Google about it and after a while you find something like this. Or, as in my case, Dino sends you the direct link :-)

Another useful commands:

.loadby sos mscorwks
!clrstack -a
!DumpStackObjects
!dumpobj 07d996fc
.load C:\Program Files (x86)\Microsoft Silverlight\3.0.40818.0\sos.dll
.load C:\Windows\Microsoft.NET\Framework\v2.0.50727\SOS.dll
.sympath SRV*c:\dos\DebugSymbols*http://msdl.microsoft.com/download/symbols

To recap it:

If you have a problem with your program, run it in WinDbg and !analyze -v it. WinDbg tells you a lot of useful information which you can utilize and find a solution for your problem.