Timestamping logs of programs managed by supervisord

Question

I'm using supervisord to manage a php program that needs to be running in the background. That program logs events out to a file worker_log. It is simple enough to configure this in the supervisord.conf I'm using:

stderr_logfile=/var/log/supervisord/worker_log;

However, I'd like for the events being written to the log to timestamp themselves. I don't have control over the php program, so decorating it's log is not an option. I figured that what I would do is comment out the above logging configuration and decorate the program via command-line pipes in supervisor's command configuration:

command=php /www/myapp/worker.php 2>&1 | sed "s/^/`date` /" > /var/log/supervisord/worker_log;

When running this command manually it seems to work fine. However, supervisord seems to somehow prevent it from properly functioning, and I'm unable to tell how. worker.php performs fine, but it's reporting is, in this configuration, suppressed. And, because of that, it of course does not add the timestamp.

Does anyone know enough about this to provide guidance on how to accomplish the goal of timestamping the worker's output?

Answer 1

You could write a dedicated wrapper script that will attach a filter to the stderr before invoking your worker code:

// filter to prepend date/time on all stderr output
class eventdata_filter extends php_user_filter
{
    function filter($in, $out, &$consumed, $closing)
    {
        while (($bucket = stream_bucket_make_writeable($in))) {
            $bucket->data = date('c') . ' ' . $bucket->data;
            $consumed += $bucket->datalen;
            stream_bucket_append($out, $bucket);
        }
        return PSFS_PASS_ON;
    }
}

// register our custom filter    
stream_filter_register('eventdata', 'eventdata_filter');

// keep a reference to the attached filter
$filter = stream_filter_append(STDERR, 'eventdata', STREAM_FILTER_WRITE);

// isolate the worker from any variables in this scope, such as $filter
function run()
{
    include 'worker.php';
}

// run the worker
run();

// remove the filter
stream_filter_remove($filter);

Btw, if you don't remove the filter it causes a segmentation fault (at least, tested on 5.4).

Answer 2

a previous answer (from Jack) is correct in that you need another layer of code to timestamp each line. This one-liner in perl will achieve the same result:

perl -ne '@timeparts=localtime(); printf("%04d/%02d/%02d %02d:%02d:%02d %s",$timeparts[5]+1900,$timeparts[4]+1,@timeparts[3,2,1,0], $_);'

Use this in place of the sed script.

One problem with the approach you tried didn't work was that the date is calculated and substituted by the shell at the point that the sed command was invoked so all the lines would have had the same log timestamp