Logging

Logging

Versions 1.0, 1.1, 2.0

Logging: What and Why

The value of logging in a headless, long-running application is obvious. In our experience, they serve as error log, debugging tool and audit trail.

We've built prototype branches that integrate Log4php and Zend Framework log into the library but as of 2.0 we've continued to ship with a very simple, one-method logging routine. Currently there are no lines of 3rd party code in use in the library (aside from PHP Extensions of course) and we'd need a very compelling reason to change that.

Deconstructing the log() method

public function log($message, $label = '', $indent = 1)

The Core_Daemon::log() method has a simple job and a simple (if slightly obtuse) implementation: Accept a string and print a formatted log entry.

The $label parameter is used by Workers and Plugins to identify the source of the message to make the combined log file easier to comprehend. You can supply your own labels for the same purpose when logging from different parts of your application. Labels will be truncated at 12 chars.

The $indent parameter gives you a very easy way to write tab-spaced output to the log. Messages you pass to the log() method are trimmed of leading and trailing whitespace. Pass an $indent argument to indent your message. Will indent every line of a multi-line or formatted message.

Logging Messages in your Application

The first time the log() method is called, it calls the log_file() (abstract) method and opens a resource handle to the file. The return value from the log_file() method is not validated and anything PHP will accept in an fopen() call is acceptable output. You can see examples of a simple log rotator implemented in the ExampleWorkers daemon.

When you're running your application inside your shell (not using the -d param to daemonize it), all log messages will be echoed to stdout as well as being written to any log file you've specified.

If the application cannot write to your log file for any reason, an E_USER_WARNING will be raised.

Multiple Processes

If you're using Workers or forked tasks in your application, all processes will write in chronological order to the same log file, as you can see in the sample excerpted below. Notice the different PID.

Logging From your Workers

You can read more about this in the Worker API Documentation.

Line Breaks

You can easily write formatted text and multi-line messages to the log without sacrificing readability. Messages are automatically split at PHP_EOL and written to the log file one-by-one. You can also use this to your benefit if you want to log two discrete messages in a single log() call.

You can see an example of formatted, multi-line logging by using the kill -10 signal to write runtime information to the log:

Date                  PID   Label         Message
[2012-05-16 13:00:24] 16599              ---------------------------------------------------------------------------------------------------
[2012-05-16 13:00:24] 16599              Application Runtime Statistics
[2012-05-16 13:00:24] 16599              ---------------------------------------------------------------------------------------------------
[2012-05-16 13:00:24] 16599              Loop Interval:        1
[2012-05-16 13:00:24] 16599              Restart Interval:     86400
[2012-05-16 13:00:24] 16599              Start Time:           1337198266 (2012-05-16 12:57:46)
[2012-05-16 13:00:24] 16599              Duration:             158 (2m 38s)
[2012-05-16 13:00:24] 16599              Log File:             /media/shared/projects/PHP-Daemon/logs/log_20120516
[2012-05-16 13:00:24] 16599              Daemon Mode:          No
[2012-05-16 13:00:24] 16599              Shutdown Signal:      No
[2012-05-16 13:00:24] 16599              Verbose Mode:         Yes
[2012-05-16 13:00:24] 16599              Role:                 Parent
[2012-05-16 13:00:24] 16599              Loaded Plugins:       Lock_File, settings
[2012-05-16 13:00:24] 16599              Loaded Workers:       PrimeNumbers 1342197841 [AVAILABLE], GetFactors 1191202898 [AVAILABLE],
[2012-05-16 13:00:24] 16599              Memory:               30670848 (29.25M)
[2012-05-16 13:00:24] 16599              Peak Memory:          30670848 (59.50M)
[2012-05-16 13:00:24] 16599              Current User:         sharter
[2012-05-16 13:00:24] 16599              Priority:             0
[2012-05-16 13:00:24] 16599              Loop duration, idle:  0.097553931342231, 0.90244606865777 (Mean Seconds)

Logging Errors

Two helper methods exist to aid error logging in your applications: Core_Daemon::error() and Core_Daemon::fatal_error(). Each of these methods take the same arguments as the log() method, and do in fact pass them right on to the log() method for logging.

In both case, immediately after the error is logged, an ON_ERROR event is dispatched. This gives you the ability to attach callbacks to the event and build whatever error handling routine you want.

In the case of fatal errors, after the event is dispatched the process will exit with error code 1. If you're in a background process the exit will happen immediately. Otherwise it will attempt to automatically restart itself.

Gotchas

1. If you are using your log_file() method to rotate logs by date or time, note that the library will cache the result of your log_file() method for at least 5 minutes. If you wanted to be able to rotate logs more frequently than that for some reason, you'll have to implement a custom version of the log() method in your application.

2. If you use the error handlers distributed with the library, note that your application will be writing messages and runtime errors thru this log() method while PHP errors are written to whatever log file you've specified in the php.ini error_log setting.

3. If you are using the Worker debug console (--debugworkers option), it will not write any logging output to stdout to prevent interference with your debugging session.

Sample Logfile Output

Date                  PID   Label         Message
[2012-05-16 22:51:33] 17403 GetFactors    Job 327 Is Complete
[2012-05-16 22:51:34] 17403 PrimeNumbers  Job 403 Is Running
[2012-05-16 22:51:34] 17403 PrimeNumbers  Job 403 to primes_among() Complete
[2012-05-16 22:51:34] 17403 PrimeNumbers  Return. Among [5, 25, 41, 205, 1025, 3343, 16715, 83575, 137063, 685315], Primes Are [5, 41, 3343]
[2012-05-16 22:51:34] 17403 PrimeNumbers  Job 403 Is Complete
[2012-05-16 22:51:34] 17403 GetFactors    Job 328 Is Running
[2012-05-16 22:51:35] 17403 GetFactors    Return: 9032115 has 6 factors
[2012-05-16 22:51:35] 17403 GetFactors    Finding Prime Factors
[2012-05-16 22:51:35] 17648 PrimeNumbers  Looking for primes among 6 items between 3 and 3010705
[2012-05-16 22:51:35] 17403 GetFactors    Job 328 Is Complete