-
Notifications
You must be signed in to change notification settings - Fork 134
Logging
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.
public function log($message, $is_error = false, $label = '')
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 second, $is_error parameter, is only used to dispatch an ON_ERROR message. There's nothing listening to that event at the library level, it exists entirely to give you the option of integrating error codes / error handlers for catchable application errors.
The final parameter is used by Workers and Plugins to identify the source of the message to make the combined log file easier to comprehend.
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.
If the application cannot write to the log file specified for any reason, or if you pass the -v Verbose Mode flag at the command line, the daemon will also write the log messages to stdout. In daemon mode this is often useful but during development it avoids the 2 second delay you see when you tail -f a log file.
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 Implementation Guide.
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)
Fatal Errors
The Core_Daemon::fatal_error() method does exactly what it says it does -- but it's worth mentioning here that the first argument passed to the method is expected to be a string log message and is passed to log() as the daemon is shut-down in response to the error condition.
-
Remember that your
log_file()method is called once, the first time a message is logged. If you're trying to rotate messages very strictly by date or time you will experience issues with that. For example, the ExampleWorkers daemon usesdate('Ymd')in thelog_file()method to rotate logs daily. If the daemon is started at 05:00:00 on May 15, and is set to auto-restart every day, messages logged from 00:00:00-04:59:59 on May 16th will be written, cached file handle, to the 20120515 log file. -
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.inierror_logsetting. -
If you are using the Worker debug console (
--debugworkersoption), it will disable verbose mode to prevent interference.
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