Redis Probleme? (Forum nach Upgrade defekt)

Ich wurde heute aufgefordert, ein Upgrade durchzuführen, und musste dann den Build über den Launcher durchführen. Seitdem ist Discourse im Grunde kaputt. Bereits angemeldete Benutzer können die Startseite sehen und von dort Nachrichten auswählen, um sie anzuzeigen, aber praktisch alle Funktionen, sowohl für Benutzer als auch für Administratoren, hängen mit dem sich drehenden Ladekreis. Das Produktionsprotokoll ist leer. Ich habe natürlich versucht, zu stoppen und neu zu starten. Ich weiß nicht einmal, wo ich anfangen soll zu suchen. Ideen? Danke!

UPDATE: Wie in meinen verschiedenen Antworten unten angegeben, scheint die Ursache des Problems darin zu liegen, dass rdis keine Verbindungen akzeptiert, und der unten stehende Auszug aus dem rdis-Protokoll zeigt, dass rdis anscheinend in einer Schleife läuft, die jedes Mal beginnt mit:

100 Änderungen in 300 Sekunden. Speichere…

und niemals in den Zustand “Warte auf Verbindung” gelangt. Jegliche Vorschläge zur Behebung dieses Problems wären sehr willkommen. Vielen Dank.

1 „Gefällt mir“

Ein vorheriges Protokoll zeigt eine Vielzahl von Blöcken, z. B.:

/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus/backends/redis.rb:274:in `block in global_subscribe'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus.rb:734:in `block in new_subscriber_thread'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:117:in `block in connect'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:269:in `block in process'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-2.3.3/lib/mini_profiler/profiling_methods.rb:85:in `block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:967:in `block in get'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:72:in `block in synchronize'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus/backends/redis.rb:274:in `block in global_subscribe'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus.rb:734:in `block in new_subscriber_thread'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:117:in `block in connect'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:269:in `block in process'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-2.3.3/lib/mini_profiler/profiling_methods.rb:85:in `block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:967:in `block in get'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:72:in `block in synchronize'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus/backends/redis.rb:274:in `block in global_subscribe'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus.rb:734:in `block in new_subscriber_thread'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:117:in `block in connect'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:269:in `block in process'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-2.3.3/lib/mini_profiler/profiling_methods.rb:85:in `block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:967:in `block in get'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:72:in `block in synchronize'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus/backends/redis.rb:274:in `block in global_subscribe'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus.rb:734:in `block in new_subscriber_thread'
1 „Gefällt mir“

Ein vollständiger Systemneustart hat das Problem nicht behoben. Die Situation ist nach einem vollständigen Neustart exakt dieselbe.

1 „Gefällt mir“

unicorn.stderr.log zeigt viele Fehler beim Verbinden mit Redis, z. B.:

Fehler beim Melden des Fehlers: Fehler beim Verbinden mit Redis auf localhost:6379 (Errno::EADDRNOTAVAIL)

1 „Gefällt mir“

Hier ist das aktuelle Redis-Protokoll:

3112:C 23 Dez 2021 01:56:54.912 # oO0OoO0OoO0Oo Redis startet oO0OoO0OoO0Oo
3112:C 23 Dez 2021 01:56:54.912 # Redis-Version=6.2.6, Bits=64, Commit=00000000, Modifiziert=0, PID=3112, gerade gestartet
3112:C 23 Dez 2021 01:56:54.912 # Konfiguration geladen
3112:M 23 Dez 2021 01:56:54.914 * Monotonische Uhr: POSIX clock_gettime
3112:M 23 Dez 2021 01:56:55.105 * Ausführungsmodus=standalone, Port=6379.
3112:M 23 Dez 2021 01:56:55.105 # WARNUNG: Die TCP-Backlog-Einstellung von 511 kann nicht erzwungen werden, da /proc/sys/net/core/somaxconn auf den niedrigeren Wert 128 gesetzt ist.
3112:M 23 Dez 2021 01:56:55.105 # Server initialisiert
3112:M 23 Dez 2021 01:56:55.105 # WARNUNG: overcommit_memory ist auf 0 gesetzt! Hintergrundspeicherung kann bei geringem Arbeitsspeicher fehlschlagen. Um dieses Problem zu beheben, fügen Sie 'vm.overcommit_memory = 1' zu /etc/sysctl.conf hinzu und starten Sie dann neu oder führen Sie den Befehl 'sysctl vm.overcommit_memory=1' aus, damit dies wirksam wird.
3112:M 23 Dez 2021 01:56:55.401 * Laden von RDB, erstellt von Version 6.2.6
3112:M 23 Dez 2021 01:56:55.401 * RDB-Alter 296 Sekunden
3112:M 23 Dez 2021 01:56:55.401 * RDB-Speichernutzung bei Erstellung 4,86 MB
3112:M 23 Dez 2021 01:56:55.634 # Laden von RDB abgeschlossen, Schlüssel geladen: 2751, Schlüssel abgelaufen: 2.
3112:M 23 Dez 2021 01:56:55.634 * DB von Festplatte geladen: 0,528 Sekunden
3112:M 23 Dez 2021 01:56:55.634 * Bereit für Verbindungsannahme
3112:M 23 Dez 2021 02:01:55.037 * 100 Änderungen in 300 Sekunden. Speichere...
3112:M 23 Dez 2021 02:01:55.038 * Hintergrundspeicherung gestartet von PID 3523
3523:C 23 Dez 2021 02:01:55.140 * DB auf Festplatte gespeichert
3523:C 23 Dez 2021 02:01:55.142 * RDB: 0 MB Arbeitsspeicher von Copy-on-Write verwendet
3112:M 23 Dez 2021 02:01:55.239 * Hintergrundspeicherung erfolgreich beendet
3112:M 23 Dez 2021 02:06:56.065 * 100 Änderungen in 300 Sekunden. Speichere...
3112:M 23 Dez 2021 02:06:56.065 * Hintergrundspeicherung gestartet von PID 3831
3831:C 23 Dez 2021 02:06:56.134 * DB auf Festplatte gespeichert
3831:C 23 Dez 2021 02:06:56.136 * RDB: 0 MB Arbeitsspeicher von Copy-on-Write verwendet
3112:M 23 Dez 2021 02:06:56.166 * Hintergrundspeicherung erfolgreich beendet
3112:M 23 Dez 2021 02:11:57.071 * 100 Änderungen in 300 Sekunden. Speichere...
3112:M 23 Dez 2021 02:11:57.071 * Hintergrundspeicherung gestartet von PID 4138
4138:C 23 Dez 2021 02:11:57.135 * DB auf Festplatte gespeichert
4138:C 23 Dez 2021 02:11:57.137 * RDB: 0 MB Arbeitsspeicher von Copy-on-Write verwendet
3112:M 23 Dez 2021 02:11:57.172 * Hintergrundspeicherung erfolgreich beendet
3112:M 23 Dez 2021 02:16:58.000 * 100 Änderungen in 300 Sekunden. Speichere...
3112:M 23 Dez 2021 02:16:58.001 * Hintergrundspeicherung gestartet von PID 4448
4448:C 23 Dez 2021 02:16:58.064 * DB auf Festplatte gespeichert
4448:C 23 Dez 2021 02:16:58.066 * RDB: 0 MB Arbeitsspeicher von Copy-on-Write verwendet
3112:M 23 Dez 2021 02:16:58.101 * Hintergrundspeicherung erfolgreich beendet
1 „Gefällt mir“

Rdis scheint wiederholt zu schleifen und erreicht nie einen Zustand, in dem es auf Verbindungen wartet:

3112:M 23 Dez 2021 03:02:07.032 * 100 Änderungen in 300 Sekunden. Speichere...
3112:M 23 Dez 2021 03:02:07.033 * Hintergrundspeicherung gestartet von PID 7243
7243:C 23 Dez 2021 03:02:07.104 * DB auf Festplatte gespeichert
7243:C 23 Dez 2021 03:02:07.105 * RDB: 0 MB Speicher von Copy-on-Write verwendet
3112:M 23 Dez 2021 03:02:07.134 * Hintergrundspeicherung erfolgreich beendet
2 „Gefällt mir“

Es könnte sich lohnen, den Arbeitsspeicher zu überprüfen:

free
vmstat 5 5 
uptime

Während wir dabei sind, könnten wir auch den Festplattenspeicher überprüfen
df -h /

Und wenn Sie keinen spezifischen Rat erhalten, könnte ein weiterer Neuaufbau einen Versuch wert sein. Stellen Sie sicher, dass Sie ein Backup haben und es auch heruntergeladen haben, nur für den Fall.

Aber eigentlich fühlt es sich so an, als ob Sie spezifischeren Rat benötigen.

2 „Gefällt mir“

Hallo. Ich habe etwa eine Woche an Discourse-Backups lokal, obwohl ich im Moment nicht weiß, wie ich sie verwenden kann. Viel Speicherplatz ist frei (mindestens 1,5 GB) und Festplattenspeicher ist ebenfalls frei. Ich werde jetzt einen weiteren Neuaufbau versuchen. Danke.

1 „Gefällt mir“

Wieder aufgebaut. Unterm Strich ist es immer noch auf die gleiche Weise kaputt, obwohl es unterwegs einige Änderungen gab. Während des Builds habe ich Folgendes bemerkt:

139:C 23 Dez 2021 16:40:32.625 # oO0OoO0OoO0Oo Redis startet oO0OoO0OoO0Oo
139:C 23 Dez 2021 16:40:32.625 # Redis-Version=6.2.6, Bits=64, Commit=00000000, Geändert=0, PID=139, gerade gestartet
139:C 23 Dez 2021 16:40:32.626 # Konfiguration geladen
139:M 23 Dez 2021 16:40:32.627 * Monotonische Uhr: POSIX clock_gettime
139:M 23 Dez 2021 16:40:32.627 # Warnung: Konnte keine serverseitige TCP-Listening-Socket erstellen *:6379: bind: Adresse bereits in Verwendung
139:M 23 Dez 2021 16:40:32.628 # Fehler beim Lauschen auf Port 6379 (TCP), Abbruch.

Später habe ich Folgendes gesehen, was dem früheren Schleifen ähnelte. Es wird jedoch angegeben, dass 1 MB Speicher für Copy-on-Write verwendet wurde, und die Redis-Protokollschleife hatte 0 MB angegeben.

112:M 23 Dez 2021 16:46:08.703 * Hintergrundspeicherung gestartet von PID 715
715:C 23 Dez 2021 16:46:08.822 * DB auf Festplatte gespeichert
715:C 23 Dez 2021 16:46:08.824 * RDB: 1 MB Speicher von Copy-on-Write verwendet
112:M 23 Dez 2021 16:46:08.905 * Hintergrundspeicherung erfolgreich beendet

Das aktuelle Redis-Protokoll:

4161:M 23 Dez 2021 16:55:11.867 * Laden von RDB, erstellt von Version 6.2.6
4161:M 23 Dez 2021 16:55:11.867 * RDB-Alter 281 Sekunden
4161:M 23 Dez 2021 16:55:11.867 * RDB-Speichernutzung bei Erstellung 4,61 MB
4161:M 23 Dez 2021 16:55:12.086 # Laden von RDB abgeschlossen, geladene Schlüssel: 2743, abgelaufene Schlüssel: 0.
4161:M 23 Dez 2021 16:55:12.086 * DB von Festplatte geladen: 0,265 Sekunden
4161:M 23 Dez 2021 16:55:12.086 * Bereit, Verbindungen anzunehmen
4161:M 23 Dez 2021 17:00:12.088 * 100 Änderungen in 300 Sekunden. Speichere...
4161:M 23 Dez 2021 17:00:12.098 * Hintergrundspeicherung gestartet von PID 4612
4612:C 23 Dez 2021 17:00:12.189 * DB auf Festplatte gespeichert
4612:C 23 Dez 2021 17:00:12.191 * RDB: 0 MB Speicher von Copy-on-Write verwendet
4161:M 23 Dez 2021 17:00:12.199 * Hintergrundspeicherung erfolgreich beendet

Ich sehe wieder diese 0 MB Copy-on-Write-Meldung, aber ich weiß nicht, ob das normal ist oder nicht. Ich kann keine Telnet-Verbindung zu diesem Rechner auf localhost 6379 öffnen, ich erhalte die Fehlermeldung:
Kann keine Verbindung zum Remote-Host herstellen: Angeforderte Adresse kann nicht zugewiesen werden

Das Produktionsprotokoll zeigt wie zuvor viele Blöcke:

/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:344:in `with_reconnect'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:116:in `connect'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:417:in `ensure_connected'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:269:in `block in process'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:356:in `logging'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:268:in `process'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis/client.rb:162:in `call'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-2.3.3/lib/mini_profiler/profiling_methods.rb:85:in `block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:967:in `block in get'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:72:in `block in synchronize'
/usr/local/lib/ruby/2.7.0/monitor.rb:202:in `synchronize'
/usr/local/lib/ruby/2.7.0/monitor.rb:202:in `mon_synchronize'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:72:in `synchronize'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/redis-4.5.1/lib/redis.rb:966:in `get'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus/backends/redis.rb:366:in `process_global_backlog'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus/backends/redis.rb:274:in `block in global_subscribe'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus/backends/redis.rb:287:in `global_subscribe'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus.rb:786:in `global_subscribe_thread'
/var/www/discourse/vendor/bundle/ruby/2.7.0/gems/message_bus-3.3.8/lib/message_bus.rb:734:in `block in new_subscriber_thread'
Job-Ausnahme: Keine Adresse für meta.discourse.org (Resolv::ResolvError)
1 „Gefällt mir“

Diese Redis-Ausgabe ist normal und zeigt nicht unbedingt an, dass Redis nicht lauscht. Es handelt sich um eine Hintergrundspeicherung, die immer alle paar Minuten stattfindet. Das bedeutet nicht, dass es „schleift“ anstatt zu funktionieren. Ich denke, es ist sogar ein gutes Zeichen, dass diese Ausgabe angezeigt wird. Etwas anderes muss also falsch sein. Vielleicht ist es auf einem anderen Port, vielleicht kann es aus einem anderen Grund nicht erreicht werden.

2 „Gefällt mir“

Vielen Dank dafür. Was wären andere Möglichkeiten, dass all diese Blöcke protokolliert werden und Befehle einfach hängen bleiben?

1 „Gefällt mir“

Es scheint, dass etwas anderes bereits auf diesem Port lauscht. Erwägen Sie einen Neustart.

1 „Gefällt mir“

Um zu sehen, welcher Prozess auf einem Port lauscht, versuchen Sie
sudo lsof -n -i -P | egrep LISTEN

1 „Gefällt mir“

Ich sehe über ps, dass Redis läuft und auf 6379 lauschen möchte

/usr/bin/redis-server *:6379

aber lsof zeigt nichts an, das tatsächlich auf diesem Port lauscht.

1 „Gefällt mir“

Als Referenz, hier ist Redis, das mitten in meinem letzten Rebuild startet:

111:C 22 Dez 2021 20:36:16.773 # oO0OoO0OoO0Oo Redis startet oO0OoO0OoO0Oo
111:C 22 Dez 2021 20:36:16.773 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=111, gerade gestartet
111:C 22 Dez 2021 20:36:16.773 # Konfiguration geladen
111:M 22 Dez 2021 20:36:16.774 * Monotonische Uhr: POSIX clock_gettime
111:M 22 Dez 2021 20:36:16.775 * Ausführungsmodus=standalone, Port=6379.
111:M 22 Dez 2021 20:36:16.776 # WARNUNG: Die TCP-Backlog-Einstellung von 511 kann nicht erzwungen werden, da /proc/sys/net/core/somaxconn auf den niedrigeren Wert 128 gesetzt ist.
111:M 22 Dez 2021 20:36:16.776 # Server initialisiert
111:M 22 Dez 2021 20:36:16.777 * Laden von RDB, erstellt von Version 6.2.1
111:M 22 Dez 2021 20:36:16.777 * RDB-Alter 22 Sekunden
111:M 22 Dez 2021 20:36:16.777 * RDB-Speichernutzung bei Erstellung 19,89 MB
111:M 22 Dez 2021 20:36:16.823 # Laden von RDB abgeschlossen, Schlüssel geladen: 4451, Schlüssel abgelaufen: 9.
111:M 22 Dez 2021 20:36:16.823 * DB von Festplatte geladen: 0,047 Sekunden
111:M 22 Dez 2021 20:36:16.823 * Bereit für Verbindungsannahme

etwas später sehe ich

I, [2021-12-22T20:36:27.079511 #1]  INFO -- : cd /var/www/discourse & git reset --hard
139:C 22 Dez 2021 20:36:27.084 # oO0OoO0OoO0Oo Redis startet oO0OoO0OoO0Oo
139:C 22 Dez 2021 20:36:27.086 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=139, gerade gestartet
139:C 22 Dez 2021 20:36:27.086 # Konfiguration geladen
139:M 22 Dez 2021 20:36:27.087 * Monotonische Uhr: POSIX clock_gettime
139:M 22 Dez 2021 20:36:27.087 # Warnung: Konnte keine TCP-Server-Lausch-Socket erstellen *:6379: bind: Adresse bereits in Verwendung
139:M 22 Dez 2021 20:36:27.087 # Fehler beim Lausch auf Port 6379 (TCP), Abbruch.
Dateien auschecken: 100% (26188/26188), erledigt.
I, [2021-12-22T20:36:30.153161 #1]  INFO -- : HEAD ist jetzt bei eb82849c FIX: keine und alle Kategorienfilter (#14999)
1 „Gefällt mir“

Ja, das sieht ungefähr so aus, wie ich es heute Morgen im Build sehe. Aber auf diesem Port lauscht nichts. Es ist bizarr.

1 „Gefällt mir“

Seltsamerweise läuft mein Setup einwandfrei, ich habe

root     26269  0.0  0.0   2160     0 ?        Ss   Dec22   0:00 runsv redis
root     26277  0.0  0.0   2304    24 ?        S    Dec22   0:00 svlogd /var/log/redis
uuidd    26278  0.2  0.4  83816  4088 ?        Sl   Dec22   3:31 /usr/bin/redis-server *:6379

und doch sehe ich (von lsof, innerhalb oder außerhalb des Containers) nichts, das auf diesem Port lauscht.

1 „Gefällt mir“

Das ist irgendwie ermutigend. Und irgendwie auch nicht …

1 „Gefällt mir“

Mein Log zeigt alle 5 Minuten eine Reihe von Einträgen. Vielleicht ist das normal und Ihre Forenprobleme hängen nicht mit Redis zusammen??

$ less /var/discourse/shared/standalone/log/var-log/redis/current
23478:C 23 Dez 2021 18:47:35.233 * DB auf Festplatte gespeichert
23478:C 23 Dez 2021 18:47:35.234 * RDB: 1 MB Speicher von Copy-on-Write verwendet
52:M 23 Dez 2021 18:47:35.290 * Hintergrundspeicherung erfolgreich beendet
52:M 23 Dez 2021 18:52:36.033 * 100 Änderungen in 300 Sekunden. Speichere...
52:M 23 Dez 2021 18:52:36.034 * Hintergrundspeicherung gestartet von PID 23804
23804:C 23 Dez 2021 18:52:36.177 * DB auf Festplatte gespeichert
23804:C 23 Dez 2021 18:52:36.178 * RDB: 1 MB Speicher von Copy-on-Write verwendet
52:M 23 Dez 2021 18:52:36.235 * Hintergrundspeicherung erfolgreich beendet
52:M 23 Dez 2021 18:57:37.085 * 100 Änderungen in 300 Sekunden. Speichere...
52:M 23 Dez 2021 18:57:37.086 * Hintergrundspeicherung gestartet von PID 24137
24137:C 23 Dez 2021 18:57:37.221 * DB auf Festplatte gespeichert
24137:C 23 Dez 2021 18:57:37.222 * RDB: 1 MB Speicher von Copy-on-Write verwendet
52:M 23 Dez 2021 18:57:37.287 * Hintergrundspeicherung erfolgreich beendet
52:M 23 Dez 2021 19:02:38.033 * 100 Änderungen in 300 Sekunden. Speichere...
52:M 23 Dez 2021 19:02:38.034 * Hintergrundspeicherung gestartet von PID 24466
1 „Gefällt mir“

Danke. Das deutet jedoch darauf hin, dass ich wieder bei Null bin und ein kaputtes Forum habe … Autsch.

1 „Gefällt mir“