Late night debugging

time to read 5 min | 919 words

[I wrote this several days ago]

The hour is 03:15 AM, and I’m sitting here satisfied. Another bug eliminated, another enemy conquered. And this one is a tricky one.
I’ve created an application that loads Caudill’s TreeListView as its main UI. Now, my problem was that after I created about 50% of the application, I decided to work on the start-up data load, and then the application started to get nasty.
An IndexOutOfBoundException charged out of nowhere, directly into my flanks. I was determined, however, and after donning my debugging armor counter-attacked.

First, I traced the application to where it barfed, which wasn’t nice, it uses threads so it won’t freeze (lot of network action).
Eventually I managed to track the error to a method which was adding items to the TreeListView.
Now, that was strange, because the exact same code was working just a few minutes ago when I was using it to insert items after the application loaded.
I commented the line that called the insertion on start-up, and… woila – everything works!

Then I knew that it wasn’t going to be nice. Nevertheless, I set to track the path of the enemy’s army… err program execution, I mean.
I found out that I inserted items into the TreeListView before I added columns to it. Aha, I thought, now I got it! Fixed this, compile and run… but IndexOutOfBound has managed to sneak behind me again, leaving me with no other option but following the entire execution path of the program when I did manage to insert the items (on normal program execution).

Tired and panting, I finished that battle, but I felt victorious, I used the campaign to refactor my forces organization, and I was certain that they would withstand any attack. But over-confidence was my failing, for as I tried once more to head for the territories I desired. I’ve tracked the traitor deep into the enemy lines, until I could no longer follow without risking the dreaded disassembly. But I thought I’d it now, I managed to reinterduce inserting the items without adding columns, so I was confident that all will be fine.

The exception caught me unaware, leaving me frustrated and screaming.
Time to regroup and do some thinking, I thought, so I commented the insertion on startup and tried invading again. But I stopped short, afraid, for there was no opposition this route.
Now I knew that I’d a spy on my side, for something was very wrong.
Hungry for blood, I attempted to throw confusion in the enemy’s lines and checked the startup data.
I wondered… could it be… but the changes were made in the application, shouldn’t it betray me then?
Change the startup data to match exactly to that created in the application and test.
Success, I’d a beachhead on the enemy’s front.
But it was still too early to get cocky; I tried to change the startup data again, and checked what this might cause.
Treason! Mayhem! The exception only struck if I tried to insert the most important items.
But how could the enemy reveal that? The only difference I could see that some of the items were selected (they were created and then selected on previous, more successful campaigns).
Impossible, for such a small change to create such drastic measurements! Yet I’d seen it with my own eyes.

Item. Checked = Group. Selected;

This was the traitor.

If Group.Selected was true, then I was for an unpleasant surprise trying to insert.
But why should it make any difference?
I tested, commenting this line and sending scouts ahead. They returned with glowing eyes, talking about a rich land, if only I could overcome the treason in my own camp…
I could not get rid of the traitor; he was too dear to me, so I sent him to the front, after the insertion occurred.
And a miracle occurred, my surprised attack was successful, and I had scored the enemy lines in many fronts.
But there was still the matter of the traitor…
I sent him to the front with a small unit, and he excelled, and so I slowly enlarged his command until I finally had so sent him a lieutenant – and then disaster struck.
Again a flank attack, directly at my weak spot. And now I’ve located the real tratior.
He was a small routine, meant to handle ItemCheck called from  the TreeListView, the problem with him was that he used this code:

Group add_grp = Messages.Items[e.Index].Tag as Group;

Apparently, TreeListView (and ListView, its base) first call the ItemCheck delegate when they get an item with Checked = true and only afterward they add the item to their Item list.
So whenever this routine was called, it would generate an IndexOutOfBoundException, I couldn’t trace it to its real location using StackTrace because I’m using threads to create a responsive UI.

Conclusions:

  • Always have a UnhandledException and ThreadException handlers, that could’ve saved me a long time, I just tested it, and it would’ve give me the real stack trace of the error which would’ve enabled me to solve this in a few minutes.
  • I would’ve never caught on to this bug if I wasn’t trying to repreduce the problem and settle on the workaround.
  • Debugging multi-threading code is fun as an excrise for the bored mind.
  • The only reason that I got this exception from the main thread was that I was using Invoke to update the UI, otherwise, I was into more trouble.
  • That was a lovely way to spend the night, thank you very much.