Wednesday, March 26, 2008

HTTP requests from the future


These days I'm working on a DotNetNuke (DNN) based Portal development. Our development env is IIS 5.1/XP while our deployment env is IIS 6/Win 2003. During our past 2 deployments we encountered a strange error on IIS 6/Win2003. Soon after the deployment every page in our portal solution spits a java script error 'Sys is undefined'. This is an error related to the ScriptManager.js which is needed in Ajax pages. There were dozens of google search results for this error pointing fingers to IIS, web.config file settings, axd file handlings, Ajax java scripts etc...but we just couldn't figure out the solution quickly enough. After a late night struggle we gave up and decided to check it the day after. When we came and check next day, the problem has got fixed by itself overnight :).

I always know when problems starts to get fixed by themselves it's a warning sign for worst things ahead. But I just could not reproduce the problem to study it that day. So we went happily in to our final deployment yesterday and here we again had the good old error 'Sys is undefined'. This time around we dig down and went in to analyzing this in depth. When we looked at the HTTP response for a page 2 requests for a ScriptResource.axd files were having HTTP 500 codes. (Read about .axd files here ). When I used fiddler to analyze the HTTP response in detail we caught up with the message
"System.ArgumentOutOfRangeException: Specified argument was out of the range of valid values.Parameter name: utcDate". Eureka!!!

Now we knew that the problem has to be something to do with the time. In every ScriptResource.axd request there are 2 parameters being sent. Eg : ScriptResource.axd?
d=8fBiB6-cb_63xIkOjfdl6BCL-uzAt8lEaJgT8GHfNac0VUzhoOSl_j9ebDYDA0Ao0
&t=633420390180000000
The 'd' param is relevant to data it is asking for and the other 't' reflects the time which the resource was built. (Use this tool to decrypt axd requests). The problem was that our win 2k3 servers time was not accurate and it actually resided in the past ( A few hours). Thus the axd request was seen by the server as requests coming from something which was built in the future.
After the problem was identified the root cause finding was not difficult. Our win2k3 time synchronizing service had a problem. Now we were able to think back and understand why this problem got fixed on it's own the last time :). The problem just slept over it till the server time difference was consumed. Isn't that a nice way to solve problems....just sleep over it :)
Post a Comment