Scott Hanselman's Computer Zen - RTFLF - Read the Expletive Log File

« BizSpark - Free Software and Production ... | Main | HD vs. SD - Flip MinoHD vs Flip Ultra - ... »

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.

* Pic from Dr. McNinja.

Thursday, January 29, 2009 11:39:46 AM (Pacific Standard Time, UTC-08:00)

Good post but the picture from Dr. McNinja makes it great!

Lou Hendricks

Thursday, January 29, 2009 11:45:24 AM (Pacific Standard Time, UTC-08:00)

Ah, but what was the solution? Was it to request /myservice.svc/ or was it something else?

dave-ilsw

Thursday, January 29, 2009 12:23:40 PM (Pacific Standard Time, UTC-08:00)

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.

John Miller

Thursday, January 29, 2009 12:30:41 PM (Pacific Standard Time, UTC-08:00)

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.

mknopf

Thursday, January 29, 2009 12:32:36 PM (Pacific Standard Time, UTC-08:00)

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.

Scott Hanselman

Thursday, January 29, 2009 3:12:58 PM (Pacific Standard Time, UTC-08:00)

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...

ZagNut

Thursday, January 29, 2009 3:14:06 PM (Pacific Standard Time, UTC-08:00)

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 3:17:59 PM (Pacific Standard Time, UTC-08:00)

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!

Scott Hanselman

Thursday, January 29, 2009 3:19:20 PM (Pacific Standard Time, UTC-08:00)

Alternative solution: Upgrade to IIS7. Then you can get rid of the .mvc extensions :)

ColinM

Thursday, January 29, 2009 3:24:29 PM (Pacific Standard Time, UTC-08:00)

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).

Scott Hanselman

Thursday, January 29, 2009 4:05:16 PM (Pacific Standard Time, UTC-08:00)

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

Thursday, January 29, 2009 5:46:31 PM (Pacific Standard Time, UTC-08:00)

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

Thursday, January 29, 2009 5:47:45 PM (Pacific Standard Time, UTC-08:00)

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

Thursday, January 29, 2009 5:57:45 PM (Pacific Standard Time, UTC-08:00)

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)"

Kristofer

Thursday, January 29, 2009 7:04:10 PM (Pacific Standard Time, UTC-08:00)

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?

Andrew Conrad

Friday, January 30, 2009 4:19:03 PM (Pacific Standard Time, UTC-08:00)

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.

Andrei Rinea

Sunday, February 01, 2009 6:26:22 AM (Pacific Standard Time, UTC-08:00)

Great reminder. I've made the same mistake more than once. :)

Clifton Griffin

Sunday, February 01, 2009 6:48:13 PM (Pacific Standard Time, UTC-08:00)

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 :)

Lex Li

Sunday, February 01, 2009 11:46:27 PM (Pacific Standard Time, UTC-08:00)

"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 12:51:06 PM (Pacific Standard Time, UTC-08:00)

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

Stu

Thursday, February 05, 2009 3:24:46 PM (Pacific Standard Time, UTC-08:00)

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.