NEWS & BLOG

“How can we speed up the sales summary report?”

“I get an error when I try to edit a customer’s address”

What helps when faced with questions such as these is a sufficiently detailed record of what happened when, and that’s where application logging can help. Ideally, logging will be built into the application as it’s developed rather than waiting until questions come up and then trying to retrofit it later (and possibly having to justify them in a change control process).

Effective logging from your application can highlight false assumptions, programming errors and performance issues.

Here’s an extract from an application log:

Nov 5 19:30:01 db2 sales_summary: Job Started
Nov 5 19:30:01 db2 sales_summary: Getting dashboard stats
Nov 5 19:30:05 db2 sales_summary: Retrieved dashboard stats
Nov 5 19:30:05 db2 sales_summary: Getting monthly sales data
Nov 5 19:30:07 db2 sales_summary: Retrieved monthly sales data
Nov 5 19:30:07 db2 sales_summary: Getting monthly lead data
Nov 5 19:30:09 db2 sales_summary: Retrieved monthly lead data
Nov 5 19:30:09 db2 sales_summary: Getting monthly sales by area
Nov 5 19:58:07 db2 sales_summary: Retrieved monthly sales by area
Nov 5 19:58:07 db2 sales_summary: Writing /tmp/tmp.PAykYbLHg9/sales.csv
Nov 5 19:58:07 db2 sales_summary: Closed /tmp/tmp.PAykYbLHg9/sales.csv

Every section of this job takes seconds, except for “Getting monthly sales by area”. If you’re looking to tune up your sales reports, that would be the area to focus on. The good news is logging like this needn’t be hard to do.

How Not To Do Application Logging

Developers often create what is intended to be temporary logfiles – for example, /tmp/myapplication.log – in order to see what’s going on.

That’s not a good idea.

Firstly – and for good reason – such temporary logging often becomes more permanent than intended. Secondly, the log files fill up disk space, and will continue to do so unless manual action is taken to remove them or reduce their size.

Better would be to use the system logging facilities that every Linux system has, which takes care of the following for free:

• The log files will be in a consistent location, typically alongside (or combined with) other system logs
• The log files will be automatically “rotated”. That is, periodically the log file will be closed, a new one started, and the old one optionally compressed. After a predetermined time, the oldest log files will be removed. This is fully automatic: no need to manually remove old or large log files.
• The system administrator can move log files without breaking your application logging

Implement Application Logging in bash

The way that log entries are created will depend upon the language your application is written in. Let’s keep it very simple, and show how this can be done from the shell.

The utility to use is logger, typically found at /usr/bin/logger. Here’s an example of its use:

/usr/bin/logger "Hello from the logger"

Running that command will result in the following line in the system log (typically /var/log/messages or /var/log/syslog):

Aug 12 08:51:42 ws kae: Hello from the logger

That line shows:

• the date and time of the log message
• the name of the system (“ws“) that logged the event
• the username under which the process that created the log entry was running (“kae“)
• the log message itself

We can add to the information logged, such as the name of the application running and its PID:

/usr/bin/logger -i -t myapplication "Hello from the logger"

That gives:

Aug 12 08:57:12 ws myapplication[18121]: Hello from the logger

Putting that all together, here’s a somewhat contrived example of how this could be used:

/bin/bash

# Define a symbol for logging
LOG="/usr/bin/logger -i -t MyApplication --"

$LOG "Starting"
for site in /srv/www/*; do
$LOG "Processing site $site"
...
done
$LOG "Finished"

The trailing double minus at the end of line 4 marks the end of the options for logger. That means that if the message starts with a minus (hyphen), logger won’t try to interpret it as an option.

It’s possible to specify log levels and other information too; the man page logger(1) has all the details. That said, the above is very simple to implement and will suffice in the vast majority of cases.

Other Languages

Just about every common programming language has the ability to make entries in the system logs. As with the logger example  above, there are a great many options, but I believe that something simple that is actually implemented is way more useful than something complex that will be ready “soon”.

Sometimes it’s helpful to create a wrapper function. In this Python example, we call a log function with a priority parameter as well as the message. The lower priority number, the more important the message, so priority 1 is the highest. Within the script, we can elect to not log the less important messages:

import syslog

log_to_stdout = True
log_to_syslog = True
verbosity = 3
syslog_name = "sales_report"

def log(priority, msg):
    "Print msg if priority is <= verbosity"

    # Print message
    if priority <= verbosity:
        if log_to_stdout:
            print msg
        if log_to_syslog:
            syslog.syslog("%s: %s" % (syslog_name, msg))

Not Just Your Applications

As a matter of routine, we put logging into just about every script we write. 99.9% of the time we never look at the logging generated, but it’s there if needed – and we don’t have to worry about cleaning up old log files because the standard system logrotate facility does that for us.

Could this article be improved?

Let us know in the comments below.