aaLog: A Logging Class for PHP

log ladyOver the years of learning the many and various skills necessary for being a well-versed web developer, you find a number of tools to help you get things done. Sometimes you have to build those tools for yourself.

There are any number of logging solutions out there, but I decided to build my own for a number of reasons. First, I had some specific requirements in mind, and I didn’t want to spend a bunch of time exhaustively researching the available options, when I could just build my own. Secondly, building my own solution allowed me to exercise design and development muscles I might not otherwise get to flex. Thirdly, building my own allows me to share it with you.

To my great and everlasting shame, however, I never got around to documenting this class. Well, never is a long time. “Never”, until now. But it has been many years since I started this project, and I’d been meaning to post some documentation since then.

Requirements

My main requirement at the outset of this project, was that the logging output not interfere with the page’s functioning. If you pump out PHP data before your HTML, the page’s headers won’t be accepted. (For instance.) Also, it could mess with your layout.

So, the first requirement was to push the logging to a text file. I came up with more requirements, but as I recall it, they came later.

Features

  • Class-based logging functionality
  • Benchmarking method
  • Different type-based logging methods
  • Cookie-based activation, allows for selective user logging under load

Getting Started

You can get the class from GitHub: https://github.com/NotoriousWebmaster/aaLog.

Then include it in your project:

include_once "/path/to/aalog.php";
$oLog = new aalog('my/logfile.log');

Good start! But it won’t work. Why? Because aaLog insists on a specific cookie being present before it’ll operate. It’s a drag, I know, but there’s a good reason for it. If you want to use the logging facility while your site is under load (i.e. live), and you’re getting bombarded with hundreds of requests a minute, an open logging system would get far too much volume to be useful.

No, you want to hit the logfile from a limited number of sessions. Possibly even only a single one. aaLog accomplishes this by checking for the presence of a cookie; and you get this cookie like so:

$oLog->setCookie();

The only other problem you may have is if the directory where you want your logfile to go doesn’t have write permissions. But that’s a configuration issue, and I’ll leave that to you.

Using aaLog

OK, so assuming you’ve put in the three lines I’ve outlined so far, requesting your page should create the file in the appropriate directory, and log the setcookie call, because that method logs itself, for good measure. Here’s what the output looks like:

2013-06-30 00:38:01 - 127.0.0.1 - DEBUG - testlog.php - aalog.php[172] - Setting Log Cookie

Once the cookie is set, you don’t need to reset it every time to invoke a page; so you can remove that call for now. We’ll look at better ways to set and unset the cookie in a bit.

Basic Logging

I usually add this code following the instantiation of my log object, so I automatically get the $_SERVER, $_REQUEST and $_SESSION variables listed for every request:

$oLog->lograw('==================================================================');
$oLog->lograw('==================================================================');
$oLog->lograw('==================================================================');
$oLog->logServer();
$oLog->logRequest();
$oLog->logSession();

The three calls to lograw() are just for visual separation of requests in the logfile. Of course, if you don’t use sessions, there’s no point in logging the session array. In fact, you’d get a notice, assuming you have error reporting turned on, which you totally should when in development.

But there are two logging methods you’ll find you use more than any others: logdbg() and logrow().

logdbg() logs a string. So you can call it as follows:

$oLog->logdbg('Start of routine abc()');

And this would produce:

2013-06-30 00:53:04 - 127.0.0.1 - DEBUG - testlog.php - testlog.php[15] - Start of routine abc()

Let’s look at this output in more detail.

First we get the date and time from the server. Then the IP address from which came the request. Then we get the severity level of the log message; in this case DEBUG. Followed by the requested script (testlog.php), and the script and line number from which the log method was invoked.

Let’s pause for a second, at this point, and mention that this is a very useful bit of information to have. First, it lets you know exactly where the log message is coming from; which makes your debugging that much easier. Second, when you decide it’s time to remove your logging calls, it’s fairly straight forward to run down the logfile and locate all the lines where calls were made.

And, finally, we have the string we asked to be output.

This is the format for all log messages, except for lograw().

The other common log method is logrow(). It works pretty much the same as logdbg(), except in addition to the string, we supply it with an array or object, which then gets printed out. Like so:

$oLog->logrow('movies', $aMovies);

Your output might look like this (depending on what was in your $aMovies array):

2013-06-30 01:15:34 - 127.0.0.1 - DEBUG - testlog.php - testlog.php[23] - movies - Array
(
    [0] => Star Wars IV: A New Hope
    [1] => Star Trek II: The Wrath of Khan
    [2] => Event Horizon
    [3] => Groundhog Day
    [4] => Godfather, The
)

Logging Errors, and Other Severity Levels

By default, most logging methods have a severity level of DEBUG. There are a couple of other levels available; namely ERR and INFO. These can be invoked like so:

$oLog->logerr('Database connection is FUBAR');
$oLog->loginfo('here\'s some info on the DB connection: ' . print_r($db, true));

And the output:

2013-06-30 20:59:28 - 127.0.0.1 - ERR - testlog.php - testlog.php[39] - Database connection is FUBAR
2013-06-30 20:59:28 - 127.0.0.1 - INFO - testlog.php - testlog.php[40] - here's some info on the DB connection: Array
(
    [dbinfo] => abc...
)

Two things to note about these methods. First, they actually produce output even if the cookie is not set. Second, they only allow for a message string. So if you want to display the contents of an array or object, you’ll have to arrange for that on your own, with a call to print_r().

Call Depth

The script and line number where the log method is called is great and very useful. Mostly.

There are situations where it’s not so very useful. For instance, imagine a series of classes which interface with your database. This is your model, if you adhere to the MVC pattern. Now, your database classes all inherit, let’s say, from a Table class; and whenever they want to access the database, they call Table::safe_query(). Now you want to monitor all SQL scripts, so you put a call to your logger in safe_query(), like so:

$oLog->logdbg('SQL: ' . $sql);

Cool. Except this will always give the same script and line number. It would be more useful if it gave the location of the script which called safe_query(). Actually, that’s only useful while you’re developing your model. On an ongoing basis you probably want the location of the line in user code which called the model.

Well, good news everyone! aaLog allows you to do just that. Every logging method has a call depth parameter which allows you to set how far back the call stack we go to report the calling location. It might look like so:

function depthTest() {
	global $oLog;

	$oLog->logdbg('Testing call depth', 1);
}

depthTest();

A call depth of 0 would give the location of the logdbg() call (the default). A call depth of 1 gives the location of the line which called depthTest(). So here’s what we see:

2013-06-30 14:47:37 - 127.0.0.1 - DEBUG - testlog.php - testlog.php[31] - Testing call depth

In our previous MVC example you’d want to use a call depth of 2, to get the user code call location.

As an aside, you’ll notice that you need to reference $oLog in the global namespace. See the section on the future of aaLog below for possible changes to that.

Benchmarking

Yet another service aaLog provides is an easy way to benchmark your code. I typically use this around database calls, or at the beginning and end of page generation. Though browser debuggers are now doing a better job for that last use case.

The logbench() method accepts two parameters: a message, and the call depth (which defaults to 0). You call it like so:

$oLog->logbench('Depth test done');

And it produces this:

2013-06-30 15:24:13 - 127.0.0.1 - BENCH - testlog.php - testlog.php[35] - id: Depth test done - diff: 0.00014591217041 - len: 0.000267028808594

Note the severity level has been changed to BENCH. Our message is tagged with id:. And then we have diff and len values in seconds. diff is the length of time since our last logbench() call. len is the length of time since the first logbench() call. So it will come as no surprise that the first logbench() call will produce diff and len values of 0.

Other Methods

There are a few other methods. Here are brief descriptions for each.

isDebug(): return TRUE when debug mode is on.

logTrace(): dumps the callstack: a list of function calls leading to our current location. Accepts an optional call depth parameter. Here’s what the output looks like:

2013-07-01 15:06:01 - 127.0.0.1 - TRACE - testlog.php - testlog.php[37] - 
	/Users/alfred/Sites/test/htdocs/testlog.php[37] - aaLog->logtrace
	/Users/alfred/Sites/test/htdocs/testlog.php[41] - depthTest

logType(): This was a solution to the problem of booleans not displaying well in logdbg(). Specifically, FALSE values didn’t show up at all, and TRUE showed up as 1. But logType() now tests for the variable type, and formats the output accordingly. Here’s the call:

$bTest = false;
$oLog->logdbg('bTest: ' . $bTest);
$oLog->logType('bTest', $bTest);

And the output:

2013-07-01 15:19:46 - 127.0.0.1 - DEBUG - testlog.php - testlog.php[52] - bTest: 
2013-07-01 15:19:46 - 127.0.0.1 - TYPE:bln - testlog.php - testlog.php[53] - bTest - false

logASCII(): I don’t even remember when I needed this, or why I thought it’d be a good idea to make it a part of the class; but here it is. This just takes a string and pumps out the ASCII value for each character:

$oLog->logASCII('test', 'testing');

And the output:

2013-07-01 15:19:46 - 127.0.0.1 - ASCII - testlog.php - testlog.php[47] - test
1 - 116 - t
2 - 101 - e
3 - 115 - s
4 - 116 - t
5 - 105 - i
6 - 110 - n
7 - 103 - g

Security Considerations

In light of the possibly sensitive information which will find its way into the logfile, it would be a good idea to put it outside of the docroot. There’s no sense in giving the hackers any more information than we have to.

Toggling Logging

I started out adding toggling pages in the admin section of my sites; but then decided that was kind of heavy. That’s definitely still an option if you want to put the logging toggle behind the login.

Another alternative might be to check for URL variables, like so:

if (isset($_GET['setlog'])) {
  $oLog->setCookie();
} elseif (isset($_GET['unsetlog'])) {
  $oLog->unsetCookie();
}

The downside to this technique is that anyone can turn logging on or off, if they know the magic variable name. Of course, nothing prevents you from checking for login before testing for the magic variable.

The Future of aaLog

I’m not crazy about putting the aaLog instance in the global namespace. So I’ll be exploring PHP namespaces to see if there’s any way to avoid that. Of course, if I used namespaces, it would only work with projects using PHP greater than 5.3.0. Film at 11.

I’m also rethinking the severity level thing. I think it may be better to set the level in some way. I was thinking of a setLevel() method, and it could be set for either just the next call, or until it was changed again. Then I thought about JavaScript’s fluent interfaces (i.e. jQuery), and we could do something like $oLog->withLevel(AALOG_DEBUG)->logrow('my array', $myArray);. But I don’t have to decide right now.

Other than that, I’m open to suggestions. I hope you find this useful.

2 thoughts on “aaLog: A Logging Class for PHP

  1. I’ve always liked the idea of breaking logging down by severity and verbosity as 2 separate concepts. Sometimes you want debug severity but just moderate levels of verbosity and other time you want debug severity and tons of verbosity. Just something to consider while you design setLevel().

Leave a Reply