a little tech and a little rock'n'roll

Optimized Error Logging With Zend Framework

If you have a large code base, it’s a good idea to log any errors that might occur. It helps you to become aware of errors and to track them down. If you’re not careful though, those logs and messages can quickly overwhelm you, so it’s wise to develop a logging strategy.

I’d like to share a few tips here on how to optimize your error logging when using Zend Framework (“ZF”), one of the most established PHP frameworks available. I assume that you already know to use this framework. .

Basic Strategies – Filtering And Fingerprinting

When we released the e-fellows.net Community (a closed social network for holders of the e-fellows.net scholarship), logging was a straight-forward affair: all errors were logged to a file. It quickly became apparent that this was not good enough: often, critical errors went undetected for days, because nobody bothered to look into the logs regularly.

So we implemented a priority-based filtering strategy: errors and log messages up to a certain log priority are logged into various files, as before. Additionally, more important errors are sent out via email to a workflow folder that is checked regularly. The most critical errors are emailed directly to all members of technical staff.

All was fine for a while until we realized that sometimes, for example after a release, the same error occurs repeatedly on every page, leading to thousands of emails that flood your inbox within minutes. That’s why we came up with the idea of assigning each log message a unique fingerprint which is stored in the database. Each time a message is to be logged, its fingerprint is first checked in the database. If it has already been logged within the last, say, 24 hours, it is discarded.

The last step was to setup log-rotating on the server, i.e. older logs are automatically archived and then deleted after a certain time (but that’s beyond the scope of this article).

Next I’m going to show you how to setup log filtering with the Zend Framework. Message fingerprinting
will be covered later in the article.

Next, for each log, we define a file-based log writer that writes all messages above a certain priority to a specified file. Messages with a lower priority (i.e. debug messages) are discarded. If we really want to see those debug messages (like for, uhm, debugging), we just change the corresponding config setting. Message priorities are actually arbitrary (though you have to choose one of the pre-determined values). It’s up to you to define what priority an error should have and what that means to you.

(Note: In the code above, we first determine all available log levels via reflection. Then we define that all messages with a priority below a certain threshold get logged (all others will be discarded). That’s because in the Zend Framework (like with UNIX system logs), a more severe error is mapped to a priority with a lower numeric value. In this article, I describe things the other way round because I find it more intuitive that way.)

Next, we set up a log writer that emails log messages with priority “ERR” or higher. It includes another threshold for sending critical messages to another mail address, but we’ll come to that later. $mailWriter = new Default_Helpers_EmailLogWriter();
$mailFilter = new Zend_Log_Filter_Priority(Zend_Log::ERR);
$mailWriter->addFilter($mailFilter);
$mailWriter->setFormatter($simpleFormatter);

Lastly, we instantiate a logger object, attach the two writers to it and save it in a registry for easier access: $logger = new Zend_Log();
$logger->addWriter($fileWriter);
$logger->addWriter($mailWriter);
Zend_Registry::set('log' . ucfirst($aLogger), $logger);
}

Log Usage

Logging an error is straight-forward and done the standard Zend Framework way. In client code, errors are logged like this:Zend_Registry::get('logDatabase')->err(__METHOD__ . ' - error getting proper
sysid from oracle');
The developer doesn’t need to know how log messages are handled internally. We just get a log from the registry and write an entry with a certain priority. (For exceptions, we use another method which includes a stack trace.)

This would result in a log message like the following, which contains information about the date, method name and the actual message:Fri, 22 May 2009 14:19:57 +0200, Default_Helpers_Database::getNextSysId() -
"error getting proper sysid from oracle" (ERR)

Based on its high priority, this message would get logged to file and be sent out via email, too.

The first two lines of the _write method check whether the method was logged before (see below). If not, we instantiate a mail helper and send the log message via email. Remember, messages only get this far if their priority is at least “ERR”. If the error is even more critical, it is not sent to the standard address, but directly to the admin team’s inboxes, to make sure it gets handled promptly.

Logging Messages Only Once A Day

In order to avoid sending the same email repeatedly, we create an md5 hash for each message and store this hash value, or “fingerprint”, in the database (remember that the message contains additional info like the method the error occurred in). If this message was already logged within the last 24 hours (or any other interval we have configured), we discard it. This is determined with the help of the Default_Models_ErrorHash class:

This class only contains one method which checks whether an error is already “known”. First we delete all hashes that are older than the configured interval. Then we look up the message’s fingerprint in the database. If it is found in the database (i.e. it was already logged within the last 24 hours), we simply return true. Otherwise, the hash will be inserted into the database. public function isErrorAlreadyLogged($errorMsg)
{
$db = $this->getAdapter();
$where = $db->quoteInto('created <= DATE_SUB(NOW(), INTERVAL ? HOUR)',
Zend_Registry::get('config')->log->resendErrorMailAfter);
$db->delete($this->_name, $where);
if (false === empty($errorMsg)) {
$md5 = md5($errorMsg);
$query = 'SELECT COUNT(*) FROM '.$this->_name.' WHERE errorhash=?';
if($db->fetchOne($query, $md5)) {
return true;
} else {
$db->insert($this->_name, array('errorhash' => $md5));
}
}
return false;
}
}

Wrap-up

There you have it: I have shown you how to filter log messages with the Zend framework based on their priority, and how to avoid getting flooded with log emails. Both strategies help to make much better sense of your error logs.

Have you found other ways to optimize your error logs? If so, please share them below.

5 thoughts on “Optimized Error Logging With Zend Framework”

I think that errors that are recurrent within the set period of time, as indicated by the filter, should be logged twice. Once when the error first happens, and a second time after the set period of time has passed, indicating the number of occurrences. Yes, this would require that we count the occurrences, and will also required a cron job to check the table where the counts are kept in order to generate the second log.

Also, what happens if there is a db error and the error’s fingerprint can not be saved, or an error writing to the log files?

Great article. I will surely incorporate some of your techniques here.

What I am currently researching is how to set a layout for a mail logs. So I can have custom formatting and include extra information such as request, logged in user, etc rather than a dump of log information which looks like a dogs breakfast.

Will surely post back here if I have any luck, have you tried the same?

I didn’t include a zip file with code because this was not meant as a complete tutorial, but rather a collection of a few helpful tips.

We have since extended our setup to include a “count” column that records the number of times an error occured, and a description column that logs the error message, to make this table more intuitive.

We have now also taken into account the case where the logger cannot write into that table (which has actually happened once or twice for various reasons). If this happens, we try no further logging and send out a direct mail to technical staff instead.

We have no particular formatting for our error mails, usually we just include time of error, system/server, actual message and a stack trace, all on separate lines. That’s still sufficient for our needs.