Time matters too

Debugging tip: When debugging code that is in any way time-sensitive, make sure that the time on the computer you're working on is correct.

This particular nugget-o-wisdom would have come in handy for me last week.

You see, I had recently been working on the advertising module for our site, integrating the old stand-alone ad system with our new CMS. I got a but report, so I made some changes to the code. But after I started testing my changes, I realized that orders for new ad campaigns were being accepted, but kept randomly disappearing. It made no sense. I would place a test order and it would go through. When I opened up a MySQL console, I could see the record in the database. But when I went into the administration portion of our CMS, it wasn't there. And when I checked the database directly after that, the record had just disappeared. Gone without a trace.

How could this happen?

The answer is simple: timing. When the administrative interface is loaded, it does some cleanup to the data base. In particular, it cleans out any "stale" orders that have been placed - ads that customers entered, but never paid for. So if an ad is left unpaid for more than a day, it will get deleted.

But the ads I was entering were no more than a couple of minutes old. So why were they getting deleted? The logic in the database-cleaning code was correct. The "stale record" time in the configuration table was correct. So the records shouldn't have been deleted.

The problem was, I forgot about two things:
1) None of the clocks on our test servers (which are VMWare Server virtual machines) are right.
2) The public portion of our site and the management portion run on different servers.

The short version is that I ordering ads on one server and trying to view them in the admin interface running on another server. However, the system clocks of those two servers weren't even remotely close - the content server where I created the orders was a day or so slow and the admin server was several days fast. So as soon as the admin server saw the newly created ads, it immediately thought they were "stale" and deleted them.

That particular "bug" actually came back and bit me again today. I guess I'm going to have to talk to the guys and see if we can set up the test servers to run a periodic ntpdate so that I don't have to worry about that sort of thing again.

You can reply to this entry by leaving a comment below. You can send TrackBack pings to this URL. This entry accepts Pingbacks from other blogs. You can follow comments on this entry by subscribing to the RSS feed.

Add your comments #

A comment body is required. No HTML code allowed. URLs starting with http:// or ftp:// will be automatically converted to hyperlinks.