Logging Framework

In a complex application, you always end up with the need to log some information to keep runtime statistics or to debug.

Logging information has an overhead and one cannot escape it, one can only try to be wise and mitigate the consequences. The Pluf logging framework provide a set of tools allowing you to have different strategies depending of your requirements (always present logs, debugging, etc.).

Simple Logging

The simple logging methods are what you can expect from a logging framework.

Pluf_Log::log('Whatever you want to log.');
Pluf_Log::info('Whatever you want to log.');
Pluf_Log::debug('Debug information.');
Pluf_Log::fatal('Runtime situation which may crash the app.');

Depending of your settings the information will be logged or not, and, you can have then log written on disk, in the database or displayed at the bottom of your page.

Delayed Logging

Delayed logging is the action not to log directly the message coming in the log queue. This is very practical for different reasons:

You do not want to write to your logs each time a log message is issued but a series in batch for performance reasons.
You want to log everything but only if the system reach a critical state.

The negative side of the delayed logging is that your logs will not be written if your application dies before flushing. This is why you should not use this method when doing debugging leading to a crash of your application. As this is a very rare case, delayed logging is often a good solution.

To enable delayed logging, just set the log_delayed key to true and run the flush static method at the point in time you want to flush the logs.

Pluf_Log::log('This is not written to disk.');
Pluf_Log::flush(); // Here we write to disk

Of course, you can get the flushing to be handle automatically at the end of the request. In that case, just listen to the Pluf_Dispatcher::postDispatch signal:

Pluf_Signal::connect('Pluf_Dispatcher::postDispatch', 
                     array('Pluf_Log', 'flushHandler'));

You can add this at the end of your configuration file or in your main relations.php file. Be sure to connect to the Pluf_Dispatcher::postDispatch only once and everything will be fine.

Low Production Impact Logging

The drawback of the simple logging approach is that you are always calling the corresponding Pluf_Log method and generating the message even if you are not logging the message. Most of the time this will not be that problematic, but in some particular cases, the performance impact could be problematic.

The solution is to dynamically generate the log message only if logging is enabled. To do so, the assert function is used.

To log with the assert call, simply run:

$object = MyApp_Foo::complex();
assert('Pluf_Log::alog("My message: $object.")');

The difference is that instead of using the log method, you use the alog method. You also have the ainfo, adebug, afatal methods.

You can see that the string passed as argument to assert is not evaluated, it is a single quoted string. The string encapsulate a valid code fragment.nnn

The very interesting point is that the string will be evaluated and logged only if you ask for it, and it will be evaluated in the local context. This means that $object will be defined. The assert call also adds the file and line number to your message.

The positive side of assert logging:

nearly no overhead when not activated;
ability to activate this logging depending on the request;
provides automatically context with the file and line number.

The negative side:

use of assert in an undocumented way;
the code fragment to be evaluated is a bit harder to write.

The recommended usage is to use assert logging for the logs which are not going to be run that often. Typically, this will be for debugging information which you normally do not want to log in production.

If you are doing statistics logging, for example to track the database query time or other complex operations, it is better to directly use the simple logging calls as these are logging actions which are most likely to be running all the time in production.

Base activation of the assert logging is performed in your configuration file. Just add the following line at the end:

Pluf_Log::activeAssert();

This will setup the assert callbacks needed to have the assert logging running smoothly.

Configuration Settings

log_level (Pluf_Log::INFO): It will log everything. The available log levels are:
- Pluf_Log::ALL: Log everything.
- Pluf_Log::DEBUG: Log debug information for the application.
- Pluf_Log::INFO: Log normal information (this is the default).
- Pluf_Log::WARN: Log events which can lead to harmful situations.
- Pluf_Log::ERROR: Log error allowing the application to keep running.
- Pluf_Log::FATAL: Log error which makes the application stop.
- Pluf_Log::OFF: Stop all logging.
The log levels are taken from log4j.
log_handler ('Pluf_Log_File'): It will log the information in a text file.
log_delayed (false): Let the programmer control when the log is flushed, by default it is logged as soon as received, for performance you need to enable the delay and flush everything in one go at the end of the request.

Available Log Handlers

File logger `Pluf_Log_File`

This is the default logger, by default it logs in a pluf.log file in your temp folder. Set the pluf_log_file configuration setting to the full path of your log file to change the path.

HTTP logger `Pluf_Log_Remote`

Post the log to a remote host via HTTP POST. The payload is the JSON encoded stack of logs at flush time. It is recommended to activate delayed logging when using this logger to log once per request.

The settings are:

'log_remote_path': /
'log_remote_server': localhost
'log_remote_headers': An array of extra headers to send with the request, you can put your authentication header in it, empty by default. For example, array('My-Header' => 'foo').
'log_remote_port': 8000

If you use a Node.js based logger, you can get up to 350 log/s. For example, copy/paste the following code as logs.js file and run it like that node logs.js.

var sys = require("sys"),
    posix = require("posix"),
    http = require("http"),
    filename = "./pluf.nodejs.log",
    port = 8000,
    fd = posix.open(filename,
                process.O_WRONLY | process.O_APPEND | process.O_CREAT,
                process.S_IRWXU | process.S_IRGRP | process.S_IROTH
                ).wait();

record_message = function(request, msg) {
    posix.write(fd, msg+"\n");
};

http.createServer(function (request, response) {
        var content = "";
        request.addListener("body", function(chunk) {
                content += chunk;
            });
        request.addListener("complete", function() {
              record_message(request, content);
              response.sendHeader(200, {"Content-Type": "text/plain"});
              response.sendBody("stored message");
              response.finish();
            });
    }).listen(port);

Inspired by log collection server with Node.js.

Report issues in the documentation

If you find errors or issues in the documentation, report a bug. We will update the documentation accordingly.