Discourse tiene "caídas" momentáneas - Cómo obtener más información de los registros

Hola,

Esta mañana, algunos usuarios me advirtieron de que nuestra instalación de Discourse aparentemente estaba caída, pero cuando la revisé, ya estaba en línea de nuevo. Pude ver varios comportamientos de “desconexión” en mi pila de monitoreo, pero cuando fui a revisar los registros con launcher logs app, parece que se muestran sin fecha ni hora (:confused:) y solo los más recientes, supongo, sin distinción real de la fuente de los registros, ya que hay varios componentes que forman una instalación de Discourse (nginx, redis, psql, etc.).

¿Hay alguna forma de tener registros más precisos o, mejor aún, exponerlos de alguna manera para poder capturarlos con loki / promtail?

Todos los gráficos son de “últimos 5 días”, ya que agregué este monitoreo solo entonces. Esto es lo que puedo ver en mi monitoreo:

Tiempo de actividad del contenedor:

Desde los plugins de discourse-prometheus, muchos “agujeros” que supongo que son de cuando Discourse no responde, ya que coinciden con las notificaciones que recibí de los usuarios esta mañana:

Ampliado las últimas 6 horas para aclarar que esta no es una ventana “pequeña” y definitivamente no es aceptable para los usuarios, por supuesto:

Registros obtenidos con ./launcher logs app

root@vmi1229594:/var/discourse# ./launcher logs app
Se detectó la arquitectura x86_64.
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
Limpiando archivos PID obsoletos
run-parts: executing /etc/runit/1.d/copy-env
Se inició runsvdir, PID es 41
ok: run: redis: (pid 53) 0s
ok: run: postgres: (pid 55) 0s
supervisor pid: 51 unicorn pid: 87
Cerrando
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normalmente activo
run-parts: executing /etc/runit/3.d/02-unicorn
(51) saliendo
ok: down: unicorn: 1s, normalmente activo
run-parts: executing /etc/runit/3.d/10-redis
ok: down: redis: 0s, normalmente activo
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
Limpiando archivos PID obsoletos
run-parts: executing /etc/runit/1.d/copy-env
Se inició runsvdir, PID es 35
ok: run: redis: (pid 49) 0s
ok: run: postgres: (pid 48) 0s
supervisor pid: 43 unicorn pid: 81
(43) Reabriendo registros
(43) Reabriendo registros
Cerrando
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
Limpiando archivos PID obsoletos
run-parts: executing /etc/runit/1.d/copy-env
Se inició runsvdir, PID es 35
fail: redis: runsv no está en ejecución
ok: run: redis: (pid 53) 1s
ok: run: postgres: (pid 48) 1s
supervisor pid: 79 unicorn pid: 83
(79) Reabriendo registros
Cerrando
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
Limpiando archivos PID obsoletos
run-parts: executing /etc/runit/1.d/copy-env
Se inició runsvdir, PID es 34
ok: run: redis: (pid 49) 0s
ok: run: postgres: (pid 44) 0s
supervisor pid: 41 unicorn pid: 80
(41) Reabriendo registros
(41) Reabriendo registros
(41) Reabriendo registros
(41) Reabriendo registros
(41) Reabriendo registros
1 me gusta

Para mayor claridad, añadiré que sé que los logs pueden estar en el contenedor /var/logs, pero nginx, postgres y redis realmente no muestran nada anormal en mi experiencia.

nginx tiene muchos logs sobre solicitudes de inundación (y por lo tanto limitando) para el JSON de insignias de usuarios que provienen de temas.
postgresql simplemente devuelve la consulta ejecutada (¿supongo? esas son algunas consultas muy largas)
redis muestra solo guardar datos regularmente como debería.

en messages veo algunos mensajes no tan 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="41" x-info="https://www.rsyslog.com"] start
May 12 17:20:56 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="43" x-info="https://www.rsyslog.com"] start
May 12 18:55:45 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" x-info="https://www.rsyslog.com"] start
May 12 19:13:36 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="42" x-info="https://www.rsyslog.com"] start
May 12 21:04:24 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" 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]

Y en syslog, muchos, muchos de estos:

[....]
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)
[....]

Pregunta principal: ¿Qué significan estos mensajes en el contexto de Discourse y cómo obtengo más información?
Nota al margen: ¿Hay alguna forma de sacar estos logs para poder recogerlos y centralizarlos?

launcher logs es simplemente un envoltorio para docker logs, que puede mostrar marcas de tiempo con -t. Lo siguiente debería darle registros con marcas de tiempo:

sudo docker logs -t --tail 1000 app

Las líneas que citaste en esos dos archivos no están relacionadas con Discourse; si lo dedujiste porque hay discourse_app en algunas de esas líneas, ten en cuenta que es un nombre de host y no una etiqueta que indique que están de alguna manera relacionadas con la configuración de Docker de Discourse.

Basándonos en ellas, parece que logrotate está fallando, pero no verás un error detallado a menos que instales una configuración de correo local. Suponiendo un derivado de Debian, ejecuta apt install default-mta, luego espera a que ocurra otro error, y luego revisa el correo local con el comando mail.

También revisaría la salud del servidor, como el espacio en disco disponible, la presión de memoria, etc. La presión extrema de memoria (es decir, paginación) es un culpable probable de la falta de respuesta recurrente.

6 Me gusta

Personalmente, revisaría las partes relevantes de la salida de dmesg, una posibilidad es que el firewall (UFW) esté bloqueando el tráfico.

De hecho, sería útil registrar la conectividad para distinguir el caso en que la máquina en sí no es accesible y el caso en que Discourse no responde.

Si tienes algún tipo de configuración de CDN, revísala también.

2 Me gusta

Gracias Leonardo, he añadido postfix (por defecto para ubuntu). Veremos qué sale de ello.

Tengo otras monitorizaciones en marcha y, para ser sincero, no veo ningún problema con la memoria o el espacio en disco.

El intercambio se mantiene alrededor de 2 GB de 8 GB disponibles. La VM tiene 30 GB de RAM disponibles. Lo que realmente me resulta extraño es lo codicioso que es discourse → Discourse Docker HW reserved/used (CPU, RAM, Disk) and how to manage it

No tengo experiencia con dmesg, pero lo que puedo ver es una plétora de mensajes [UFW BLOCK] de varias IPs diferentes, pero por supuesto, al ser tantas, es difícil entender si hay algún patrón.

Para darte un ejemplo:

[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

Los identificadores están anonimizados, pero si son los mismos, tienen la misma referencia.

Usamos Cloudflare, pero solo como proveedor de SSL/dominio y caché. Desafortunadamente, no estoy a cargo de eso, así que antes de profundizar más en esa dirección, me gustaría agotar otras posibilidades.

He añadido una comprobación de tiempo de actividad a través del exportador blackbox que apunta al dominio para ver si se detecta algún tiempo de inactividad.

Sí, similar para mí. Los únicos que nos importan, creo, son a los puertos 80 y 443. Quizás intente
dmesg | egrep "DPT=80 |DPT=443 " | egrep PROTO=TCP
y es muy probable que no haya nada allí. Pero si lo hay, eso puede significar que el firewall está bloqueando el acceso a discourse.

Sí, tampoco nada para mí.

De todos modos, a juzgar por la monitorización, parece que el contenedor está activo en todo momento y la página de inicio también, pero es literalmente la aplicación la que no responde a las solicitudes y el hecho de que no haya noData en esos gráficos confirma esa teoría, para ser honesto. Lo que eso significa es que la página de inicio probablemente cargará (es la categoría para nosotros) ya que está en caché por cloudflare, pero luego la navegación simplemente se agota en las solicitudes.

Últimas 24h

Intentaré añadir una nueva comprobación de tiempo de actividad en la página /latest, que lo más probable es que no sea cacheable debido a que el contenido cambia casi constantemente.

CloudFlare no debería estar almacenando en caché ninguna de sus páginas. Discourse es una aplicación, no un sitio web.

1 me gusta

Estas interrupciones duran aproximadamente una hora o más, y se agrupan alrededor de la medianoche, ¿coincide eso con tus observaciones?