Sunday, March 17, 2013

How Logging Rule of Thumb saved my butt twice in a day


tl;dr:

I have a simple Rule of Thumb for implementing logging in my apps:
  • If your application crashes - log the exception + anything relevant to the crash.
  • If you suppress (handle) an exception - log it. 
And it saved me recently when a demo version crashed on remote manager's PC 2 hours before the demo.


Rule of Thumb

[1]
A rule of thumb is a principle with broad application that is not intended to be strictly accurate or reliable for every situation. It is an easily learned and easily applied procedure for approximately calculating or recalling some value, or for making some determination. 
(Wikipedia) 

I love Rules of Thumb: these small pieces of well-established and time-tested knowledge are easy to apply and share but yet provide a powerful way to let your brain focus on the key novel tasks rather than re-invent the wheel every time you need it. In other words it is a generalization of the Industry experience in some particular (often very narrow) task. Of course, such a rule is not necessarily 100% correct in each particular situation - often you need much deeper analysis to make a decision.  Once you keep this in mind, Rules of Thumb can be very helpful in your day-to-day development tasks.

Examples

I have some examples of the handy rules I use every day:

Decompose Conditional refactoring 

This is one of the easiest to apply refactoring recipes from Martin Fowler's Catalog of Common Refactorings. Basically, it says, that such a piece of code:
if (notSummer(date))
    charge = winterCharge(quantity);
else 
    charge = summerCharge (quantity);
is usually easier to read and maintain than its shorter counterpart:
if (date.before (SUMMER_START) || date.after(SUMMER_END))
    charge = quantity * _winterRate + _winterServiceCharge;
else 
    charge = quantity * _summerRate;
this refactoring exists for a good reason: whenever somebody tries to to debug or just understand this passage of code he will most likely need to know that different calculations are triggered by the fact, that date variable's value "is not summer" rather than the implementation details of this condition. It saves you several seconds every time you do so.

"Same-Line Comments are Evil" rule

This one is my rephrasing of Steve McConnell's "Code Complete" chapter on code comments. It says, that same-line comments like that:
int i = GetCurrentUserId(); // Get user's Id from Session. (This throws an exception if not logged in)
bool isAdminOrMod = GetIsAdminOrMode(i); // check if user is marked as Admin or Moderator in the db
bool shouldShowNotification = !isAdminOrMod; // notifications should be shown to simple users only.
should be avoided as:
  • they are hard to read (you always need to scroll horizontally which is painful)
  • they are hard to maintain (every change in every line triggers a change in the corresponding comment) - and therefore will most likely be out-of-sync with code as it evolves.
I use these 2 rules literally everyday - and I stopped spending time and energy on deciding if I should extract a method from the condition / if I should use same-line or code-block comments - my fingers follow these simple rules almost automatically! 

In fact I think I read books like "Code Complete" and 'Refactoring" to extract such rules and decide if I should use them. I don't have time to figure out everything myself - I think industry experience is something I should utilize if possible. (this is my main argument in disagreeing with some of my friends and colleagues considering books like that useless as "you should figure out yourself if you a professional").

What happened

Let's get back to the reason which caused this post to happen. I have an easy rule of thumb for logging (I think I got it from my very first colleague and mentor at Itransition);
  • if your application crashes - log the exception + anything relevant to the crash.
  • If you suppress (handle) an exception - log it. 
Sounds very simple and fairly logical, doesn't it? 

Save #1

For WPF app the first point means, that you have to handle AppDomain.UnhandledException Event (well, have a look at this answer on SO for more options) and log the exception using you favourite logger. 

That day we were having a demo for the Client. I think it was about 2-3 hours left when it turned out, that "nothing works" on the manager's PC which is supposed to be used for the demo (The app shows up but any button on the Home Screen results in a crash). It was strange and a little bit frightening as all worked fine on devepolers' PCs across the team. I work remotely from Dresden for a company in Minsk, so trying to debug it on the target PC was not an option and I requested the log file, hoping that it helps - and it did! Here's what I've seen:
System.InvalidOperationException: A TwoWay or OneWayToSource binding cannot work on the read-only property 'Progress' of type 'ProjectName.Dialogs.ProgressDialogViewModel'
OK, fair enough - why would I need a two-way binding on a read-only property in the first place? Not much time to reflect - I changed the failing binding to be One-Way and sent a build to be checked on the PC in question: it worked and it was pretty much a relief. (However, I still wonder why it works fine on dev PCs - maybe, we have different .NET versions/updates installed).

Save #2

The second part of this rule is even easier to implement: every catch block should log the exception first. It payed off the same day: after we've deployed the fixed build to the demo PC it turned out that the crashes are gone, but the App refuses to open any video file. It usually happens when PC does not have relevant codecs installed, however It seemed, the PC had the codecs in place (as WMP opened the videos normally). Back to log file - and it says the app can't resolve a specific codec, so I insisted that we install K-Lite codec pack - and it helped: our demo was saved about an hour before the deadline.

So my very basic and simple rule of thumb for deciding what should be logged has saved me twice in a single day - pretty cool for a 2-lines rule, isn't it?


Do you have a standard approach to what you log and when? What are your favourite rules of thumb?

----
 [1] - Picture cred. http://www.clinicalarchitecture.com/blog/clinical-architecture-healthcare-it-blog/march-2009/rule-of-thumb-%E2%80%93-drug-allergy-alerts/

4 comments:

  1. "ProjectName" is a bad name for root namespace, seriously. Sounds like a property, not like a namespace, you know.

    ReplyDelete
    Replies
    1. haha, good point: I stripped real namespace to prevent information leakage :) (outsource, you know))

      Delete
  2. Tiny amendment:

    > The second part of this rule is even easier to implement: every catch block should log the exception first.

    Only if this block does not re-throw this exception, to avoid duplicate logs for a single exception caught twice on different "stages" of call stack.

    ReplyDelete
    Replies
    1. That's totally right - sorry, I wasn't clear enough, when describing the rule (I just seldom use catch block which re-throw exceptions). I will post an update tomorrow.

      Thanks!

      Delete