Laravel队列任务超时后不退出，导致队列挂起的故障分析(curl)

Laravel队列任务超时后不退出，导致队列挂起的故障分析(curl)

故障现象

昨天同事反馈一个奇怪的问题，Laravel的队列整个挂住了，任务都有设置超时，但是超时以后，任务并不会被自动终止，导致后续的任务一直得不到处理。

故障重现

最初我的反应是队列任务配置不正确导致超时机制失效，但是经过同事的验证，大部分的情况任务超时会被正常终止，只有通过Guzzle发API请求的时候才会出现这个问题。结合反馈的信息，设计了一组实验来验证此问题：

1. 超时时间设置成10s，然后任务执行sleep(15)，没有故障；
2. 超时时间设置成10s，然后任务执行sleep(8)，接着调用Guzzle（或者curl)发起请求，这个请求需要20秒才能完成，故障就出现了。

可见故障一定跟Guzzle(实际上是curl)有关。能重现故障的代码如下：

// app/Jobs/TestJob.php
<?php

namespace AppJobs;

use IlluminateBusQueueable;
use IlluminateContractsQueueShouldQueue;
use IlluminateFoundationBusDispatchable;
use IlluminateQueueInteractsWithQueue;
use IlluminateQueueSerializesModels;
use Log;
    
class TestJob implements ShouldQueue
{
    use Dispatchable, InteractsWithQueue, Queueable, SerializesModels;
    public $timeout = 10;
    public $tries = 1;

    /** 
     * Execute the job.
     *  
     * @return void
     */ 
    public function handle()
    {   
        sleep(8); // 设置为15s，超过$timeout的值，则可以正常工作
        $client = new GuzzleHttpClient();
        $url = 'http://dev1.test/longtime'; // 这是一个执行时间超过20秒的脚本
        $res = $client->get($url);
    }   
    
    public function failed(Exception $e)
    {
        Log::info('test job failed');
    }
}

通过php artisan tinker连续执行多次dispatch(new AppJobsTestJob())。队列一开立刻就重现了故障，如下面日志所示，队列在执行第1个任务时就没在打出任务东西了。

$php artisan queue:work
[2020-09-03 20:15:27][UP4PcTPaZgx2ckI4RCZhZeih5KtosfSs] Processing: AppJobsTestJob

故障分析

在分析的时候，有两个基本的判断：

1. 由于Guzzle库只是对curl的封装，所以这个问题可以断定跟curl有关；
2. 队列的超时处理需要操作系统级别的支持才能做得到，因此需要了解下Laravel是怎么实现超时的。

根据这2个判断，首先应该了解队列的超时机制，其次去分析curl为什么会影响到队列的超时机制。

于是首先查看了Larvel队列的源码关于处理超时的原理，不出意外，Laravel利用了UNIX的信号机制，通过pcntl注册SIGALRM信号的方式实现超时处理，防止进程无限等待。对应的代码在Laravel工程的vendor/laravel/framework/src/Illuminate/Queue/Worker.php可以看到：

    {
        // We will register a signal handler for the alarm signal so that we can kill this
        // process if it is running too long because it has frozen. This uses the async
        // signals supported in recent versions of PHP to accomplish it conveniently.
        pcntl_signal(SIGALRM, function () use ($job, $options) {
            if ($job) {
                $this->markJobAsFailedIfWillExceedMaxAttempts(
                    $job->getConnectionName(), $job, (int) $options->maxTries, $this->maxAttemptsExceededException($job)
                );
            }

            $this->kill(1);
        });

        pcntl_alarm(
            max($this->timeoutForJob($job, $options), 0)
        );
    }

curl会影响到队列的超时机制不能工作只有两种可能性：信号被屏蔽了或者定时器被重新注册。在GOOGLE搜索关于Laravel队列和curl的影响，果然发现其他人也碰到类似的问题。Guzzle在不设置超时的时候，就会设置CURLOPT_NOSIGNAL，于是信号被屏蔽了，SIGLARM发不出来，队列也就无法做超时处理。详见解释

https://github.com/laravel/framework/issues/22301

既然知道了原因，可以通过设置一个超时来防止CURLOPT_NOSIGNAL被设置。从Guzzle的超时参数来看，它有3个超时参数，刚开始只设置timeout没生效，于是加read_timeout和connect_timeout也一起设置了就生效了。调整后的TestJob，执行代码如下：

  // app/Jobs/TestJob.php
    public function handle()
    {   
        sleep(8); // 设置为15s，超过$timeout的值，则可以正常工作
        $client = new GuzzleHttpClient();
        $url = 'http://dev1.test/longtime'; // 这是一个执行时间超过20秒的脚本
        $res = $client->get($url, ['timeout' => 60, 'read_timeout' => 60, 'connect_timeout' => 60]); // 增加超时参数
    }   

这样修改以后，任务会被终止，日志如下：

$ php artisan queue:work
[2020-09-03 22:08:42][pkcCTZvVDeFRzKBo2QLz2qJ8KDIqGpsh] Processing: AppJobsTestJob
[2020-09-03 22:09:50][pkcCTZvVDeFRzKBo2QLz2qJ8KDIqGpsh] Failed:     AppJobsTestJob
Killed

但是仔细观察， 终止的时间并不是队列设置的超时时间，而是68秒。这是由于curl的超时也是使用了SIGALRM信号，于是队列的超时机制就被curl给代替了。关于curl的超时使用的是信号机制，在CURLOPT_TIMEOUT的参数(https://curl.haxx.se/libcurl/c/CURLOPT_TIMEOUT.html) 就有详细的说明。

结合整个分析，得出以下结论：任务队列的超时机制，在使用curl时将会无效。要想让任务在指定时间内被终止，应该设置curl的超时时间与任务的超时时间相等。任务最长被终止的时间(config/queue.php配置文件里retry_after选项)将为2*任务超时时间。

解决方案

代码中的Guzzle或者curl，都必须设置超时参数。防止在队列中调用时挂住。超时时间根据实际情况设置。

(new GuzzleHttpClient())->get('https://demo.test/api', [
   'timeout' => 30，
   'connect_timeout' => 30,
   'read_timeout' => 30
]);

参考资料

• CURLOPT_NOSIGNAL解释
• CURLOPT_TIMEOUT解释
• 为什么需要 CURLOPT_NOSIGNAL
• Worker timeout has no effect when making cURL requests with no curl timeout #22301

GuzzleHttp 请求设置超时时间

之前调用一个三方的 WEB API，大量的请求超时，导致 PHP 进程被占用完。整个网站一直报 504。

其中一个优化措施就是对三方 API 调用设置超时时间

use GuzzleHttpClient;
        
$client = new Client();
$url = 'https://www.xxxx.com';
try {
    $res = $client->request('GET', $url, ['timeout' => 1.5]);
    $res = $res->getBody();
} catch(Throwable $e) {
    Log::info('Fail to call api‘);
}

timeout 默认值是 0， 即一直等待，这非常危险。所以这里改成了 1.5 秒。

Always set a timeout for Guzzle requests inside a queued job

If you have a queued job that uses Guzzle to make a request, make sure you set a timeout value for the guzzle request:

(new GuzzleHttpClient())->get('http://domain.com', [
   'timeout' => 15
]);

If you don't set a proper timeout and the external endpoint doesn't respond, the worker will get stuck and further jobs won't get processed. Even if you have a timeout set on the worker or the job level, it will get ignored and the process will wait indefinitely.

The reason for that is cURL blocking the execution of your PHP code and thus it will not be able to handle the timeout signal sent to the worker.

Also make sure that the timeout set for the worker is more than the timeout set for the guzzle requests, otherwise the job will fail even if the guzzle request eventually succeeds.

大概意思 guzzle curl 的超时时间要小于 job任务的时间。