Scott Hanselman

RTFLF - Read the Expletive Log File

January 29, '09 Comments [21] Posted in ASP.NET | ASP.NET Dynamic Data | ASP.NET MVC | IIS | Learning .NET | Programming | Web Services
Sponsored By

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.

Ninjas can't catch you if you're on fire.

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.

* Pic from Dr. McNinja.

About Scott

Scott Hanselman is a former professor, former Chief Architect in finance, now speaker, consultant, father, diabetic, and Microsoft employee. I am a failed stand-up comic, a cornrower, and a book author.

facebook twitter subscribe
About   Newsletter
Sponsored By
Hosting By
Dedicated Windows Server Hosting by ORCS Web
Thursday, January 29, 2009 7:39:46 PM UTC
Good post but the picture from Dr. McNinja makes it great!
Lou Hendricks
Thursday, January 29, 2009 7:45:24 PM UTC
Ah, but what was the solution? Was it to request /myservice.svc/ or was it something else?
dave-ilsw
Thursday, January 29, 2009 8:23:40 PM UTC
This is what makes a truly great admin. They read the logfiles and figure it out from there. Users describe their problems all sorts of ways, log files are consistent. important reminder. I had a similar moment right after new years.
Thursday, January 29, 2009 8:30:41 PM UTC
Scott

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.
Thursday, January 29, 2009 8:32:36 PM UTC
I like that: "The real experts have mastered the basics."

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.
Thursday, January 29, 2009 11:12:58 PM UTC
I've noticed a fascinating side-issue that arises from these "erroneous" bug fixing forays: many, many small code changes that may or may not have made the code better. I'll get so caught up trying to fix the bug, that I forget to sit back and look at the larger picture, which would point out things like "look at the log file."

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...
Thursday, January 29, 2009 11:14:06 PM UTC
I wonder if this is a differnt mindset at play here - a QA person more than likely would have started troubleshooting by looking specifically for the log files. Does a Developer mindset ignore that or take that for granted?
Rohit
Thursday, January 29, 2009 11:17:59 PM UTC
Rohit - I think you nailed it. A QA person is more likely to consider the problem/program holistically, while the programmer is thinking about code and such. The programmer is likely too close to the thing to effectively debug this. In fact, in my case, it was a QA person who solved the problem!
Thursday, January 29, 2009 11:19:20 PM UTC
Alternative solution: Upgrade to IIS7. Then you can get rid of the .mvc extensions :)

Thursday, January 29, 2009 11:24:29 PM UTC
ColinM - I love IIS7 also, but there's no .mvc stuff going on here...I'm talking about ADO.NET Data Services, which have a .svc extension regardless (unless you rewrite them away).
Friday, January 30, 2009 12:05:16 AM UTC
Interesting - I've only done small, internal-to-the-company-I-work-for web apps with Apache, mod_wsgi, Python + some Python libraries (CherryPy, Genshi + other bits'n'bobs) and to be honest, the logfiles are the first place I'd be looking.

But maybe that's because that's pretty much the only option (that I'm aware of) that I've got :-)
Stuart Dootson
Friday, January 30, 2009 1:46:31 AM UTC
My fellow coworker today was doing the same thing today. He pushed out some code to production and for whatever reason it wasnt working, checked the services, the web application, it should have worked. It wasnt until about an hour of beating his head in he realized the code was never put out to begin with correctly.
Mark Coleman
Friday, January 30, 2009 1:47:45 AM UTC
Please note that RTFLF is (IMHO) better translated as "Read The Fascinating Log File".

(Just a little feedback for anyone who's asking "WTF?" or "What's That For?").
Dan Gilleland
Friday, January 30, 2009 1:57:45 AM UTC
So true and easy to overlook.

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)"
Friday, January 30, 2009 3:04:10 AM UTC
Hey Scott –
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?
Saturday, January 31, 2009 12:19:03 AM UTC
Tough one, Scott. However I really appreciate that you are not ashamed of these minor mistakes and even make them public on your blog. A person with a big ego would certainly destroy any proof regarding such an issue.

@Dan Gilleland : I had a great laugh for your excellent reinterpretation of the acronyms :)) They are just awesome.
Sunday, February 01, 2009 2:26:22 PM UTC
Great reminder. I've made the same mistake more than once. :)
Monday, February 02, 2009 2:48:13 AM UTC
Well, in such case, it is always recommended to start from IIS log.

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 :)
Monday, February 02, 2009 7:46:27 AM UTC
"Ok, people, what's the definition of insanity? Trying the same thing and expecting a different result."

So does it follow that impure languages (i.e. with sideeffects) are languages of the insane?
Einar W. Høst
Monday, February 02, 2009 8:51:06 PM UTC
Ahhh Scott, I do that sort of thing occasionally and I relate to your feeling of impending "egg on face". I hate that moment of realization that someone is about to do the simplest thing that can work and make me look like a beginner. It's synonymous with the "did you plug it in?" question I know I have to ask my grandma on the phone when her "printer is broken again". As developers we look so hard for the tough solutions that we forget the really, really easy ones.

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
Thursday, February 05, 2009 11:24:46 PM UTC
Hehe, glad to know I'm not the only one!

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.

Disclaimer: The opinions expressed herein are my own personal opinions and do not represent my employer's view in any way.