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
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
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
Exception object: 014628a4
Exception type: System.InvalidOperationException
Message: Operation is not valid due to the current state of the object.
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)
0012e914 77e55dea [HelperMethodFrame: 0012e914]
0012e98c 00f10164 Test.DaysBetween(System.DateTime, System.DateTime)
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
Method Name: Test.DaysBetween(System.DateTime, System.DateTime)
0:000> !dumpil 00ee0d38
ilAddr = 004020a4
IL_0003: call System.DateTime::op_LessThan
IL_000d: brtrue.s IL_0015
IL_000f: newobj System.InvalidOperationException::.ctor
IL_0017: call System.DateTime::op_Subtraction
IL_001d: ldloca.s VAR OR ARG 2
IL_001f: call System.TimeSpan::get_Days
IL_0025: br.s IL_0027
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
Method Name: Test.Main()
0:000> !DumpIL 00ee0d10
ilAddr = 00402050
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_0021: leave.s IL_0033
} // end .try
IL_0025: ldstr “Could not calculate days between”
IL_002a: call System.Console::WriteLine
IL_0031: leave.s IL_0033
} // end .catch
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.