Discourse hat momentan "Ausfälle" - Wie man mehr Informationen aus den Logs erhält

Hallo,

Heute Morgen haben mich einige Benutzer davor gewarnt, dass unsere Discourse-Installation anscheinend ausgefallen war, aber als ich nachsah, war sie wieder online. Ich konnte in meinem Monitoring-Stack mehrere “Offline”-Verhaltensweisen erkennen, aber als ich die Protokolle über launcher logs app überprüfte, schienen sie ohne Zeitstempel ausgegeben zu werden (:confused:) und nur die aktuellsten, wie ich vermute, ohne wirkliche Unterscheidung der Protokollquelle, da eine Discourse-Installation aus mehreren Komponenten besteht (nginx, redis, psql usw.).

Gibt es eine Möglichkeit, genauere Protokolle zu erhalten oder, noch besser, sie irgendwie verfügbar zu machen, damit ich sie mit loki / promtail erfassen kann?

Alle Diagramme zeigen die “letzten 5 Tage”, da ich dieses Monitoring erst vor kurzem hinzugefügt habe. Das sehe ich in meinem Monitoring:

Container Uptime:

Vom Discourse-Prometheus-Plugin gibt es viele “Löcher”, die ich vermute, von Zeiten stammen, in denen Discourse nicht reagiert, da sie mit den Benachrichtigungen übereinstimmen, die ich heute Morgen von Benutzern erhalten habe:

Vergrößert auf die letzten 6 Stunden, um zu verdeutlichen, dass dies kein “kleines” Zeitfenster ist und für die Benutzer natürlich absolut nicht akzeptabel ist:

Logs, die mit ./launcher logs app abgerufen wurden

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 „Gefällt mir“

Zur Verdeutlichung füge ich hinzu, dass ich weiß, dass Logs im Container /var/logs liegen können, aber nginx, postgres und redis meiner Erfahrung nach nichts Ungewöhnliches zeigen.

nginx hat viele Protokolle über überflutete Anfragen (und somit Begrenzungen) für JSON-Badges von Benutzern, die von Themen kommen.
postgresql gibt einfach die ausgeführte Abfrage zurück (nehme ich an? Das sind sehr lange Abfragen).
redis zeigt nur das regelmäßige Speichern von Daten, wie es sein sollte.

In messages sehe ich einige nicht so beruhigende Meldungen, wie zum Beispiel:

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

Und in syslog gibt es viele, viele davon:

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

Hauptfrage: Was bedeuten diese Meldungen im Kontext von Discourse und wie bekomme ich mehr Informationen?
Nebenbemerkung: Gibt es eine Möglichkeit, diese Protokolle auszulagern, damit ich sie abgreifen und zentralisieren kann?

launcher logs ist lediglich ein Wrapper für docker logs, welches Zeitstempel mit -t anzeigen kann. Folgendes sollte Ihnen zeitgestempelte Protokolle liefern:

sudo docker logs -t --tail 1000 app

Die Zeilen, die Sie in diesen beiden Dateien zitiert haben, haben nichts mit Discourse zu tun. Wenn Sie das dachten, weil in einigen dieser Zeilen discourse_app steht, bedenken Sie, dass dies ein Hostname ist und kein Label, das darauf hindeutet, dass sie irgendwie mit dem Discourse Docker-Setup zusammenhängen.

Basierend darauf scheint logrotate fehlerhaft zu sein, aber Sie werden keinen detaillierten Fehler sehen, es sei denn, Sie installieren eine lokale Mail-Einrichtung. Angenommen, Sie verwenden ein Debian-Derivat, führen Sie apt install default-mta aus, warten Sie dann auf einen weiteren Fehler und überprüfen Sie dann die lokale Mail mit dem Befehl mail.

Ich würde auch die Servergesundheit überprüfen, wie z. B. den verfügbaren Speicherplatz, den Speicherdruck usw. Extremer Speicherdruck (d. h. Paging) ist eine wahrscheinliche Ursache für wiederkehrende Nichtreaktionsfähigkeit.

6 „Gefällt mir“

Ich würde persönlich die relevanten Teile der Ausgabe von dmesg durchsehen – eine Möglichkeit wäre, dass Firewall-Ereignisse (UFW) den Datenverkehr blockieren.

Tatsächlich könnte eine Protokollierung der Konnektivität nützlich sein, um den Fall zu unterscheiden, dass die Maschine selbst nicht erreichbar ist, und den Fall, dass Discourse nicht reagiert.

Wenn Sie eine Art CDN-Arrangement haben, überprüfen Sie auch das.

2 „Gefällt mir“

Danke Leonardo, ich habe Postfix (Standard für Ubuntu) installiert. Wir werden sehen, was dabei herauskommt.

Ich habe andere Überwachungen eingerichtet und ehrlich gesagt sehe ich keine Probleme mit dem Speicher oder dem Festplattenspeicher.

Swap bleibt bei etwa 2 GB von 8 GB verfügbar. Die VM hat 30 GB RAM zur Verfügung. Was mir wirklich seltsam vorkommt, ist, wie gierig Discourse damit umgeht → Discourse Docker HW reserved/used (CPU, RAM, Disk) and how to manage it

Ich bin kein Experte für dmesg, aber was ich sehe, ist eine Fülle von [UFW BLOCK]-Meldungen von verschiedenen IPs, aber da es so viele sind, ist es schwer zu verstehen, ob es ein Muster gibt.

Um Ihnen ein Beispiel zu geben:

[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

Identifikatoren sind anonymisiert, aber wenn sie gleich sind, haben sie die gleiche Referenz.

Wir verwenden Cloudflare, aber nur als SSL/Domain-Anbieter und Cache. Leider bin ich dafür nicht verantwortlich, daher möchte ich andere Möglichkeiten ausschöpfen, bevor ich in diese Richtung weitergrabe.

Ich habe eine Uptime-Prüfung über den Blackbox-Exporter hinzugefügt, die auf die Domain zeigt, um zu sehen, ob Ausfallzeiten erkannt werden.

Ja, bei mir ähnlich. Die einzigen, die uns meiner Meinung nach interessieren, sind die zu den Ports 80 und 443. Versuchen Sie vielleicht
dmesg | egrep "DPT=80 |DPT=443 " | egrep PROTO=TCP
und es ist ziemlich wahrscheinlich, dass dort nichts sein wird. Aber wenn etwas da ist, könnte das bedeuten, dass die Firewall den Zugriff auf Discourse blockiert.

Ja, bei mir auch nichts.

Jedenfalls scheint es nach der Überwachung so zu sein, dass der Container die ganze Zeit läuft und die Homepage ebenfalls, aber die App reagiert buchstäblich nicht auf Anfragen, und die Tatsache, dass es in diesen Diagrammen überhaupt keine noData gibt, bestätigt diese Theorie ehrlich gesagt. Das bedeutet, dass die Homepage wahrscheinlich geladen wird (sie ist die Kategorie für uns), da sie von Cloudflare gecacht wird, aber dann gehen die Anfragen beim Surfen einfach in einen Timeout.

Letzte 24h

Ich werde versuchen, eine neue Uptime-Prüfung auf der /latest-Seite hinzuzufügen, die höchstwahrscheinlich nicht gecacht werden kann, da sich der Inhalt fast ständig ändert.

CloudFlare sollte keine Ihrer Seiten cachen. Discourse ist eine App, keine Website.

1 „Gefällt mir“

Diese Ausfälle dauern etwa eine Stunde oder länger und häufen sich um Mitternacht – entspricht das Ihren Beobachtungen?