RTFLF - Read the Expletive Log File
A buddy of mine and I had a nice slap in the face yesterday. I was helping him deploy an ADO.NET Data Service to a large company's staging server and we were seeing REALLY odd behavior.
We'd request something like /myservice.svc and get a 404. But we could request /myservice.svc/Stuff or /myservice.svc/?metadata.
We settled in to debug this. We thought we were "getting down to basics." You know, you've done this. The conversation goes something like:
"Ok, people, what's the definition of insanity? Trying the same thing and expecting a different result."
"Right...let's challenge all our assumptions. Let's start from scratch. Can get Hello World working?"
"What's the ACLs on that file? Is the .svc extension registered? Are we sure we have the right version of .NET?"
We were both tired and we wasted a couple of hours basically dicking around, hitting Refresh and hoping for another solution. I wanted to plugin procexp and filemon and get down to some serious CSI: IIS-type debugging, but here's the rub: We didn't have access to the machine. Only "large company's" guys were allow to touch anything. We could make suggestions, watch a SharedView session, but the human latency of the whole process was slowing us by a factor of at least five.
But I can't blame it all on the process. In retrospect, it was my fault. I'm a good debugger. I know this and I'm happy to say it. However, I can recognize a ninja when I see one. Well, if you can see the ninja, maybe they aren't a ninja, but still. I reached out to a real debugging ninja. What did he do that I was missing?
I ignored a basic tenet of debugging. It wasn't that I didn't RTFM. I didn't RTFLF.
My debugger-ninja-friend started out by simply asking us to Start|Run and type "LogFiles."
At this point I realized that this process was going to make me look and feel like an idiot. My internal lights went on and I realized my buddy and I hadn't bothered to check any log files. We'd been treating IIS like it was a black box. It's not. It logs the hell out of everything that goes in and out if you want it to.
We were trying to debug a 404 on this .svc. We opened the log in Notepad, went to the bottom, searched up for ".svc" and there it was:
This Page was blocked by Microsofts URL Scan 3.0 Reason=Dot-in-path-detected
You could have knocked me over with a feather. I've said myself, UrlScan is step 0. If you're debugging a weird 404, UrlScan is the first and most obvious place to look and it was all there, in the log files. You remember, the log files I never looked at. ;)
Did my ninja friend know or care? No, because he RTFLF. A painful reminder to me as I wasted a bit of a ninja's time. Everyone knows, don't piss off a ninja. He was cool about it though.
Today's Lesson: Whatever it was, it was probably logged. Try there first.
About Scott
Scott Hanselman is a former professor, former Chief Architect in finance, now speaker, consultant, father, diabetic, and Microsoft employee. He is a failed stand-up comic, a cornrower, and a book author.
About Newsletter
Lou Hendricks
Its so easy to forget the basics, I do it all the time. Recently I read an article about how to become a true expert in your skill set, the main point in the entire article was that real experts are those who have mastered the basics of what they do, and continue to improve on those basics throughout their entire career.
Thanks for reminding us to read the Log Files first, i'll make sure to keep that basic skill as sharp as a knife.
Dave - The problem was the "AllowDotInPath=0" setting in UrlScan. that needs to be off for IIS6 and up and for ADO.NET Data Services.
It's like when you're driving along and get lost in a daydream, then suddenly realize you weren't paying attention to where you were driving to. Where would you have driven to? Or in this case, how much code did I "fix" before recalling / discovering the real problem involved? Maybe these aren't related...
But maybe that's because that's pretty much the only option (that I'm aware of) that I've got :-)
(Just a little feedback for anyone who's asking "WTF?" or "What's That For?").
Another scenario where the RTFLF is important is when Visual Studio crashes; VS goes and dies with no error message or feedback. Look in the windows event log and there's will always be an entry explaining why it crashed, e.g. ".NET Runtime version 2.0.50727.1434 - Fatal Execution Engine Error (79FEC5F0) (80131506)"
Who exactly was the Ninja that helped you out? Or did they request for their identity to remain secret in order to protect their relatives and friends?
@Dan Gilleland : I had a great laugh for your excellent reinterpretation of the acronyms :)) They are just awesome.
318380 Description of Microsoft Internet Information Services (IIS) 5.0 and 6.0 status codes
http://support.microsoft.com/default.aspx?scid=kb;EN-US;318380
943891 The HTTP status codes in IIS 7.0
http://support.microsoft.com/default.aspx?scid=kb;EN-US;943891
Scott, next time you may consider involve our support team :)
So does it follow that impure languages (i.e. with sideeffects) are languages of the insane?
My favorite story along those line was spending days with a vicious COM+ transaction failure problem. The calls to our services would work perfectly for days and then fail at exactly the same time late on a Friday night for no clear reason. We attached debuggers, wrote automated unit tests, inspected code, even got an SOS profile running to see if it was a long running memory leak or the likes. Turns out that an errant cable blocked the path of a janitor who, consistently at the start of his shift on a Friday night, would unplug said cable, get behind the server in question and then plug it back in 15 minutes later when he was done. Not an RTFLF scenario exactly but we'd really missed the most basic explanation for a consistently timed outage each week.
Cheers!
-- Stu
I came over here due to a comment one of my readers left on this post and found some comfort in your frustrations. Thanks for sharing.
Comments are closed.