Viewing IL at Debug Time

Last week, I mentioned Yiru’s post on using SOS to see the IL of a dynamically generated method.  Yiru’s post is about lightweight code gen, but the technique she shows is useful for more general purpose managed debugging .  Let’s work through debugging a program that’s supposed to display the number of days between two dates.  The problem is that the author of this program didn’t seem to test it before releasing it, and currently it only says that it cannot calculate the date difference.

I’ll start by firing up WinDbg and requesting that I break on any first chance managed exceptions. (Throughout this post, I’ll be italicising command I type and highlighting in bold and maroon debugger output that’s important for use later on):

0:000> sxe clr
0:000> g
…
ModLoad: 5b0c0000 5b1c0000   C:\WINNT\Microsoft.NET\Framework\v2.0.50607\mscorjit.dll
(960.860): CLR exception - code e0434f4d (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=0012e6e0 ebx=00000001 ecx=00000000 edx=00000006 esi=0012e7dc edi=0012e7d8
eip=77e55dea esp=0012e6dc ebp=0012e730 iopl=0         nv up ei pl nz na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202
KERNEL32!RaiseException+0x53:
77e55dea 5e               pop     esi

Once I’ve gotten the exception, I’ll load up SOS and see if displaying the exception gives any clue to what the problem might be:

0:000> !load sos
0:000> !pe
Exception object: 014628a4
Exception type: System.InvalidOperationException
Message: Operation is not valid due to the current state of the object.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80131509

Huh, well that’s not very useful at all.  It appears that the author of this program didn’t supply an exception message, so InvalidOperationException just used its default exception.  In order to figure out why this exception was thrown, I’m going to look at the IL of the method that threw.  Why look at the IL, instead of just using .frame or the call stack window to pull up the source for the method?  Well, in this case I don’t have access to source code or symbols for the program.

In order to do that, I’ll have to first take a look at the call stack:

0:000> !CLRStack -p
OS Thread Id: 0x860 (0)
ESP       EIP    
0012e914 77e55dea [HelperMethodFrame: 0012e914]
0012e98c 00f10164 Test.DaysBetween(System.DateTime, System.DateTime)
    PARAMETERS:
        start = <no data>
        end = <no data>

0012e9c0 00f100bd Test.Main()
0012f450 5d57671d [GCFrame: 0012f450]

I can see that the DaysBetween method is responsible for throwing the exception, since it’s at the top of the call stack.  I also notice that it’s a static method (since there is no this parameter given), and that the IP of the throw was 0x00f10164.  The SOS DumpIL command requires a MethodDesc as a parameter, so I’ll first use the ip2md command to get the MethodDesc that covers that IP, and then dump it’s IL:

0:000> !ip2md 00f10164
MethodDesc: 00ee0d38
Method Name: Test.DaysBetween(System.DateTime, System.DateTime)
Class: 00ef12c0
MethodTable: 00ee0d9c
mdToken: 06000002
Module: 001e0d40
IsJitted: yes
m_CodeOrIL: 00f10100
0:000> !dumpil 00ee0d38
ilAddr = 004020a4
IL_0000: nop
IL_0001: ldarg.1
IL_0002: ldarg.0
IL_0003: call System.DateTime::op_LessThan
IL_0008: ldc.i4.0
IL_0009: ceq
IL_000b: stloc.1
IL_000c: ldloc.1
IL_000d: brtrue.s IL_0015
IL_000f: newobj System.InvalidOperationException::.ctor
IL_0014: throw
IL_0015: ldarg.1
IL_0016: ldarg.0
IL_0017: call System.DateTime::op_Subtraction
IL_001c: stloc.2
IL_001d: ldloca.s VAR OR ARG 2
IL_001f: call System.TimeSpan::get_Days
IL_0024: stloc.0
IL_0025: br.s IL_0027
IL_0027: ldloc.0
IL_0028: ret

From looking at the IL of the throwing method, it appears that between IL_0000 and IL_000d we check to see if the second parameter is less than the first parameter (remember ldarg.0 gets the first parameter in this method since the method is static).  If it is, then we jump to IL_0015, however if is not then between IL_000f and IL_0014 we use the default InvalidOperationException constructor and throw.

That analysis leads me to believe that the second parameter was in fact not less than the first parameter.  Lets take a look at the calling method to try to figure out what the parameters were.  From the call stack above, we know that the calling method is Main, and the IP where the call was made is 0x00f100bd.  Following the same !ip2md, !dumpil sequence we see:

0:000> !ip2md 00f100bd
MethodDesc: 00ee0d10
Method Name: Test.Main()
Class: 00ef12c0
MethodTable: 00ee0d9c
mdToken: 06000001
Module: 001e0d40
IsJitted: yes
m_CodeOrIL: 00f10070
0:000> !DumpIL 00ee0d10
ilAddr = 00402050
IL_0000: nop
.try
{
  IL_0001: nop
  IL_0002: call System.DateTime::get_Now
  IL_0007: ldc.i4 1980
  IL_000c: ldc.i4.s 9
  IL_000e: ldc.i4.s 15
  IL_0010: newobj System.DateTime::.ctor
  IL_0015: call Test::DaysBetween
  IL_001a: call System.Console::WriteLine
  IL_001f: nop
  IL_0020: nop
  IL_0021: leave.s IL_0033
} // end .try
.catch
{
  IL_0023: pop
  IL_0024: nop
  IL_0025: ldstr "Could not calculate days between"
  IL_002a: call System.Console::WriteLine
  IL_002f: nop
  IL_0030: nop
  IL_0031: leave.s IL_0033
} // end .catch
IL_0033: nop
IL_0034: ret

The call to DaysBetween is on line IL_0015, and looking just above the call site we see that at the time of the call the parameters on the IL stack are September 15, 1980 and the current date.  Clearly the current date is not less than a date in 1980, so it appears that the bug is in the order these parameters are given to DaysBetween.

In fact, with a little ildasm / ilasm magic, we can test that theory.  Moving IL_0002  to appear between IL_00010 and IL_0015 will reverse the order of the parameters to the method call, and result in the program running and telling me that it’s been 9,032 days since 9/15/1980.