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

故障现象

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

故障重现

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

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

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

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

namespace App\Jobs;

use Illuminate\Bus\Queueable;
use Illuminate\Contracts\Queue\ShouldQueue;
use Illuminate\Foundation\Bus\Dispatchable;
use Illuminate\Queue\InteractsWithQueue;
use Illuminate\Queue\SerializesModels;
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 \GuzzleHttp\Client();
        $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 App\Jobs\TestJob())。队列一开立刻就重现了故障,如下面日志所示,队列在执行第1个任务时就没在打出任务东西了。

$php artisan queue:work
[2020-09-03 20:15:27][UP4PcTPaZgx2ckI4RCZhZeih5KtosfSs] Processing: App\Jobs\TestJob

故障分析

在分析的时候,有两个基本的判断:

  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_timeoutconnect_timeout也一起设置了就生效了。调整后的TestJob,执行代码如下:

    // app/Jobs/TestJob.php
    public function handle()
    {   
        sleep(8); // 设置为15s,超过$timeout的值,则可以正常工作
        $client = new \GuzzleHttp\Client();
        $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: App\Jobs\TestJob
[2020-09-03 22:09:50][pkcCTZvVDeFRzKBo2QLz2qJ8KDIqGpsh] Failed:     App\Jobs\TestJob
Killed

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

结合整个分析,得出以下结论:任务队列的超时机制,在使用curl时将会无效。要想让任务在指定时间内被终止,应该设置curl的超时时间与任务的超时时间相等。任务最长被终止的时间将为2*任务超时时间

解决方案

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

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

参考资料

posted @ 2020-09-03 22:05  枫叶落一地  阅读(3387)  评论(1编辑  收藏  举报