Discourse 出现短暂的“宕机” - 如何从日志中获取更多信息

你好,

今天早上我收到一些用户警告说我们的 discourse 安装似乎宕机了,但当我检查时它又恢复正常了。我的监控堆栈显示有多个“离线”行为,但当我通过 launcher logs app 查看日志时,它们似乎没有带时间戳(:confused:),而且可能只显示最近的日志,并没有区分日志来源,因为 discourse 安装包含多个组件(nginx、redis、psql 等)。

有没有办法获得更准确的日志,或者更好的是,以某种方式暴露它们,以便我可以使用 loki / promtail 捕获它们?

所有图表都显示“过去 5 天”,因为我只在那个时候添加了此监控。这是我在监控中看到的内容:

容器正常运行时间:

来自 discourse-prometheus 插件,有很多“空洞”,我猜是因为 discourse 没有响应的时候,这与我今天早上收到用户通知的时间相符:

放大最后 6 小时以澄清这不是一个“小”窗口,当然绝对不能被用户接受:

使用 ./launcher logs app 获取的日志

root@vmi1229594:/var/discourse# ./launcher logs app
x86_64 arch detected.
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 41
ok: run: redis: (pid 53) 0s
ok: run: postgres: (pid 55) 0s
supervisor pid: 51 unicorn pid: 87
Shutting Down
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normally up
run-parts: executing /etc/runit/3.d/02-unicorn
(51) exiting
ok: down: unicorn: 1s, normally up
run-parts: executing /etc/runit/3.d/10-redis
ok: down: redis: 0s, normally up
run-parts: executing /etc/runit/3.d/99-postgres
ok: down: postgres: 0s, normally up
ok: down: nginx: 5s, normally up
ok: down: postgres: 0s, normally up
ok: down: redis: 3s, normally up
ok: down: unicorn: 5s, normally up
ok: down: cron: 1s, normally up
ok: down: rsyslog: 1s, normally up
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 35
ok: run: redis: (pid 49) 0s
ok: run: postgres: (pid 48) 0s
supervisor pid: 43 unicorn pid: 81
(43) Reopening logs
(43) Reopening logs
Shutting Down
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normally up
run-parts: executing /etc/runit/3.d/02-unicorn
(43) exiting
ok: down: unicorn: 0s, normally up
run-parts: executing /etc/runit/3.d/10-redis
ok: down: redis: 0s, normally up
run-parts: executing /etc/runit/3.d/99-postgres
timeout: run: postgres: (pid 48) 34983s, want down, got TERM
run-parts: /etc/runit/3.d/99-postgres exited with return code 1
ok: down: nginx: 10s, normally up
ok: down: redis: 8s, normally up
ok: down: unicorn: 10s, normally up
ok: down: cron: 0s, normally up
ok: down: rsyslog: 0s, normally up
kill: run: postgres: (pid 48) 34991s, want down, got TERM
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 35
fail: redis: runsv not running
ok: run: redis: (pid 53) 1s
ok: run: postgres: (pid 48) 1s
supervisor pid: 79 unicorn pid: 83
(79) Reopening logs
Shutting Down
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normally up
run-parts: executing /etc/runit/3.d/02-unicorn
(79) exiting
ok: down: unicorn: 0s, normally up
run-parts: executing /etc/runit/3.d/10-redis
ok: down: redis: 0s, normally up
run-parts: executing /etc/runit/3.d/99-postgres
ok: down: postgres: 0s, normally up
ok: down: nginx: 5s, normally up
ok: down: postgres: 0s, normally up
ok: down: redis: 3s, normally up
ok: down: unicorn: 5s, normally up
ok: down: cron: 1s, normally up
ok: down: rsyslog: 1s, normally up
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 34
ok: run: redis: (pid 49) 0s
ok: run: postgres: (pid 44) 0s
supervisor pid: 41 unicorn pid: 80
(41) Reopening logs
(41) Reopening logs
(41) Reopening logs
(41) Reopening logs
(41) Reopening logs
1 个赞

为了更清楚,我补充说明我知道日志可能在容器 /var/logs 中,但根据我的经验,nginx、postgres 和 redis 都显示不出任何异常。

nginx 有大量关于请求泛滥(因此受到限制)的日志,这些请求来自用户的主题徽章 JSON。
postgresql 只是返回执行的查询(我猜的?那些查询非常长)。
redis 显示数据按应有的方式定期保存。

messages 中,我看到一些不太令人放心的消息,例如:

[....]
5月 1日 07:46:50 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 2日 07:56:45 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 2日 23:20:57 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
5月 3日 07:35:27 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 4日 07:38:08 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 5日 07:40:32 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 6日 08:01:40 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 7日 07:38:45 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 8日 07:37:31 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 9日 07:35:21 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 10日 07:53:08 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 11日 07:43:09 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 12日 07:56:06 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 12日 15:15:30 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="48" x-info="https://www.rsyslog.com"] start
5月 12日 15:59:28 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="41" x-info="https://www.rsyslog.com"] start
5月 12日 17:20:56 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="43" x-info="https://www.rsyslog.com"] start
5月 12日 18:55:45 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" x-info="https://www.rsyslog.com"] start
5月 12日 19:13:36 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="42" x-info="https://www.rsyslog.com"] start
5月 12日 21:04:24 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" x-info="https://www.rsyslog.com"] start
5月 12日 22:15:46 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="47" x-info="https://www.rsyslog.com"] start
5月 13日 07:43:36 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 13日 20:07:44 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
5月 14日 07:46:22 vmi1229594-app logrotate: ALERT 以 [1] 非正常退出
5月 14日 22:05:18 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="42" x-info="https://www.rsyslog.com"] start
5月 14日 22:16:04 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" x-info="https://www.rsyslog.com"] start
5月 14日 22:43:03 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
5月 14日 23:00:09 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
5月 15日 00:22:59 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="45" x-info="https://www.rsyslog.com"] start
5月 15日 00:56:17 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 15日 10:06:13 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="43" x-info="https://www.rsyslog.com"] start
5月 16日 07:55:46 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 16日 08:40:17 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="45" x-info="https://www.rsyslog.com"] start
5月 17日 07:58:24 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 18日 07:55:33 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 19日 07:48:14 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 20日 08:03:44 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 21日 07:40:15 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 22日 07:44:59 discourse_app logrotate: ALERT 以 [1] 非正常退出

在 syslog 中,有很多这样的信息:

[....]
5月 20日 05:17:01 discourse_app CRON[1001623]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
5月 20日 05:25:01 discourse_app CRON[1002727]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 05:35:01 discourse_app CRON[1004446]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 05:45:01 discourse_app CRON[1006215]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 05:55:01 discourse_app CRON[1007612]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 06:05:01 discourse_app CRON[1009398]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 06:15:01 discourse_app CRON[1011120]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 06:17:01 discourse_app CRON[1011400]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
5月 20日 06:25:01 discourse_app CRON[1012535]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 06:25:01 discourse_app CRON[1012537]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
5月 20日 06:35:01 discourse_app CRON[1014375]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 06:45:01 discourse_app CRON[1016178]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 06:55:01 discourse_app CRON[1017757]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 07:05:02 discourse_app CRON[1019550]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 07:15:01 discourse_app CRON[1021373]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 07:17:01 discourse_app CRON[1021667]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
5月 20日 07:25:01 discourse_app CRON[1022811]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 07:30:01 discourse_app CRON[1023931]: (root) CMD (/usr/sbin/anacron -s >/dev/null)
5月 20日 07:30:01 discourse_app anacron[1023933]: Anacron 2.3 started on 2023-05-20
5月 20日 07:30:01 discourse_app anacron[1023933]: Will run job `cron.daily' in 5 min.
5月 20日 07:30:01 discourse_app anacron[1023933]: Jobs will be executed sequentially
5月 20日 07:35:01 discourse_app anacron[1023933]: Job `cron.daily' started
5月 20日 07:35:01 discourse_app anacron[1024646]: Updated timestamp for job `cron.daily' to 2023-05-20
5月 20日 07:35:01 discourse_app CRON[1024649]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 07:45:01 discourse_app CRON[1026439]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 07:55:01 discourse_app CRON[1027921]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 08:03:44 discourse_app logrotate: ALERT 以 [1] 非正常退出
5月 20日 08:03:44 discourse_app anacron[1023933]: Job `cron.daily' terminated (exit status: 1) (mailing output)
5月 20日 08:03:44 discourse_app anacron[1023933]: Can't find sendmail at /usr/sbin/sendmail, not mailing output
5月 20日 08:03:44 discourse_app anacron[1023933]: Normal exit (1 job run)
5月 20日 08:05:01 discourse_app CRON[1029819]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 08:15:01 discourse_app CRON[1031611]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
5月 20日 08:17:01 discourse_app CRON[1031886]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
[....]

主要问题:这些消息在 Discourse 的上下文中意味着什么?我如何获取更多信息?
附注:有没有办法将这些日志提取出来,以便我收集并集中管理它们?

launcher logs 只是 docker logs 的一个包装器,后者可以使用 -t 显示时间戳。以下命令应能为您提供带时间戳的日志:

sudo docker logs -t --tail 1000 app

您在两个文件中引用的行与 Discourse 无关;如果您认为它们有关是因为其中包含 discourse_app,请注意那是一个主机名,而不是表明它们与 Discourse Docker 设置相关的标签。

根据这些行来看,似乎是 logrotate 失败了,但除非您安装了本地邮件设置,否则您将看不到详细的错误。假设您使用的是 Debian 衍生版,请执行 apt install default-mta,然后等待出现另一个错误,再使用 mail 命令检查本地邮件。

我还会检查服务器运行状况,例如可用磁盘空间、内存压力等。极端的内存压力(即分页)很可能是导致反复无响应的原因。

6 个赞

我个人会查看 dmesg 输出的相关部分——一种可能性是防火墙 (UFW) 事件正在阻止流量。

事实上,一些连接性日志记录可能会很有用,以区分机器本身无法访问的情况和 Discourse 无响应的情况。

如果您有任何类型的 CDN 安排,也请检查一下。

2 个赞

谢谢 Leonardo,我已经安装了 postfix(Ubuntu 的默认设置)。我们拭目以待。

我已经有了其他的监控,说实话,我没有看到内存或磁盘空间方面的问题。

Swap 保持在 8GB 可用内存的 2GB 左右。虚拟机有 30GB 的 RAM 可用。对我来说,真正奇怪的是 discourse 是如何占用大量资源的 → Discourse Docker HW reserved/used (CPU, RAM, Disk) and how to manage it

我对 dmesg 不太熟悉,但根据我看到的情况,有大量的 [UFW BLOCK] 消息来自不同的 IP 地址,但由于数量众多,很难判断是否存在某种模式。

举个例子:

[Tue May 23 09:32:21 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_A DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=248 ID=54321 PROTO=TCP SPT=34909 DPT=40930 WINDOW=65535 RES=0x00 SYN URGP=0
[Tue May 23 09:32:22 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_A DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=248 ID=54321 PROTO=TCP SPT=43093 DPT=40942 WINDOW=65535 RES=0x00 SYN URGP=0
[Tue May 23 09:32:29 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_B DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=249 ID=57687 PROTO=TCP SPT=42801 DPT=3350 WINDOW=1024 RES=0x00 SYN URGP=0
[Tue May 23 09:32:35 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_C DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=54 ID=61548 PROTO=TCP SPT=21721 DPT=23 WINDOW=43065 RES=0x00 SYN URGP=0
[Tue May 23 09:32:59 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_D DST=SERVER_IP LEN=44 TOS=0x00 PREC=0x00 TTL=114 ID=0 PROTO=TCP SPT=50293 DPT=1023 WINDOW=29200 RES=0x00 SYN URGP=0

标识符已匿名化,但如果它们相同,则具有相同的引用。

我们确实使用 Cloudflare,但仅作为 SSL/域名提供商和缓存。不幸的是,我并不负责这方面的工作,所以在深入研究这方面之前,我想先排除其他可能性。

我添加了一个通过 blackbox exporter 进行正常运行时间检查,指向该域以查看是否检测到任何停机时间。

是的,我和你遇到的情况类似。我认为我们唯一需要关注的是端口 80 和 443。也许可以尝试
dmesg | egrep "DPT=80 |DPT=443 " | egrep PROTO=TCP
很可能什么都没有。但如果有什么,那可能意味着防火墙正在阻止对 discourse 的访问。

是的,我这里也没有。

不过,从监控来看,容器似乎一直都在运行,主页也是如此,但实际上是应用程序没有响应请求,而且那些图表中确实没有数据,这证实了这一理论。这意味着主页可能会加载(对我们来说是类别),因为它被cloudflare缓存了,但然后浏览就会因请求超时而失败。

过去24小时

我将尝试为/latest页面添加一个新的正常运行时间检查,该页面由于内容几乎 constantly changing 而最不可能被缓存。

CloudFlare 不应该缓存您的任何页面。Discourse 是一个应用程序,而不是一个网站。

1 个赞

这些中断持续约一小时或更长时间,并且集中在午夜附近——这与您的观察一致吗?