« Back to home

Attack of the Heisenbug

This week I battled a bug which was exceptionally sneaky at hiding itself.

Consider the following Domino Java code accessing a single-valued date-only field:

Document doc;
[...fetch document...]
Vector v = doc.getItemValueDateTimeArray("SomeDateField");
DateTime dt = (DateTime) v.get(0);
Date jdt = dt.toJavaDate();
System.out.println(dt.toString() + " = " + jdt.toString());

What happens when you run the code?

Well, the getItemValueDateTimeArray() call fetches the contents of the Notes item (field) from the document, and returns it as a Vector of Notes DateTime objects. For a single value date field, you get a Vector with one element.

The next line extracts the DateTime object from the Vector.

Then, we convert the DateTime object to a java.util.Date object. Here’s where things get tricky. In spite of the name, java.util.Date is actually a date and time class, a timestamp if you will. Worse, it’s a thin wrapper around POSIX epoch time, with all the brokenness that implies. So it’s impossible for a Java Date to represent just a date; it always has a time as well. So what does Domino do?

If you run the code in an agent running in the Notes client, you’ll get something like this:

01/24/2014 = Fri Jan 24 14:45:22 CST 2014

Or at least, that’s what I get if I run the code at about 2:45 in the afternoon in my local time zone. Basically, Domino defaults the time to the current time, and the time zone to the current time zone.

However, if at about the same time I run the same code fragment in a command line Java application that communicates with the server via CORBA and IIOP, I get this:

01/24/2014 = Fri Jan 24 08:45:47 CST 2014

Can you see the horrible bug yet? Ponder it for a moment before reading on.

Your first reaction might be “So what?” I mean, it’s not like the documentation makes any guarantees about what time you’ll end up with in your Java Date object. The date part of the object is still correct, so everything’s fine, right?

Sadly, everything is not fine. To see why, look at the two values closely. Notice that the value obtained in the CORBA environment is 6 hours before the value obtained in the Notes agent environment. CST is Central Standard Time, my time zone, which happens to be 6 hours west of Greenwich.

So it looks as if what Domino is doing — more specifically, what the CORBA implementation of the Domino classes is doing — is ‘adjusting’ the current time that it puts in the object before calculating the Java Date. It seems it’s shifting it to the current time zone, even though it’s already in that time zone. The end result is that instead of the current time, you get a Date object with the time shifted by however many hours your time zone is to the east of UTC.

That’s a big problem, because if you run the code at 4AM local time, you get this:

    01/24/2014 = Thu Jan 23 22:45:47 CST 2014

When Domino subtracts the 6 hours from 4AM, it gets 10PM the previous day.

This problem cropped up in some code I use to pump data between Domino and a data warehouse. The Java Date gets turned into a java.sql.Date, which is written to the destination database via JDBC. The code runs regularly, so when I was alerted to the problem and checked the data, I found lots of records that had dates off by a day.

Yet every time I tested the code, it worked perfectly. Because, of course, I was never at work and testing code before 6AM. If I still lived in Europe, I’d probably have found the problem a lot sooner.