Discourse tendo "quedas" momentâneas - Como obter mais informações dos logs

Olá,

Esta manhã, alguns usuários me avisaram que aparentemente nossa instalação do Discourse estava fora do ar, mas quando verifiquei, ela já estava no ar novamente. Houve vários comportamentos “offline” que pude ver em minha pilha de monitoramento, mas quando fui verificar os logs via launcher logs app, parece que eles são exibidos sem data/hora (:confused:) e apenas os mais recentes, presumo, sem distinção real da origem dos logs, pois existem vários componentes que formam uma instalação do Discourse (nginx, redis, psql, etc.).

Existe alguma maneira de ter logs mais precisos ou, melhor ainda, expô-los de alguma forma para que eu possa capturá-los com loki / promtail?

Todos os gráficos são de “últimos 5 dias”, pois adicionei este monitoramento apenas naquela época. Isso é o que posso ver em meu monitoramento:

Uptime do Container:

A partir dos plugins do discourse-prometheus, muitos “buracos”, que suponho serem de quando o Discourse não está respondendo, pois correspondem a quando fui notificado pelos usuários esta manhã:

Zoom nos últimos 6 horas para esclarecer que esta não é uma janela “pequena” e definitivamente não é aceitável pelos usuários, é claro:

Logs obtidos com ./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 curtida

Para clareza, adicionarei que sei que os logs podem estar no contêiner /var/logs, mas nginx, postgres e redis realmente não mostram nada anormal na minha experiência.

nginx tem muitos logs sobre requisições de inundação (e, portanto, limitação) para o JSON de distintivos de usuários vindos de tópicos.
postgresql simplesmente retorna a consulta executada (eu acho? são algumas consultas muito longas).
redis mostra apenas salvando dados regularmente como deveria.

Em messages, vejo algumas mensagens não muito reconfortantes, como:

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

E em syslog, muitas e muitas destas:

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

Pergunta principal: O que essas mensagens significam no contexto do Discourse e como obtenho mais informações?
Nota lateral: Existe uma maneira de extrair esses logs para que eu possa coletá-los e centralizá-los?

launcher logs é simplesmente um wrapper para docker logs, que pode mostrar timestamps com -t. O seguinte deve fornecer logs com timestamps:

sudo docker logs -t --tail 1000 app

As linhas que você citou nesses dois arquivos não estão relacionadas ao Discourse; se você pensou assim porque há discourse_app em algumas dessas linhas, lembre-se de que este é um nome de host e não um rótulo que indica que eles estão de alguma forma relacionados à configuração do Docker do Discourse.

Com base neles, parece que o logrotate está falhando, mas você não verá um erro detalhado a menos que instale uma configuração de e-mail local. Assumindo um derivado do Debian, execute apt install default-mta, depois espere até que ocorra outro erro e, em seguida, verifique o e-mail local com o comando mail.

Eu também verificaria a saúde do servidor, como espaço em disco disponível, pressão de memória, etc. Pressão extrema de memória (ou seja, paginação) é um culpado provável para a falta de resposta recorrente.

6 curtidas

Pessoalmente, eu daria uma olhada nas partes relevantes da saída do dmesg - uma possibilidade é que eventos do firewall (UFW) estejam bloqueando o tráfego.

Na verdade, algum registro de conectividade pode ser útil, para distinguir o caso de que a máquina em si está inalcançável e o caso de que o discourse não está respondendo.

Se você tiver algum tipo de configuração de CDN, verifique isso também.

2 curtidas

Obrigado Leonardo, adicionei o postfix (padrão para ubuntu). Veremos o que sai disso.

Tenho outros monitoramentos em vigor e, para ser honesto, não vejo nenhum problema com memória ou espaço em disco.

O Swap permanece em torno de 2 GB de 8 GB disponíveis. A VM tem 30 GB de RAM disponíveis. O que realmente é estranho para mim é como o discourse é ganancioso com isso → Discourse Docker HW reserved/used (CPU, RAM, Disk) and how to manage it

Não tenho experiência com dmesg, mas o que posso ver é uma infinidade de mensagens [UFW BLOCK] de vários IPs diferentes, mas é claro que, sendo tantos, é difícil entender se há um padrão.

Para dar um exemplo:

[Ter 23 de maio 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
[Ter 23 de maio 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
[Ter 23 de maio 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
[Ter 23 de maio 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
[Ter 23 de maio 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

Os identificadores são anonimizados, mas se forem os mesmos, eles têm a mesma referência.

Usamos o Cloudflare, mas apenas como provedor de SSL/domínio e cache. Infelizmente, não sou o responsável por isso, então antes de me aprofundar nessa direção, gostaria de esgotar outras possibilidades.

Adicionei uma verificação de uptime via blackbox exporter que aponta para o domínio para ver se há alguma inatividade detectada.

Sim, semelhante para mim. Os únicos que nos importam, acho, são para as portas 80 e 443. Talvez tente
dmesg | egrep "DPT=80 |DPT=443 " | egrep PROTO=TCP
e é bem provável que não haja nada lá. Mas se houver, isso pode significar que o firewall está bloqueando o acesso ao discourse.

Sim, nada para mim também.

De qualquer forma, a julgar pelo monitoramento, parece que o contêiner está sempre ativo e a página inicial também, mas é literalmente o aplicativo que não responde às solicitações e o fato de haver noData (sem dados) no período nesses gráficos confirma essa teoria, para ser honesto. O que isso significa é que a página inicial provavelmente carregaria (é a categoria para nós) pois é armazenada em cache pelo Cloudflare, mas a navegação simplesmente entra em tempo limite nas solicitações.

Últimas 24h

Tentarei adicionar uma nova verificação de tempo de atividade na página /latest, que muito provavelmente não pode ser armazenada em cache devido ao conteúdo estar mudando quase constantemente.

O CloudFlare não deve armazenar em cache nenhuma de suas páginas. O Discourse é um aplicativo, não um site.

1 curtida

Essas interrupções duram cerca de uma hora ou mais e ocorrem perto da meia-noite - isso corresponde às suas observações?