Laravel 5.1：主管队列致命退出，但作业与队列一起运行：听就好

【问题标题】：Laravel 5.1: supervisor queue fatal exiting but jobs run with queue:listen just fineLaravel 5.1：主管队列致命退出，但作业与队列一起运行：听就好
【发布时间】：2017-03-28 09:26:05
【问题描述】：

我多年来一直使用主管来管理我的 laravel 队列，没有任何问题，但突然在 11 月 5 日它停止工作并不断退出。我在任何地方都找不到任何错误消息。我检查了主管、laravel 的日志文件以及我记录到 bugsnag 的异常，但没有真正有用的信息。通常我会认为这是我的 laravel 应用程序中的一个问题导致退出，但我发现如果我只使用所有作业都会正常处理：

php artisan queue:listen

但是使用supervisor它会运行一段时间然后退出，或者有时在生成时退出。

这是我的程序配置文件

[program:laravel_queue]
command=php artisan queue:work --tries=3
process_name=%(program_name)s_%(process_num)02d
directory=/path/to/my/app
autostart=true
autorestart=true
user=myusername
numprocs=1
stderr_logfile=/path/to/my/logs/supervisor_queue_stderr.log
stdout_logfile=/path/to/my/logs/supervisor_queue_stdout.log

这是我的主管配置文件

; supervisor config file

[unix_http_server]
file=/var/run/supervisor.sock   ; (the path to the socket file)
chmod=0700                       ; sockef file mode (default 0700)

[supervisord]
#logfile=/var/log/supervisor/supervisord.log ; (main log file;default $CWD/supervisord.log)
logfile=/path/to/logs/supervisord.log
pidfile=/var/run/supervisord.pid ; (supervisord pidfile;default supervisord.pid)
childlogdir=/var/log/supervisor            ; ('AUTO' child log dir, default $TEMP)
loglevel=debug

; the below section must remain in the config file for RPC
; (supervisorctl/web interface) to work, additional interfaces may be
; added by defining them in separate rpcinterface: sections
[rpcinterface:supervisor]
supervisor.rpcinterface_factory = supervisor.rpcinterface:make_main_rpcinterface

[supervisorctl]
serverurl=unix:///var/run/supervisor.sock ; use a unix:// URL  for a unix socket

; The [include] section can just contain the "files" setting.  This
; setting can list multiple files (separated by whitespace or
; newlines).  It can also contain wildcards.  The filenames are
; interpreted as relative to this file.  Included files *cannot*
; include files themselves.

[include]
files = /path/to/my/program/confs/*.conf

现在我看到两个主要错误。

第一个有时会在重新启动进程后直接出现：

laravel_queue:laravel_queue_00: ERROR（生成错误）

它不是每次都出现，而是有时会说

laravel_queue:laravel_queue_00: 开始

然后它就退出了。

如果我这样做 sudo supervisorctl status 它会说：

laravel_queue:laravel_queue_00 FATAL 退出太快（进程日志可能有详细信息）

程序的 stdout_logfile 日志文件一直显示这个：

Processed: Illuminate\Queue\CallQueuedHandler@call
Processed: Illuminate\Queue\CallQueuedHandler@call
Processed: Illuminate\Queue\CallQueuedHandler@call
Processed: Illuminate\Queue\CallQueuedHandler@call
Processed: Illuminate\Queue\CallQueuedHandler@call

这没有帮助。

我将 loglevel 更改为 debug，这是我在主 supervisord 日志文件中得到的：

2016-11-14 15:51:30,255 INFO spawned: 'laravel_queue_00' with pid 13969
2016-11-14 15:51:30,445 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:30,445 DEBG fd 11 closed, stopped monitoring <POutputDispatcher at 140364068662736 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:30,446 DEBG fd 13 closed, stopped monitoring <POutputDispatcher at 140364060359496 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:30,454 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:30,454 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:31,457 INFO spawned: 'laravel_queue_00' with pid 13973
2016-11-14 15:51:31,636 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:31,637 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060359496 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:31,637 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060578304 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:31,645 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:31,645 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:33,649 INFO spawned: 'laravel_queue_00' with pid 13977
2016-11-14 15:51:33,852 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:33,853 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060359496 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:33,853 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364068662736 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:33,861 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:33,861 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:36,864 INFO spawned: 'laravel_queue_00' with pid 13981
2016-11-14 15:51:37,655 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call
2016-11-14 15:51:37,656 DEBG 'laravel_queue_00' stdout output:


2016-11-14 15:51:37,658 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364069069168 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:37,659 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364068662736 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:37,670 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:37,670 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:37,992 INFO gave up: laravel_queue_00 entered FATAL state, too many start retries too quickly
2016-11-14 15:51:47,713 INFO spawned: 'laravel_queue_00' with pid 13993
2016-11-14 15:51:47,902 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:47,903 DEBG fd 11 closed, stopped monitoring <POutputDispatcher at 140364060709376 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:47,903 DEBG fd 13 closed, stopped monitoring <POutputDispatcher at 140364060709952 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:47,911 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:47,911 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:48,914 INFO spawned: 'laravel_queue_00' with pid 13997
2016-11-14 15:51:49,092 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:49,093 DEBG fd 11 closed, stopped monitoring <POutputDispatcher at 140364060709952 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:49,093 DEBG fd 13 closed, stopped monitoring <POutputDispatcher at 140364060710528 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:49,101 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:49,101 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:51,106 INFO spawned: 'laravel_queue_00' with pid 14001
2016-11-14 15:51:51,284 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:51,284 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364059718216 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:51,284 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060709952 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:51,293 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:51,293 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:54,298 INFO spawned: 'laravel_queue_00' with pid 14005
2016-11-14 15:51:54,572 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:54,573 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364059718216 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:54,573 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060710456 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:54,582 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:54,583 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:55,584 INFO gave up: laravel_queue_00 entered FATAL state, too many start retries too quickly
2016-11-14 15:51:58,199 INFO spawned: 'laravel_queue_00' with pid 14013
2016-11-14 15:51:58,394 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:51:58,394 DEBG fd 11 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:51:58,395 DEBG fd 13 closed, stopped monitoring <POutputDispatcher at 140364060034472 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:51:58,403 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:51:58,404 DEBG received SIGCLD indicating a child quit
2016-11-14 15:51:59,407 INFO spawned: 'laravel_queue_00' with pid 14017
2016-11-14 15:52:00,407 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:52:00,407 INFO success: laravel_queue_00 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2016-11-14 15:52:00,409 DEBG fd 11 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state RUNNING> (stdout)>
2016-11-14 15:52:00,410 DEBG fd 13 closed, stopped monitoring <POutputDispatcher at 140364060034472 for <Subprocess at 140364059961176 with name laravel_queue_00 in state RUNNING> (stderr)>
2016-11-14 15:52:00,422 INFO exited: laravel_queue_00 (exit status 0; expected)
2016-11-14 15:52:00,422 DEBG received SIGCLD indicating a child quit
2016-11-14 15:52:01,426 INFO spawned: 'laravel_queue_00' with pid 14025
2016-11-14 15:52:01,620 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:52:01,620 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:52:01,620 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060034472 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:52:01,630 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:52:01,630 DEBG received SIGCLD indicating a child quit
2016-11-14 15:52:02,633 INFO spawned: 'laravel_queue_00' with pid 14059
2016-11-14 15:52:03,650 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:52:03,650 INFO success: laravel_queue_00 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2016-11-14 15:52:03,652 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state RUNNING> (stdout)>
2016-11-14 15:52:03,652 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060034472 for <Subprocess at 140364059961176 with name laravel_queue_00 in state RUNNING> (stderr)>
2016-11-14 15:52:03,663 INFO exited: laravel_queue_00 (exit status 0; expected)
2016-11-14 15:52:03,663 DEBG received SIGCLD indicating a child quit
2016-11-14 15:52:04,666 INFO spawned: 'laravel_queue_00' with pid 14068
2016-11-14 15:52:05,411 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:52:05,413 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:52:05,414 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060034472 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:52:05,424 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:52:05,424 DEBG received SIGCLD indicating a child quit
2016-11-14 15:52:06,427 INFO spawned: 'laravel_queue_00' with pid 14073
2016-11-14 15:52:06,612 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:52:06,613 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:52:06,613 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060036704 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:52:06,621 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:52:06,622 DEBG received SIGCLD indicating a child quit
2016-11-14 15:52:08,626 INFO spawned: 'laravel_queue_00' with pid 14079
2016-11-14 15:52:09,458 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:52:09,460 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:52:09,460 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060035120 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:52:09,472 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:52:09,473 DEBG received SIGCLD indicating a child quit
2016-11-14 15:52:12,478 INFO spawned: 'laravel_queue_00' with pid 14084
2016-11-14 15:52:13,325 DEBG 'laravel_queue_00' stdout output:
Processed: Illuminate\Queue\CallQueuedHandler@call

2016-11-14 15:52:13,327 DEBG fd 10 closed, stopped monitoring <POutputDispatcher at 140364060138888 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stdout)>
2016-11-14 15:52:13,328 DEBG fd 12 closed, stopped monitoring <POutputDispatcher at 140364060033968 for <Subprocess at 140364059961176 with name laravel_queue_00 in state STARTING> (stderr)>
2016-11-14 15:52:13,339 INFO exited: laravel_queue_00 (exit status 0; not expected)
2016-11-14 15:52:13,339 DEBG received SIGCLD indicating a child quit
2016-11-14 15:52:14,340 INFO gave up: laravel_queue_00 entered FATAL state, too many start retries too quickly

里面有一些奇怪的东西，比如它有时会说：

INFO 退出：laravel_queue_00（退出状态 0；不是预期的）

其他时候

INFO 退出：laravel_queue_00（退出状态 0；预期）

没有说明为什么有时是预期的，有时不是。

这可能与“startretries”配置选项有关。我可以在日志中看到一些模式。前两次有 4 个“退出代码 0；未预期”和 4 个“已处理”输出，然后才说它进入 FATAL 状态。但是第三次​​它说它进入了致命状态，它需要 8 个退出代码。然而，在那段时间内有两个“退出状态 0；预期”的实例，最终的 FATAL 错误发生在另外 4 个“退出状态 0；不预期”的实例之后，所以这可能与 4 次失败有关。但是默认的 startretries 是 3 并且我没有更改该配置选项，所以它肯定应该在 3 之后失败？或者它可能启动了 3 次而没有启动第 4 次，所以 4 次失败实际上是正确的。如果是这样，它可能与 startretries 有关。

但这并没有太大帮助，因为我仍然不知道为什么它会失败。看起来正在处理作业，因为输出说它有，我可以看到数据库中的活动与正在处理的作业一致。那么导致supervisor停止运行的错误是什么？

我不知道，经过一整天的谷歌搜索，我感到很失落。任何帮助或指示将不胜感激。

【问题讨论】：

    标签： laravel laravel-5 queue supervisord


    【解决方案1】：

    This github issue 引导我在我的主管 conf 中尝试startsecs=0，这似乎已经解决了问题。

    目前尚不清楚确切原因，我不确定这是否会导致进一步的问题（如果我的应用程序崩溃会知道吗？）但是对于其他发现此问题的人，您可能想尝试 startsecs= 0.

    我假设发生的情况是，有时我的脚本运行得如此之快，以至于主管认为它已经崩溃了

    【讨论】：

    • 如果问题是您的命令非常快并且在startsecs之前完成，则它正在解决问题
    【解决方案2】：

    这可能会发生，因为这意味着

    程序需要保持运行的总秒数 启动后认为启动成功

    所以，如果你的命令太快，它就会失败

    【讨论】：

      猜你喜欢
      • 2019-11-28
      • 2020-03-17
      • 2018-03-15
      • 2015-07-07
      • 1970-01-01
      • 1970-01-01
      • 2017-12-02
      • 1970-01-01
      • 2017-11-20
      相关资源
      最近更新 更多
      热门标签
      Java Python linux javascript Mysql C# Docker 算法 前端 SpringBoot Redis Vue spring 设计模式 .net core .net kubernetes c++ 数据库 数据结构 大数据 js 机器学习 微服务 Android Go 程序员 面试 JVM ASP.net core 云原生 人工智能 后端 PHP git CSS golang k8s Nginx Django mybatis 深度学习 多线程 React 架构 devops 爬虫 云计算 Spring Boot LeetCode