Archive for Exceptions

In my last post we set up a minimalist application, attached Gibraltar to it, and reported some trace information. In this post we’re going to build on that and add exceptions. First we are going to add an unhandled exception, so we change our code so that it looks like this:

using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;

namespace GibraltarGettingStartedApp
{

	class Program
	{
		static int Main(string[] args)
			{
				Trace.WriteLine("About to Blow up...");
				int zero = 0;
				Trace.Close();
				return 1 / zero;
			}
		}
	}
}

That should get the runtime’s panties in a bunch, let’s try it. Smile

SNAGHTML22a2b5ec

Yep, that did it! Now, let’s see what Gibraltar logged…

image

Gibraltar knows we crashed and if we open up the record…

image

We know what the problem was, we can click the link and go right to the line in the source code and Gibraltar tells us what the user experience is going to be, “This fatal error will not be reported to the user, then the application will exit”. All and all, pretty cool.

As an aside, let me close down VS, I want to test if I click the link, will it open the file and go to the line? It does! That’s cool, though I notice that it only opens the actual file and not the solution or project that the file is in. Hmm, I’ll need to investigate that more as it’d be better if the entire solution was opened, don’t you think?

Let’s try running the same unhandled exception in a winforms application and see what happens. We’ll need to run the exe from the commandline, as the VS debugger will “get in the way” and try to do “clever stuff”, but when we do, we see the following dialog:

SNAGHTML298b97c

Here Gibraltar is giving us even more help. It’s popped up a dialog which will actually help us recover from the crash and carry on using our application. If we select “Restart Application” Gibraltar will restart the application for us and enable us to carry on using our application. Of course, this facility should only be used in a testing environment. In the real world, I don’t think it would be wise to restart and to continue using an application which had just suffered from a crash, as there is no way to know what state the underlying model is in. However, from a testing perspective, it’s an excellent tool.

Of course, the same information is recorded in Gibraltar:

image

Notice that the “Status” has been recorded as “Normal”. If we open the record we can see why:

image

It’s because we chose to continue the execution and shut down the application normally after.

Okay, let’s change our console application code to handle the exception…

using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;

namespace GibraltarGettingStartedApp
{
	class Program
	{
		static int Main(string[] args)
		{
			Trace.WriteLine("About to Blow up...");
			int zero = 0;
			Trace.Close();
			try { return 1 / zero; }
			catch (DivideByZeroException e) { }
			return 0;
		}
	}
}

And let’s see what difference that made to Gibraltar…

image

Hmm, as far as Gibraltar is concerned everything is normal, there is no sign of the handled exception. For a clue as to why that is, let’s examine logging best practices, you can read them at…

http://www.gibraltarsoftware.com/Support/Documentation/Logging_BestPractices.html

And they quite clearly state:

“We strongly recommend that in all cases where an exception is consumed within a catch block that you log the exception with an Informational severity rather than silently swallowing the error.”

Okay, so this states that if we handle an exception, and we want that fact recorded by Gibraltar, then we have to log it. That makes sense really. So, let’s change our code to the following:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;

namespace GibraltarGettingStartedApp
{
	class Program
	{
		static int Main(string[] args)
		{
			Trace.WriteLine("About to Blow up...");
			int zero = 0;
			try { return 1 / zero; }
			catch (DivideByZeroException e)
			{
				Trace.WriteLine("Error: " + e.Message);
			}
			Trace.Close();
			return 0;
		}
	}
}

Now let’s see how that’s affected Gibraltar:

image

This time you can plainly see that the error has been recorded, which is good, but notice too that there’s no exception tab:

image

Of course, we should be able to do better and we can. If we use the TraceInformation method, and pass a formatted string, along with the exception, then Gibraltar will give us a much richer experience.

So, let’s change our code to use that method:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Diagnostics;

namespace GibraltarGettingStartedApp
{
	class Program
	{
		static int Main(string[] args)
		{
			Trace.WriteLine("About to Blow up...");
			int zero = 0;
			try { return 1 / zero; }
			catch (DivideByZeroException e)
			{
				Trace.TraceInformation("Error: {0}",e.Message,e);
			}
			Trace.Close();
			return 0;
		}
	}
}

And let’s look at the information provided in Gibraltar:

image

This time, as you can see, we get the “Exceptions” tab. This is because Gibraltar scans the insertion variables and, if it finds one that is an exception, then it uses that as the exception for the log message (regardless of its severity). Pretty cool eh?

In this post we added an unhandled exception to your console application to see what effect that had on Gibraltar. We then added an unhandled exception to a winforms application so we could see the enhanced features available to us there and then we finished up by handling that exception and seeing why best practice is to log handled exceptions.

I hope you’ll join me next time as we continue our exploration of Gibraltar, until then, happy coding! Smile

kick it on DotNetKicks.com

When we’re talking with prospective Gibraltar users, we often hear something that goes a bit like this:

Wow, that sounds like it’d be really useful, but we don’t have time to integrate something like that: we’re having all kinds of problems trying to get our latest project working at the client site.

Lifeguard StationIt’s one of the more painful experiences when advocating a solution:  They’re experiencing exactly the pain that Gibraltar is designed to help with, and with just a small amount of attention it could quickly help get them out of the hole they’re in.  The problem is, when someone’s in the middle of a critical issue, getting them to try out a new tool is a bit like trying to teach swimming lessons to someone that’s drowning.

When you’re going under, you don’t want to hear about how to kick effectively with your feet, correctly time your breathing, and coordinate your arms and legs.  You just want to be out of the water right now.  

Take a few swimming lessons

If you want to be prepared in an unexpected emergency, it’s easiest if you put in a little practice ahead of time when the pressure’s off.  With a few swimming lessons you’d be able to extricate yourself from the water with a lot less drama.  You don’t need to become a world class athlete, just moderately proficient.

Similarly, when it comes to being prepared to support your application once it leaves the developer’s desks doing something, anything, is better than nothing.  One of my favorite approaches is to push the development team to not use anything the client wouldn’t have when troubleshooting problems that show up during formal testing.  If you have to pull out Visual Studio on the test server to figure out why the web site is returning the wrong page, what would you do if this was on the client’s computer?  Ask them to install Visual Studio in production?

What you may need to do instead is insert more logging in the area around the problem to see if you can figure out what’s going wrong.  Once the additional logging has illuminated the issue (which may take a few iterations, often with it first showing what it isn’t more than what it is) don’t remove the logging, leave it in.  You may want to tune it slightly (get rid of some excessive verbose stages or reduce the severity of a few things) but now you have some battle tested logging in place for at least part of your code.

Often, problems that can show up in one place can also show up in another, so what other parts of your software have similar vulnerabilities?  How about dropping in a few log statements in those areas too?

Prepare for the Expected

One easy-to-introduce practice that can be surprisingly beneficial in the field is to log handled exceptions.  These are the errors that you’re expecting:  Perhaps you’re using an API that doesn’t let you check the validity of an operation before you try, so you try it, then if it fails you go a different way.  It might be that you try to open the file and if you get an exception then you assume it’s not there and create a new one.  

I’ve been on many projects where unexpected problems cropped up in exactly these places.  You’re expecting an exception at the location so it isn’t surprising to find one, and most people don’t bother verifying that the exception they caught is exactly the one they were expecting.  One practice we like to use is to put a low severity (verbose or informational) log statement in the catch that indicates it was an expected exception, and what we’re taking it to mean.   That way, if you’re reading the log and see a message that you were expecting an exception meaning the file wasn’t found, but you see that the actual exception was Access Denied you know you’re on to something.

Here’s an actual example from the Gibraltar Analyst codebase:

try
{
m_Parameter.Value = m_Parameter.ConvertValue(txtParameterValue.Text);
}
catch(Exception ex)
{
//even though we expect exceptions,log it in case it isn't why we expect.
Log.TraceInformation(ex, "User provided invalid parameter value/r/n" +
"Unable to convert to native type.  The new value will be ignored.");
}

That said, you should strive to eliminate all expected exceptions you can.  Not only are they problematic from a reliability standpoint, exceptions are very slow compared to other routine operations in code.  Finally, if your code is throwing exceptions even in normal use then it isn’t feasible to debug with Visual Studio set to break on thrown managed exceptions.  That’s a pity because this is a great debugging aide for cleanly setup code because it halts the debugger as the exception is being thrown before it has changed the location to where it will be caught, even allowing you to unroll the exception and back up.

kick it on DotNetKicks.com

Categories : Development, Logging
Comments (0)