The Importance Of Logging

Until recently I had underestimated the value that can be gained by implementing an effective logging strategy.

The most common benefit to be gained is of course that it makes your application easier to debug. As a developer you have probably tailed an apache error log when trying to debug an issue. This technique is just as good for debugging your application providing a good log exists. Having a good application log can show you at a glance where errors are occurring in your application, from technical issues like a database connection going away, to unexpected conditions being reached in the business logic, logs are invaluable.

In production logs will be used by first and second line support teams to diagnose live issues. Good descriptive log lines ensure that the right people get ‘called in the middle of the night’ to deal with a production issues. Logs help to diagnose the cause of production issues after they have occurred, they are invaluable when trying to establish the root cause of an incident or when trying to produce an issue that you can’t seem to replicate in your development environment.

Finally logs can be used to log events that occur within your application for monitoring purposes. This technique is called ‘evented logging’ . By treating each line in a log file as an event it’s possible to monitor logs for events in real time. Events could be technical: API calls, database interactions, page requests. More interestingly you can log business events: Purchases, customer interactions or cash deposits.

Using this technique it’s possible to monitor business events in real time and present them graphically to stake holders. You can see the impact a change on your live platform has on your business metrics. Has a new release dramatically reduced the number of new registrations per minute? This could point to an unexpected problem in the registration process caused by this change. An excellent tool for this (and a subject for it’s own post) is Graphite.

Bellow is an example of a common logging format used by apache.

127.0.0.1 - frank [10/Oct/2000:13:55:36 -0700] "GET /apache_pb.gif HTTP/1.0" 200 2326

In this single line we can see lots of useful information: the ip address of the request, the user’s ID (frank), the date of the request, the request made, the response and the size of the object returned (example credit: Wikipedia).This provides all the information required to log individual requests to a server. Every line in the file represents a request and the format is consistent across lines.

Application logging requires slightly different information. Heres a line to demonstrate :

URGENT c68f39913f901f3ddf44c707357a7d70  [10/Oct/2000:13:55:36 -0700] "Database connection lost in DB.php Line 4"
DEBUG c68f39913f901f3ddf44c707357a7d70  [10/Oct/2000:13:56:00 -0700] "Making call to fulfilment service"

In an application log we are aggregating numerous different pieces of information from multiple simultaneous requests so some additional meta data is required. In these lines we can see a log level, a unique hash identifying which request has generated the log line, the date time and a textual log line.

The log level is required because we may want to adjust which lines are written to the log file. Extensive debug level logging can be expensive to run in production (as each log line is a file operation). A unique hash is required to identify each request because a request may generate multiple log lines and requests are coming in to the application simultaneously. When analysing logs at a later date we may wish to isolate the lines from individual requests.

Ultimately you can decide based on your applications needs the content and format of your logs. The golden rule is it must be absolutely consistent, logs are most useful when they can be parsed at a later to time to yield information.

An evented log may look like this:

URGENT c68f39913f901f3ddf44c707357a7d70  [10/Oct/2000:13:55:36 -0700] BUSEVENT.registration "Customer Registration"
DEBUG c68f39913f901f3ddf44c707357a7d70  [10/Oct/2000:13:56:00 -0700] TECHEVENT.APICall.fulfilment "Fulfilment API Called"

It has many common attributes to the standard application log line but it also includes an easily parsed ‘.’ delimited string determining the type of event that has occurred. The string can easily be parsed and the appropriate event logged on whatever system you are using to display events to your stake holders.

There are many logging libraries you can make use of to make logging easy, they are often components in frameworks but there are also stand alone libraries. Of course it’s also easy to implement your own logging library, however you may be accused of re-inventing the wheel.

Some popular libraries:

Zend Log (part of Zend Framework)
Mono Log (Stand alone logging library used in Silex and Symfony 2)

That was my quick introduction to logging and why it’s important. Go forth and log!

Tags: Best Practise, Logging, PHP