Just another debugging story from the trenches

2016-05-27 23:23  a-debug-story    [permalink]

It's all logic, really. Once you get to the bottom of it. But getting there... Phew!

So I was working on something that had a line like this:

function TPostgresConnection.Insert(const TableName: UTF8String;
  const Values: array of OleVariant; const PKFieldName: UTF8String=''): int64;

I forgot what went wrong in the beginning (it was somewhere yesterday between midnight and bedtime...) but to check something out, to debug without a debugger so to speak, I wanted to dump a string. Deep within the data-layer you can't really access the things that handle the output to the user, so I just do this:

  raise Exception.Create('debug:'+sql1);

And then run the application again and reproduce the issue you're tending to. But it doesn't throw this exception,  it throws a quite severe access violation instead, strange. Not the error it started with, but none the less something strange going on in the exact same bit of code you're working on. But it was running late and I felt ready to go to sleep, so that is where I left it. It's always nicer to leave a project in working order at the end if the working day, but problems like this typically look different when viewed with a freshly rested set of eyes.

So the next day, let's move the debug exception somewhere higher up in the function body. Actually, all that happens before is handing the values in the Values array... So instead, I put this in near the top:

  sql1:='';
  l:=Length(Values);
  for i:=0 to l-1 do sql1:=sql1+','+IntToHex(VarType(Values[i]),4);
  raise Exception.Create(sql1);

Which gives me:

,0000,20C8,0015,FD18,46A4,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000,0000

Hmm, so it looks like the list of VarType's of the Values array, but these values are totally bogus! The VarType constants are (at least in older Delphi versions) right there at the top of System.pas (the unit that's always included, even if you don't list in a uses-clause), $0000 is varEmpty, but $FD18 is impossible since only varArray = $2000 and varByRef = $4000 are used of the highest 4 bits... And I'm sure I didn't pass any empties in. What is this?! Time to break out the real debugger then, I guess.

An xxm project pre-compiles files that have HTML and server-side pascal in the same source-files, into a full-fledged set of .pas files and a .dpr file, have that compiled, and then hot-swaps this new DLL in place to handle the next web-requests. So the usual development on an xxm project doesn't involve the Delphi IDE (I actually use atom.io since a while now.) but since the source is right there, you can open it in the plain old Delphi IDE and have the debugger start the DLL using something like xxmHttp.exe (the xxm handler that doesn't auto-recompile like xxmHttpDev.exe, since that would interfere with debugging.)

So, let's see what the debugger makes of this Values array the moment of this debug execption:

Values: (Unassigned, Variant array of Unknown, Unknown type: 21, Variant array of Unknown, Variant array of Unknown, Unassigned, Delphi exception EAccessViolation at $...

Yikes. But good news since with debugger it is doing the exact same thing wrong. That's something you can't take for granted, but that's another story.

So setting a breakpoint at this specific call to Insert, to see if the values get passed in:

Hey! Those are the correct values. But just one press of the F7 key later:

Bam, they're gone. Hmm, switching on the compiler "Use Debug DCUs" setting and retrying this doesn't bring me into any underlying code (sometimes some behind-the-scenes work is done on variants and strings for you), so nothing there...

And then it dawned on me! I know of one thing that can 'eat' your memory like that and it's compiler optimization.

By putting in that 'debug raise', using only an unrelated string, the optimization might conclude it can get away with releasing the memory of that Values array sooner, apparently disregarding the work that's been done on it. (Newer versions of Delphi may handle this differently, but that's another story...) So having a quick try with this:

  sql1:='';
  l:=Length(Values);
  for i:=0 to l-1 do sql1:=sql1+','+IntToHex(VarType(Values[i]),4);
  if l<1000 then
  raise Exception.Create(sql1);

And it works! So that's the weird misbehaving variant array out of the way. Now I feel extra silly not remembering what was originally the thing that I thought went wrong, was I just getting tired? This function is rather new, so I was just trying to debug for the first time, I guess. Still, makes for a nice story about debugging deeper and deeper until hitting the system, then finding out what's causing your trouble, calling on more of your knowledge of that system than usual.

(In case you want to know more about what I was working on in the first place, look here.)

→