debugging

[Brian K. White]

todays war story...

report that usually works crashes after moving customers data to a 
different machine.

error message just says segmentation violation

Stepping through the debugger is impractical because a lot of looping 
happens on every record.

So I insert code to write to a temp file at various points in the 
processing. open the file in @once, writeline @rn to it at the top, 
writeline the name of every gosub and call just before every gosub or 
call, dozens...

Run it

log file shows it processed record 1, completed most of the processing, 
never got to record 2. (this report is processing-only, no auto 
processing, no index or sorting just -u -a)

Go back in and find the line with the last gosub/call that the log 
shows, to insert some more fine grained debug output within that gosub 
or call.

In the end the indicated gosub ran to completion and it was segfaulting 
on the next line of regular code that just had a simple test and an end 
statement, end of record processing if that test was true.

Insert a writeline just before that next line, insert a writeline at the 
beginning of the then: portion of the actual failing line,

so the original line was just:
126: if: mid(@td,"4","2") ne "01"
then: end

Now it had
126: if: mid(@td,"4","2") ne "01"
then: x = writeline(h,"line 126") ; end

And the very top line of processing has
1: if:
then: x = writeline(h, at rn)

Run it, the log file gets the "line 126" as the last line.

This means it's crashing on the END statement, or crashing somewhere 
between the end (of current record handling, but _before_ starting the 
next record, because the very top line is a writeline @rn, and the log 
file does not get this new record number written to it. It ends with 
"line 126"

How in the world could you ever debug THAT?

Had to resort to strace. strace is a little hard to explain how to 
decipher it, but basically the segv happens right after trying to read 
file handle 38, and file handle 38 at that time, was an index in some 
other file "/path/to/filepro/logfield/indexadts.P"
(adts was the current qualifier, and the current file is not logfield, 
that's a lookup)

Rebuilt that index and all was well.

The point is that I don't see how you could ever debug this using the 
normal tools. I know what that index in that other file is used for and 
where it's used from. It's in one of the many gosubs that actually ran 
to completion without error. That one loops through all fields in the 
current file and logs any changes to another filepro file. Those gosubs 
all ran without error. The crash happened in the no-mans-land *between* 
END and line 1. Most of the line with the end worked, iow the if: part 
didn't crash, shown by the fact that writeline "line 126" worked. Line 1 
worked fine, shown by the fact that writeline @rn worked in the first 
record. The on-screen error messages did not say anything about logfield 
or logfield index P. Even stepping through the debugger wouldn't show it 
because the code that actually used that lookup and that index, actually 
worked. The crash did not happen on any line that looked like it had 
anything to do with any lookups or anything.

strace is your friend.

-- 
bkw