CODEWITHSUNDEEP
phpbashsupervisord
Nathaniel Ford
Nathaniel Ford

Reputation: 21269

Timestamping logs of programs managed by supervisord

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?

Upvotes: 13

Views: 5768

Answers (3)

Gertlex
Gertlex

Reputation: 295

Edit: Guess I'll leave this here. This approach doesn't work, exactly, since the sed command just uses its startup date output in perpetuity, so the timestamps aren't correct.

Another way to accomplish this, very close to your initial attempt, would be to put your original command inside the quotes of a bash -c "command here" e.g.

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

Note I switched from > to >> since I tend to want to preserve these logs, and manage the log files via logrotate rules.

For the more general case, you may need to set up your environment as well, and that gets a bit unseemly, but at least it's all in one spot to be inspected. Toy example: bash -c "source ~/setup.bash && php /www/myapp/worker.php 2>&1 | sed ... >> /your/logfile/path.log"

(Disclaimer: Given my mild surprise that this answer doesn't exist already, I would be unsurprised to learn that this is a bad way to do things)

Upvotes: 1

Nick
Nick

Reputation: 2050

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

Upvotes: 5

Ja͢ck
Ja͢ck

Reputation: 173662

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).

Upvotes: 9

Related Questions