Mustali Kachwala's Blog: Back to Basics: Daylight Savings Time bugs strike again with SetLastModified

Back to Basics: Daylight Savings Time bugs strike again with SetLastModified:

No matter how well you know a topic, or a codebase, it's never to late (or early) to get nailed by a latest bug a over a half-decade old.

DasBlog, the ASP.NET 2 blog engine that powers this blog, is done. It's not dead, but it's done. It's very stable. We had some commits last year, and I committed a bug fix in February, but it's really well understood and very baked. My blog hasn't been down for traffic spike reasons in literally years as DasBlog scales nicely on a single machine.

It was 10:51pm PDT (that's Pacific Daylight Time) and I was writing a blog post about the clocks in my house, given that PST (that's Pacific Standard Time) was switching over soon. I wrote it up in Windows Live Writer, posted it to my blog, then hit Hanselman.com to check it out.

Bam. 404.

What? 404? Nonsense. Refresh.

404.

*heart in chest* Have I been hacked? What's going on? OK, to the logs!

l2    time    2011-11-06T05:36:31    code    1    message    Error:System.ArgumentOutOfRangeException: Specified argument was out of the range of valid values.
Parameter name: utcDate
   at System.Web.HttpCacnhePolicy.UtcSetLastModified(DateTime utcDate)
   at System.Web.HttpCachePolicy.SetLastModified(DateTime date)
   at newtelligence.DasBlog.Web.Core.SiteUtilities.GetStatusNotModified(DateTime latest) in C:\dev\DasBlog\source\newtelligence.DasBlog.Web.Core\SiteUtilities.cs:line 1253
   at newtelligence.DasBlog.Web.Core.SharedBasePage.NotModified(EntryCollection entryCollection) in C:\dev\DasBlog\source\newtelligence.DasBlog.Web.Core\SharedBasePage.cs:line 1182
   at newtelligence.DasBlog.Web.Core.SharedBasePage.Page_Load(Object sender, EventArgs e) in C:\dev\DasBlog\source\newtelligence.DasBlog.Web.Core\SharedBasePage.cs:line 1213
   at System.EventHandler.Invoke(Object sender, EventArgs e)
   at System.Web.UI.Control.OnLoad(EventArgs e)
   at System.Web.UI.Control.LoadRecursive()
   at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) while processing http://www.hanselman.com/blog/default.aspx.

What's going on? Out of range? What's out of range. Ok, my site is down for the first time in years. I must have messed it up with my clock post. I'll delete that. OK, delete. Whew.

Refresh.

404.

WHAT?!?

Logs, same error, now the file is a meg and growing, as this messages is happening of hundreds of times a minute. OK, to the code!

UtcSetLastModified is used for setting cache-specific HTTP headers and for controlling the ASP.NET page output cache. It lets me tell HTTP that something hasn't been modified since a certain time. I've got a utility that figures out which post was the last modified or most recently had comments modified, then I tell the home page, then the browser, so everyone can decide if there is fresh content or not.

public DateTime GetLatestModifedEntryDateTime(IBlogDataService dataService, EntryCollection entries)
{
   //figure out if send a 304 Not Modified or not...
   return latest //the lastTime anything interesting happened.
}

In the BasePage we ask ourselves, can we avoid work and give a 304?

//Can we get away with an "if-not-modified" header?
if (SiteUtilities.GetStatusNotModified(SiteUtilities.GetLatestModifedEntryDateTime(dataService, entryCollection)))
{
  //snip
}

However, note that I'm have to call SetLastModified though. Seems that UtcSetLastModified is private. (Why?) When I call SetLastModified it does this:

public void SetLastModified(DateTime date)
{
    DateTime utcDate = DateTimeUtil.ConvertToUniversalTime(date);
    this.UtcSetLastModified(utcDate);
}

Um, OK. Lame. So that means I have to work in local time. I retrieve dates and convert them ToLocalTime().

At this point, you might say, Oh, I get it, he's called ToLocalTime() too many times and double converted his times. That's what I thought. However, after .NET 2 that is possible.

The value returned by the conversion is a DateTime whose Kind property always returns Local. Consequently, a valid result is returned even if ToLocalTime is applied repeatedly to the same DateTime.

But. We originally wrote DasBlog in .NET 1.1 first and MOVED it to .NET 2 some years later. I suspect that I'm actually counting on some incorrect behavior deep in own our (Clemens Vasters and mine) TimeZone and Data Access code that worked with that latent incorrect behavior (overconverting DateTimes to local time) and now that's not happening. And hasn't been happening for four years.

Hopefully you can see where this is going.

It seems a comment came in around 5:36am GMT or 10:36pm PDT which is 1:36am EST. That become the new Last Modified Date. At some point we an hour was added in conversion as PDT wasn't PST yet but EDT was EST.

Your brain exploded yet? Hate Daylight Saving Time? Ya, me too.

Anyway, that DateTime became 2:36am EST rather than 1:36am. Problem is, 2:36am EST is/was the future as 6:46 GMT hadn't happened yet.

A sloppy 5 year old bug that has been happening for an hour each year that was likely always there but counted on 10 year old framework code that was fixed 7 years ago. Got Unit Tests for DST? I don't.

My server is in the future, but actually not as far in the future as it usually is. My server in on the East Coast and it was 1:51am. However, the reasons my posts sometimes look like they are from the future, is I store everything in the neutral UTC/GMT zone, so it was 5:51am the next day on my file system.

Moral of the story?

I need to confirm that my server is on GMT time and that none of my storage code is affected my Daylight Saving Time.

Phrased differently, don't use DateTime.Now for ANY date calculations or to store anything. Use DateTime.UTCNow and be aware that some methods will freak out if you send them future dates, as they should. Avoid doing ANYTHING in local time until that last second when you show the DateTime to the user.

In my case, in the nine minutes it took to debug this, it resolved itself. The future became the present and the future last modified DateTime became valid. Is there a bug? There sure it, at least, there is for an hour, once a year. Now the real question is, do I fix it and possibly break something that works the other 8759 hours in a year. Hm, that IS still four 9's of uptime. (Ya, I know I need to fix it.)