Supervisor日志输出异常

Supervisor是用 Python 开发的在 Linux/Unix 系统下的一个进程管理工具。

用 Supervisor 管理的进程，当一个进程意外被杀死，Supervisor 监听到进程死后，会自动将它重新拉起，很方便的做到进程自动恢复的功能，不再需要自己写 shell 脚本来控制，这样就可以很方便的监听、启动、停止、重启一个或多个进程。

---

• 我们内部的某个服务发生故障，需要排除日志，发现日志的输出文件不太正常，日志分散在了十个轮转日志里面一起打了，如下所示：

$ ls -lh app-web-stderr*
-rw-r--r-- 1 root root 100K Jul 24 15:49 app-web-stderr.log
-rw-r--r-- 1 root root 100K Jul 24 14:44 app-web-stderr.log.1
-rw-r--r-- 1 root root  98K Jul 24 14:44 app-web-stderr.log.2
......
-rw-r--r-- 1 root root 102K Jul 24 14:44 app-web-stderr.log.10

$ ls -lh app-web-stdout*
-rw-r--r-- 1 root root  99K Jul 24 16:45 app-web-stdout.log
-rw-r--r-- 1 root root 102K Jul 24 14:44 app-web-stdout.log.1
-rw-r--r-- 1 root root  98K Jul 24 14:44 app-web-stdout.log.2
......
-rw-r--r-- 1 root root 100K Jul 24 14:44 app-web-stdout.log.10

• 排查了 Supervisor 和操作系统的服务日志，并没有发现有价值的报错信息。随即，排除了对应服务的 Supervisor 配置，大致如下所示：

[program:app]
directory=/opt/app
command=/usr/bin/python3 -m run_web
process_name=%(program_name)s_%(process_num)02d
user=chrism
numprocs=5
autostart=true
autorestart=unexpected
startsecs=1
startretries=3
stopasgroup=false
killasgroup=false
redirect_stderr=true
stdout_logfile=/data/logs
stdout_logfile_maxbytes=50MB
stdout_logfile_backups=10
stderr_logfile=/data/logs
stderr_logfile_maxbytes=50MB
stderr_logfile_backups=10

• 可以看到，值得注意的配置就是下面这三个了，但是看了看使用上面也没有什么有问题的地方！
  • process_name => 启动多个进程时的进程命名规则
  • stderr_logfile => 错误日志文件路径
  • stdout_logfile => 正常日志文件路径
• 所以，又看了下官方文档对于上述三个参数的解释，发现如下图的注意事项。可以看到，官方文档里面提示：当启用日志轮转的功能时，两个进程不可能共享同一个日志文件，如果使用的话将导致文件被损坏。这是就在考虑，是不是因为服务启动时启用多进程，导致多个进程同时写一个配置文件，导致日志输出发生异常。但是仔细考虑了下，发现如果真是这个问题，出问题的也只会是一个单个文件，并不会导致日志同时输出到多个轮转日志里面的。呃呃呃，没搞明白到底发生了什么事情。

• 查了下服务器上面对应的 Supervisor 版本并不是最新的，考虑是不是 Supervisor 工具自身的 Bug 导致的呢？随后，翻看了官方仓库中的 CHANGES.rst 文件以及 issue 的相关条目，并没有发现相同问题的描述。

$ dpkg -l | grep supervisor
ii    supervisor    3.x.x-x.x    all    System for controlling process state

• 这时抱着试一试的态度，通过 lsof 命令查看对应的十个日志文件，到底是那些进程打开的呢？使用如下命令，查看之后才发现，对应的这几个文件，都被 supervisor 进程给打开了。

# 同样的PID接管了日志文件
$ sudo lsof app-web-stderr.log
COMMAND     PID   USER  FD   TYPE  DEVICE  SIZE/OFF      NODE  NAME
supervisor  2228  root  xxw   REG    x,xx  2431xx20  1416xx18  /var/log/supervisor/app-web-stderr.log

# 同样的PID接管了日志文件
$ sudo lsof app-web-stderr.log.1
COMMAND     PID   USER  FD   TYPE  DEVICE  SIZE/OFF      NODE  NAME
supervisor  2228  root  xxw   REG    x,xx  2431xx20  1416xx18  /var/log/supervisor/app-web-stderr.log.1

# 同样的PID接管了日志文件
$ sudo lsof app-web-stderr.log.2
COMMAND     PID   USER  FD   TYPE  DEVICE  SIZE/OFF      NODE  NAME
supervisor  2228  root  xxw   REG    x,xx  2431xx20  1416xx18  /var/log/supervisor/app-web-stderr.log.2

• 走到这里，现在基本就可以大致判断出问题的原因了，就是因为某些因素或者工具 Bug 导致 Supervisor 异常接管对应日志文件，使日志内容输出到多个文件。后来通过重启 Supervisord 服务，使日志输出正常了，到现在为止也没有再出现同样的问题了。

# 重启服务
$ systemctl restart supervisor.service