Get the current task being run when Laravel queue:listen times out

Question

We are running Laravel 4 with supervisord / SQS and we have 30+ different tasks being run using 10 worker processes. All has been going very well however it seems that certain tasks have started to timeout. We get an exception like this:

[Symfony\Component\Process\Exception\ProcessTimedOutException]
The process ""/usr/bin/php5" artisan queue:work  --queue="https://sqs.us-east-     1.amazonaws.com/xxxx" --delay=0 --memory=128 --sleep=3 --tries=0 --env=development" exceeded the timeout of 180 seconds.

I can catch this exception using this:

App::error(function(Symfony\Component\Process\Exception\ProcessTimedOutException $exception) {

    /// caught!
});

However I can't seem to determine WHICH task is being run (when the timeout occurs) and even better if I can access the data which was passed to the task..

I have tried logging the exception object stack trace:

$exception->getTraceAsString()

However, this doesn't get me enough detail about the task that was called.

UPDATE

I have done more research on how the php artisan queue:listen works. Some references:

• Illuminate/Queue/Console/Listen
• Illuminate/Queue/Listener
• Symfony/Component/Process

Basically, when you call php artisan queue:listen, a SUB-PROCESS (using Symfony/Component/Process) is created which essentially runs the command php artisan queue:work. That sub-process fetches the next job from the queue, runs it, reports when complete, and then the Listener spawns another sub-process to handle the next job.

So, if one of the sub-processes is taking longer than the established timeout limit, the PARENT Listener throws an exception however, the parent instance has no data about the sub-process it created. WITH A SLIGHT EXCEPTION! It appears that the parent Listener DOES handle the sub-process' output. It appears to me that the parent does nothing more than render the sub-process' (worker) output to the console. However, perhaps there is a way to capture this output so that when an exception is thrown, we can log the output and therefore have knowledge about which task was running when the timeout occurred!

I have also noticed that when using supervisord, we are able to specify a stdout_logfile which logs all of the worker output. Right now we are using a single log file for all of our 10 supervisord "programs". We could change this to have each "program" use it's own log file and then perhaps when the timeout exception is thrown on the parent Listener, we could have it grab the last 10 lines of that log file. That would also give us info on which tasks are being run during the timeout. However, I am not sure how to "inform" the parent Listener which supervisord program it is running so it knows which log file to look at!

Answer 1

Looking at the exception class (Symfony\Component\Process\Exception\ProcessTimedOutException) I found the method getProcess() which returns an instance of Symfony\Component\Process\Process. In there you got getOutput(). The method does what it's name says.

As you proposed in the comments you can use this by echoing classname and parameters in each task and then using the generated output to determine the problematic task. As you said, it's not very elegant but I can't think of a better way (except maybe tinkering with the Illuminate\Queue\Listener class...)

Here's an example how you could do it (untested though)

I chose this format for the output:

ClassName:ParametersAsJson;ClassName:ParametersAsJson;

So in a BaseTask I'd do this:

abstract class BaseTask {
    public function fire(){
        echo get_class($this) . ':' . json_encode(func_get_args()) . ';';
    }
}

Unfortunately that means in every task you will have to call parent::fire

class Task extends BaseTask {
    public function fire($param1, $param2){
        parent::fire($param1, $param2);

        // do stuff
    }
}

And finally, the exception handler:

App::error(function(Symfony\Component\Process\Exception\ProcessTimedOutException $exception) {

    $output = $exception->getProcess()->getOutput();
    $tasks = explode(';', $output);
    array_pop($output); // remove empty task that's here because of the closing ";"
    $lastTask = end($tasks);
    $parts = explode(':', $lastTask);

    $className = $parts[0];
    $parameters = json_decode($parts[1]);

    // write details to log

});

Answer 2

Since Laravel 4.1 there is a built-in mechanism for handling failed jobs where all job details are persisted in database or available at exception-time (or both). Detailed and clear documentation is available on Laravel's website.

To summarise:

1. Laravel can move failed jobs into a failed_jobs table for later review
2. You can register an exception handler via Queue::failing, which will receive detailed job information for immediate handling

However, it is questionable whether a timeout is considered a failure in Laravel, so this requires testing as I do not have hands-on experience with queues.

If you use Laravel 4.0 perhaps it would be worthwhile to evaluate an upgrade at least to 4.1 instead of writing complicated code that will become redundant once you really have to upgrade (you will upgrade at some point, right? :) ). Upgrade path seems quite straightforward.

While this does not directly answer your question for Laravel 4.0 it is something you and any future reader may consider.