Problemi con Redis? (Forum rotto dopo l'aggiornamento)

L30110 · 23 Dicembre 2021, 1:22am

Mi è stato chiesto di aggiornare oggi, e poi mi è stato richiesto di eseguire la build tramite il launcher. Da allora Discourse è praticamente rotto. Gli utenti già autenticati possono vedere la home page e selezionare messaggi da lì per visualizzarli, ma quasi tutte le funzioni utente e admin si bloccano con il throbber che gira. Il log di produzione è vuoto. Ho provato ad arrestare e riavviare, ovviamente. Non so nemmeno da dove iniziare a cercare. Idee? Grazie!

AGGIORNAMENTO: Come indicato nelle mie varie risposte qui sotto, sembra che la radice del problema sia che rdis non accetta connessioni, e l’estratto del log di rdis qui sotto mostra rdis apparentemente in loop, ogni volta iniziando con:

100 cambiamenti in 300 secondi. Salvataggio…

e non raggiungendo mai uno stato di “in attesa di connessione”. Qualsiasi suggerimento su come risolvere questo problema sarebbe molto apprezzato. Grazie.

L30110 · 23 Dicembre 2021, 1:32am

Un log precedente mostra una varietà di blocchi, ad esempio:

/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'

L30110 · 23 Dicembre 2021, 1:59am

Il riavvio completo del sistema non ha risolto il problema. La situazione è esattamente la stessa dopo il riavvio completo.

L30110 · 23 Dicembre 2021, 2:21am

unicorn.stderr.log mostra molti errori relativi alla connessione a Redis, ad esempio:

Errore durante la segnalazione dell’errore: Errore di connessione a Redis su localhost:6379 (Errno::EADDRNOTAVAIL)

L30110 · 23 Dicembre 2021, 2:26am

Ecco il log redis corrente:

3112:C 23 Dec 2021 01:56:54.912 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
3112:C 23 Dec 2021 01:56:54.912 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=3112, just started
3112:C 23 Dec 2021 01:56:54.912 # Configuration loaded
3112:M 23 Dec 2021 01:56:54.914 * monotonic clock: POSIX clock_gettime
3112:M 23 Dec 2021 01:56:55.105 * Running mode=standalone, port=6379.
3112:M 23 Dec 2021 01:56:55.105 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
3112:M 23 Dec 2021 01:56:55.105 # Server initialized
3112:M 23 Dec 2021 01:56:55.105 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
3112:M 23 Dec 2021 01:56:55.401 * Loading RDB produced by version 6.2.6
3112:M 23 Dec 2021 01:56:55.401 * RDB age 296 seconds
3112:M 23 Dec 2021 01:56:55.401 * RDB memory usage when created 4.86 Mb
3112:M 23 Dec 2021 01:56:55.634 # Done loading RDB, keys loaded: 2751, keys expired: 2.
3112:M 23 Dec 2021 01:56:55.634 * DB loaded from disk: 0.528 seconds
3112:M 23 Dec 2021 01:56:55.634 * Ready to accept connections
3112:M 23 Dec 2021 02:01:55.037 * 100 changes in 300 seconds. Saving...
3112:M 23 Dec 2021 02:01:55.038 * Background saving started by pid 3523
3523:C 23 Dec 2021 02:01:55.140 * DB saved on disk
3523:C 23 Dec 2021 02:01:55.142 * RDB: 0 MB of memory used by copy-on-write
3112:M 23 Dec 2021 02:01:55.239 * Background saving terminated with success
3112:M 23 Dec 2021 02:06:56.065 * 100 changes in 300 seconds. Saving...
3112:M 23 Dec 2021 02:06:56.065 * Background saving started by pid 3831
3831:C 23 Dec 2021 02:06:56.134 * DB saved on disk
3831:C 23 Dec 2021 02:06:56.136 * RDB: 0 MB of memory used by copy-on-write
3112:M 23 Dec 2021 02:06:56.166 * Background saving terminated with success
3112:M 23 Dec 2021 02:11:57.071 * 100 changes in 300 seconds. Saving...
3112:M 23 Dec 2021 02:11:57.071 * Background saving started by pid 4138
4138:C 23 Dec 2021 02:11:57.135 * DB saved on disk
4138:C 23 Dec 2021 02:11:57.137 * RDB: 0 MB of memory used by copy-on-write
3112:M 23 Dec 2021 02:11:57.172 * Background saving terminated with success
3112:M 23 Dec 2021 02:16:58.000 * 100 changes in 300 seconds. Saving...
3112:M 23 Dec 2021 02:16:58.001 * Background saving started by pid 4448
4448:C 23 Dec 2021 02:16:58.064 * DB saved on disk
4448:C 23 Dec 2021 02:16:58.066 * RDB: 0 MB of memory used by copy-on-write
3112:M 23 Dec 2021 02:16:58.101 * Background saving terminated with success

L30110 · 23 Dicembre 2021, 3:02am

Rdis sembra essere in un loop ripetuto con questo e non raggiunge mai uno stato in cui è in attesa di connessioni:

3112:M 23 Dec 2021 03:02:07.032 * 100 changes in 300 seconds. Saving...
3112:M 23 Dec 2021 03:02:07.033 * Background saving started by pid 7243
7243:C 23 Dec 2021 03:02:07.104 * DB saved on disk
7243:C 23 Dec 2021 03:02:07.105 * RDB: 0 MB of memory used by copy-on-write
3112:M 23 Dec 2021 03:02:07.134 * Background saving terminated with success

Ed_S · 23 Dicembre 2021, 9:03am

Potrebbe valere la pena controllare la memoria:

free
vmstat 5 5 
uptime

Già che ci siamo, forse controlliamo anche lo spazio su disco
df -h /

E, se non ricevi consigli specifici, un’altra ricompilazione potrebbe valere la pena. Assicurati di avere un backup, e di averlo anche scaricato, per sicurezza.

Ma in realtà sembra che tu abbia bisogno di consigli più specifici.

L30110 · 23 Dicembre 2021, 4:37pm

Ciao. Ho circa una settimana di backup di Discourse localmente, anche se a questo punto non so come usarli. Ho molta memoria libera (almeno 1,5 G) e disco libero. Riproverò un’altra ricostruzione ora. Grazie.

L30110 · 23 Dicembre 2021, 5:10pm

Ricostruito. In sintesi, è ancora rotto nello stesso modo, anche se ho notato alcuni cambiamenti lungo il percorso. Durante la compilazione ho notato:

139:C 23 Dec 2021 16:40:32.625 # oO0OoO0OoO0Oo Redis si sta avviando oO0OoO0OoO0Oo
139:C 23 Dec 2021 16:40:32.625 # Versione Redis=6.2.6, bit=64, commit=00000000, modificato=0, pid=139, appena avviato
139:C 23 Dec 2021 16:40:32.626 # Configurazione caricata
139:M 23 Dec 2021 16:40:32.627 * Clock monotono: POSIX clock_gettime
139:M 23 Dec 2021 16:40:32.627 # Avviso: Impossibile creare il socket TCP del server *:6379: bind: Indirizzo già in uso
139:M 23 Dec 2021 16:40:32.628 # Impossibile ascoltare sulla porta 6379 (TCP), interruzione.

Più tardi ho visto questo, che era simile al loop che avevo visto in precedenza. Tuttavia, dice che ha utilizzato 1 MB di memoria per la copia in scrittura, mentre il log di Redis in loop diceva 0 MB.

112:M 23 Dec 2021 16:46:08.703 * Salvataggio in background avviato dal pid 715
715:C 23 Dec 2021 16:46:08.822 * DB salvato su disco
715:C 23 Dec 2021 16:46:08.824 * RDB: 1 MB di memoria utilizzata dalla copia in scrittura
112:M 23 Dec 2021 16:46:08.905 * Salvataggio in background terminato con successo

Il log di Redis corrente:

4161:M 23 Dec 2021 16:55:11.867 * Caricamento RDB prodotto dalla versione 6.2.6
4161:M 23 Dec 2021 16:55:11.867 * Età RDB 281 secondi
4161:M 23 Dec 2021 16:55:11.867 * Utilizzo memoria RDB al momento della creazione 4.61 Mb
4161:M 23 Dec 2021 16:55:12.086 # Caricamento RDB completato, chiavi caricate: 2743, chiavi scadute: 0.
4161:M 23 Dec 2021 16:55:12.086 * DB caricato dal disco: 0.265 secondi
4161:M 23 Dec 2021 16:55:12.086 * Pronto per accettare connessioni
4161:M 23 Dec 2021 17:00:12.088 * 100 modifiche in 300 secondi. Salvataggio...
4161:M 23 Dec 2021 17:00:12.098 * Salvataggio in background avviato dal pid 4612
4612:C 23 Dec 2021 17:00:12.189 * DB salvato su disco
4612:C 23 Dec 2021 17:00:12.191 * RDB: 0 MB di memoria utilizzata dalla copia in scrittura
4161:M 23 Dec 2021 17:00:12.199 * Salvataggio in background terminato con successo

Vedo di nuovo quell’avviso di copia in scrittura da 0 MB, ma non so se sia normale o meno. Non riesco ad aprire una connessione telnet su quella macchina a localhost 6379, ottengo l’errore:
Impossibile connettersi all’host remoto: Impossibile assegnare l’indirizzo richiesto

Il log di produzione mostra molti blocchi come prima:

/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'
Eccezione del job: nessun indirizzo per meta.discourse.org (Resolv::ResolvError)

michaeld · 23 Dicembre 2021, 5:46pm

Quell’output di redis è normale e non indica necessariamente che Redis non sia in ascolto. È un salvataggio in background che si verifica sempre ogni tot minuti. Non significa che stia “andando in loop” invece di funzionare. Penso che sia in realtà un buon segno che mostri questo output. Quindi qualcos’altro deve essere sbagliato. Forse è su una porta diversa, forse non è raggiungibile per qualche altro motivo.

L30110 · 23 Dicembre 2021, 5:50pm

La ringrazio molto. Quali sarebbero altre possibilità per tutti questi blocchi registrati e comandi in sospeso?

michaeld · 23 Dicembre 2021, 5:51pm

L30110:

139:M 23 Dec 2021 16:40:32.627 # Impossibile creare il socket TCP di ascolto del server *:6379: bind: Address already in use
139:M 23 Dec 2021 16:40:32.628 # Impossibile ascoltare sulla porta 6379 (TCP), interruzione.

Sembra che qualcos’altro sia già in ascolto su quella porta. Considera un riavvio.

Ed_S · 23 Dicembre 2021, 6:03pm

Per vedere quale processo è in ascolto su una porta, prova
sudo lsof -n -i -P | egrep LISTEN

L30110 · 23 Dicembre 2021, 6:30pm

Da ps vedo che redis è in esecuzione e vuole ascoltare sulla porta 6379

/usr/bin/redis-server *:6379

ma lsof non mostra nulla in ascolto su quella porta.

Ed_S · 23 Dicembre 2021, 6:32pm

Per riferimento, questo è redis che si avvia nel mezzo della mia ultima ricostruzione:

111:C 22 Dec 2021 20:36:16.773 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
111:C 22 Dec 2021 20:36:16.773 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=111, just started
111:C 22 Dec 2021 20:36:16.773 # Configuration loaded
111:M 22 Dec 2021 20:36:16.774 * monotonic clock: POSIX clock_gettime
111:M 22 Dec 2021 20:36:16.775 * Running mode=standalone, port=6379.
111:M 22 Dec 2021 20:36:16.776 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
111:M 22 Dec 2021 20:36:16.776 # Server initialized
111:M 22 Dec 2021 20:36:16.777 * Loading RDB produced by version 6.2.1
111:M 22 Dec 2021 20:36:16.777 * RDB age 22 seconds
111:M 22 Dec 2021 20:36:16.777 * RDB memory usage when created 19.89 Mb
111:M 22 Dec 2021 20:36:16.823 # Done loading RDB, keys loaded: 4451, keys expired: 9.
111:M 22 Dec 2021 20:36:16.823 * DB loaded from disk: 0.047 seconds
111:M 22 Dec 2021 20:36:16.823 * Ready to accept connections

poco después veo

I, [2021-12-22T20:36:27.079511 #1]  INFO -- : cd /var/www/discourse & git reset --hard
139:C 22 Dec 2021 20:36:27.084 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
139:C 22 Dec 2021 20:36:27.086 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=139, just started
139:C 22 Dec 2021 20:36:27.086 # Configuration loaded
139:M 22 Dec 2021 20:36:27.087 * monotonic clock: POSIX clock_gettime
139:M 22 Dec 2021 20:36:27.087 # Warning: Could not create server TCP listening socket *:6379: bind: Address already in use
139:M 22 Dec 2021 20:36:27.087 # Failed listening on port 6379 (TCP), aborting.
Checking out files: 100% (26188/26188), done.
I, [2021-12-22T20:36:30.153161 #1]  INFO -- : HEAD is now at eb82849c FIX: none and all categories filter (#14999)

L30110 · 23 Dicembre 2021, 6:33pm

Sì, sembra proprio quello che vedo dalla build di stamattina. Ma in realtà nessuno sta ascoltando su quella porta. È bizzarro.

Ed_S · 23 Dicembre 2021, 6:37pm

Stranamente, la mia configurazione funziona correttamente, ho

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

eppure anch’io non vedo (da lsof, all’interno o all’esterno del container) nulla in ascolto su quella porta.

L30110 · 23 Dicembre 2021, 6:50pm

È incoraggiante. E in un certo senso no…

Ed_S · 23 Dicembre 2021, 7:17pm

Il mio log mostra un gruppo di voci ogni 5 minuti. Forse è normale e i problemi del tuo forum non sono correlati a redis??

$ less /var/discourse/shared/standalone/log/var-log/redis/current
23478:C 23 Dec 2021 18:47:35.233 * DB salvato su disco
23478:C 23 Dec 2021 18:47:35.234 * RDB: 1 MB di memoria utilizzata da copy-on-write
52:M 23 Dec 2021 18:47:35.290 * Salvataggio in background terminato con successo
52:M 23 Dec 2021 18:52:36.033 * 100 modifiche in 300 secondi. Salvataggio in corso...
52:M 23 Dec 2021 18:52:36.034 * Salvataggio in background avviato dal processo 23804
23804:C 23 Dec 2021 18:52:36.177 * DB salvato su disco
23804:C 23 Dec 2021 18:52:36.178 * RDB: 1 MB di memoria utilizzata da copy-on-write
52:M 23 Dec 2021 18:52:36.235 * Salvataggio in background terminato con successo
52:M 23 Dec 2021 18:57:37.085 * 100 modifiche in 300 secondi. Salvataggio in corso...
52:M 23 Dec 2021 18:57:37.086 * Salvataggio in background avviato dal processo 24137
24137:C 23 Dec 2021 18:57:37.221 * DB salvato su disco
24137:C 23 Dec 2021 18:57:37.222 * RDB: 1 MB di memoria utilizzata da copy-on-write
52:M 23 Dec 2021 18:57:37.287 * Salvataggio in background terminato con successo
52:M 23 Dec 2021 19:02:38.033 * 100 modifiche in 300 secondi. Salvataggio in corso...
52:M 23 Dec 2021 19:02:38.034 * Salvataggio in background avviato dal processo 24466

L30110 · 23 Dicembre 2021, 7:45pm

Grazie. Anche se questo suggerisce che sono tornato al punto di partenza con un forum rotto… Ahi.

Argomento		Risposte	Visualizzazioni
Error connecting to Redis Installation	17	6975	Marzo 21, 2023
Discourse failing due to expired certificates, rebuilt app, now discourse not working Installation	17	859	Marzo 30, 2023
502 bad gateway with clean rebuild and no plugins except discourse docker Installation	5	371	Febbraio 14, 2024
Installed OK. Working fine for one day. Suddenly stopped working Installation	14	2596	Giugno 20, 2018
Redis Error after upgrade Installation	14	1587	Luglio 3, 2020

Problemi con Redis? (Forum rotto dopo l'aggiornamento)

Argomenti correlati