Logging should not be an afterthought
With products going out to remote User Acceptance Testing this week, I’ve been reminded of one of my pet topics – making sure there’s enough logging in the application.
In this article I give a taster of why logging’s a good idea, a good logging tool for .NET programmers, and some real-life “I wish I’d logged…” stories which illustrate just why I like logging.
Setting the scene
Consider the following scenarios.
You’ve delivered the application to the customer – be it a prototype release or final release – and you sit back to think ‘job done’. But then you get a call from the customer…
Customer call – No logging
Customer: “I’ve been using the application, and it’s come up with an error.”
You: “What was the error?”
Customer: “Erm, ‘An error has occurred’ or something.”
You: “Can’t you be more specific?”
Customer: “No – I just clicked ‘Ok’ and it went away, but now nothing’s working.”
You: “Oh, erm…”
Customer call – With logging
Customer: “I’ve been using the application, and it’s come up with an error.”
You: “OK -can you please email me the application log, which can be found at c:\ApplicationName\logs\logfile.txt?”
Customer: “Ok.”
[Half an hour later]
You: “OK – I’ve looked at the log file and all you need to do is [action] and this will the fix the problem.”
I’m sure we all know which one we’d prefer.
How to log
As we mainly develop in .NET at Microsec, we use log4net – this is a port of the original log4j logging library. These are very mature – the first log4net port was made in 2001.
This article is not intended to be a tutorial on how to use log4net – there are plenty available. However, it’s worth looking at the core concepts – loggers and appenders.
Loggers and levels
At the core of log4net is the concept of the level at which a logger issues its messages. The levels are more or less self-describing:
- DEBUG – information to help debugging the application
- INFO – informative messages
- WARN – warnings
- ERROR – errors
- FATAL – fatal errors
Loggers are – pretty obviously – used in code, to hard-code logging messages at the appropriate points.
Appenders
The beauty of log4net is that appenders can be configured at runtime to append the log messages to one or more destinations. There are 40 appenders available, but the most useful are:
- File appender – logs to a text file
- Rolling file appender – logs to a text file, rolling over to a new file depending on date or file size
- Telnet appender – logs to telnet (really useful for real-time monitoring)
- Database appender – great for analysis/search of historic log events
- Event Log appender – logs to the Windows event log
Finally – and crucially – log4net’s behaviour (the appenders and level of logging being run) can be configured at runtime without needing an application restart.
What to log
When coding an application, I use the logging levels as follows:
- DEBUG – Should be put in place at all significant processes/events/decisions in the code to aid problem solving. However, keeping DEBUG logging in a live application can cause excessive logging and end up filling up disks and/or affecting performance.
- INFO – Significant events, the frequency and meaning of which are useful to keep in place in the live application.
- WARN – Like INFO, events we’d like to know about – but are more important than INFO.
- ERROR – All errors which we need to know about. Definitely unhandled exceptions, but also handled exceptions. The live system should always log these.
- FATAL – Well, this is like ERROR but – erm – fatal! I think we need to know about this, so always log it!
Tuning the logging level
The level at which we log depends on where the application’s is in its lifecycle. Remember, with log4net we can tune the logging level at runtime. In general, I adopt the following strategy:
- Development – DEBUG, INFO, WARN, ERROR, FATAL
- User Acceptance Testing – DEBUG, INFO, WARN, ERROR, FATAL
- Initial live deployment – DEBUG (if performance/disk space allows), INFO, WARN, ERROR, FATAL
- Normal live running – INFO (as long as INFO hasn’t been logged too much), WARN, ERROR, FATAL
- Live running, but errors reported – turn on DEBUG or INFO if they’ve been turned off
I wish I’d logged…
So, in the real world, here are some scenarios we’ve had where logging has really helped (or, if I’m honest in some cases, would have helped).
1. Customer calls with: “There was an error”
ERROR logging for all handled/unhandled exceptions should be catching these, but there’s deadly silence from customer after delivery of a web/service based application.
Is the customer actually using it? INFO logging to record access to the application will tell us, without having to call the customer.
2. “This error occurs every single time I do…”
Does it occur every time? With a web/service application, the error logs will tell us. They may also give insight as to what is causing the error. Don’t forget that logging a full exception give that Holy Grail – a stack trace!
3. “We’re getting this error only sometimes”
That favourite – the intermittent error. With DEBUG logging available, we can up the logging level for a time to capture a better trace of activity leading up to the (logged, of course) error.
4. Failure between services
The provider of a service with which our service communicates tells us that there’s nothing coming from you. Error logging shows that the username/password being used is failing authentication. The provider had changed passwords without telling us.
Logging is your friend
On a recent skiing trip, one of the superlative skiers evangelized “Speed is your friend.” Not so sure about that, but I’m certain that “Logging is your friend” – but you must plan your logging early, while coding.
Oh yes, and don’t leave DEBUG logging on a live server unless you’re happy to get the “The disk is full” call from Server Ops.