Sunday, June 19, 2011

Keep a Debug Journal

Whether just starting a new job, or entering a long period of heads-down coding, something I have found helpful from time to time is keeping a "Debug Journal". This is another tool in your arsenal to solve problems. You may have spent an hour or twelve today struggling with an issue. In addition to making notes about what the fix is for that item so that you have it handy in case it reappears elsewhere, you can also look at the big picture and infer lessons which apply to a larger subset of problems. An entry from my own journal follows:
Problem: CGI Form submit, script is executed twice

Answer: HTML Validator plug-in for Firefox was making additional requests. I checked the Changelog and they were aware of the bug and it had been fixed. After I upgraded, everything was fine

Lesson: Involving another pair of eyes and another brain helped me greatly. For one thing, the other person involved wasn't experiencing the error, even when hitting my code. That got us to thinking about the browser. Then he sent me a link regarding the plug-in and voilĂ . Also, again I made a bad assumption - that there was a problem with the server, and not the client. I need to start asking myself what I am assuming after being frustrated by a problem. I also need to involve other people sooner.


Having another person look at the problem may seem like an obvious step, but one thing I want to stress is that this journal can help alert you to your own blind spots. I'm not sure if it was vanity or stubbornness but it took me too long to ask for help in this case. This is something I can work on during future troubleshooting. It is also a good example of drawing a larger lesson from a specific fix. Here is another:
Problem: Does the user have sufficient privileges to see this particular control and perform its function? Code is not always very friendly in looking this sort of thing up.

Answer: In dev, I hard-coded the username to be her if it was initially me:

if($ENV{REMOTE_USER} eq 'david') {
$ENV{REMOTE_USER} = 'betsy';
}
then I could see the screen from her point of view and saw that she did indeed have access.

Lesson: If the initial problem seems difficult, it might be worth a few minutes trying to figure out if there's an easier way to determine the answer.


In our software, we do have a feature that allows us to take the role of another user. However, the view is artificial and there are some constraints on the way it works, so it was not really useful to me in this case. The point here again is the larger picture: the privilege system is somewhat complex, both in code and in data. Hard coding the login was much faster and easier than the alternatives I was facing. Also, in this case, I ended up keeping this snippet handy and using it quite frequently to diagnose user issues. Another entry:
Problem: device_id's were showing up as 1 or 2 or 8 etc (expecting 5762,12428,etc).

Answer: That's what they freakin' were.

Lesson: Just because something might look a little weird, doesn't mean it isn't so. Check the source of the data first and see if it is correct before considering it a problem.


This one was a funny one. Since there are a significant number of devices being tracked by our system, I was used to seeing DEVICE_IDs in the database of say, "5728" or "14972". My brain did not want to accept a single-digit DEVICE_ID. It just so happened I was working with devices that were entered very early in the lifetime of the system. When I looked them up explicitly, they indeed had single-digit identifiers.

Assumptions are a major blind spot for me (and many other people, I suspect). Assumptions are difficult, since we can't really move forward diagnosing any problem without making some assumptions. We just have to try to keep combing through our minds for the bad or unnecessary ones.

And that's the gist of it. If nothing else, keeping a journal can be reenforcement of your experience, helping you to remember without even needing to look it up. But you can look it up if you need to! Several more entries follow without additional comment:


Problem: I keep saying "verified" is set to 1, so why isn't this code running?

Answer: Because that's not the only requirement to get to that code. "Submit" also needs to be set (case-sensitive), but instead, I have set "submit" (lower-case "s").

Fix: copied & pasted output of Data::Dumper of $qs right beside code, so I could compare what was being sent with how it was being tested

Lesson: Also, I was getting sleepy. That makes for bad debugging. Walk around a bit and come back to it.


Problem: alert() isn't working

Answer: the JavaScript command is there, the problem is that the JavaScript command preceding it causes an error. It was a focus() method called on a control that doesn't exist.

Lesson: If a JavaScript command isn't working, you should check the JavaScript console and also the HTML source. Furthermore, if any component of a program isn't working, check THAT component. No sense in adding debug code to a Perl script when the JavaScript is failing (at least as a first resort).


Problem: Script is plugging SYSDATE into records when I have a fixed date I want in there. At the end of the script, I changed the way the script works so that, at the end of processing, I plug the same date into whatever records' AS_OF_DATE field is NULL.

Answer: The problem is that when I changed the script to do this, I never went back and took out SYSDATE so that the records' AS_OF_DATE fields were NULL.

Lesson: I solved this one pretty quickly, but I'm not sure what I could have done differently. There were two parts of the script that needed to be changed and I only changed one part. I guess when I see that setting (foo to bar if foo is baz) isn't working, I should make sure I have set foo to baz first. That seems to be a common theme in slow debugging - assumptions. When you assume...

Monday, June 13, 2011

Hard Drive Paranoia

Brought my laptop running XP out of hibernation mode today and tried to start Firefox, and got some weird error about it not being able to start due to a missing file.  Tried to start something else and started seeing weirdness in other apps as well and decided to reboot.  Upon reboot, CHKDSK automatically ran and found (and seemingly fixed) a TON of errors.

I went to the Event Viewer (Start->Control Panel->Administrative Tools->Event Viewer) and could only find this error "The system failed to flush data to the transaction log. Corruption may occur." which, after a quick Google check led me to believe it was only related to pulling out my USB drive.

I felt compelled to thoroughly check the drive before I put any more serious work onto this laptop only to risk losing it.

My idea was to copy a lot of data and then run a comparison.  First, I ran JDiskReport.  It's a great tool for identifying what's taking up space on your hard drive.  Using this, I located a local directory taking up about 25G.

I copied this directory to c:\testA

Then, though it might have been overkill, I copied it to c:\testB

Then I used another tool I'm liking: FreeFileSync.  This directory sync tool has a setting allowing you to compare file contents instead of just sizes and timestamps.

It took about an hour, but I compared c:\testA to c:\testB.  FreeFileSync reported no file differences.

Then, just to be safe I compared the original source directory to c:\testA.  Again, FreeFileSync reported no file differences.

Since I had done a lot of writing and reading of the hard drive I checked the Event Viewer again and found nothing scary.

From a command prompt (Start->Run->CMD[Enter]), I ran chkdsk c: .  It did do a few more fixes but it also gave me a message to the effect of "This does not indicate disk corruption".  Still, I was a little concerned, so

I ran chkdsk /f c: .  The /F switch tells CHKDSK to fix errors on the disk if found.  It can't run while I'm in Windows so it asks if I want to schedule it for the next boot and I answer Y.  Then I reboot.

It ran successfully, but just to be extra safe I ran chkdsk /r c: .  The /R switch tells CHKDSK to scan the entire disk for bad sectors.  Again, it can't run while I'm in Windows so it asks if I want to schedule it for the next boot and I answer Y.  Then I reboot.

It took a long time to run (maybe a couple hours), but it ran successfully.

Checked the Event Viewer again and this time I am seeing a couple entries from yesterday in the System category which seem to indicate a problem occurred:

Warning: "An error was detected on device \Device\Harddisk0\D during a paging operation."

Error: "A parity error was detected on \Device\Ide\iaStor0."

Still nothing from today, though.  Guess I will keep an eye on it.