Problemas com Redis? (Fórum quebrado após atualização)

L30110 · Dezembro 23, 2021, 1:22am

Fui solicitado a atualizar hoje e, em seguida, fui obrigado a fazer a compilação através do launcher. Desde então, o Discourse está basicamente quebrado. Usuários já logados podem ver a página inicial e selecionar mensagens de lá para exibir, mas praticamente todas as funções de usuário e administrador simplesmente travam com o throbber girando. O log de produção está vazio. Já tentei parar e reiniciar, é claro. Nem sei por onde começar a procurar. Ideias? Obrigado!

ATUALIZAÇÃO: Conforme indicado nas minhas várias respostas abaixo, parece que a raiz do problema é que o rdis não está aceitando conexões, e o extrato do log do rdis abaixo mostra o rdis aparentemente em loop, cada vez começando com:

100 mudanças em 300 segundos. Salvando…

e nunca atingindo um estado de “aguardando conexão”. Quaisquer sugestões sobre como corrigir esse problema seriam muito apreciadas. Obrigado.

L30110 · Dezembro 23, 2021, 1:32am

Um log anterior mostra uma variedade de blocos, por exemplo:

/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 · Dezembro 23, 2021, 1:59am

A reinicialização completa do sistema não resolveu o problema. A situação é exatamente a mesma após a reinicialização completa.

L30110 · Dezembro 23, 2021, 2:21am

unicorn.stderr.log mostra muitos erros relacionados à conexão com o Redis, por exemplo:

Falha ao relatar erro: Erro ao conectar ao Redis em localhost:6379 (Errno::EADDRNOTAVAIL)

L30110 · Dezembro 23, 2021, 2:26am

Aqui está o log atual do redis:

3112:C 23 Dez 2021 01:56:54.912 # oO0OoO0OoO0Oo Redis está iniciando oO0OoO0OoO0Oo
3112:C 23 Dez 2021 01:56:54.912 # Versão do Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=3112, recém-iniciado
3112:C 23 Dez 2021 01:56:54.912 # Configuração carregada
3112:M 23 Dez 2021 01:56:54.914 * Relógio monotônico: POSIX clock_gettime
3112:M 23 Dez 2021 01:56:55.105 * Modo de execução=standalone, porta=6379.
3112:M 23 Dez 2021 01:56:55.105 # AVISO: A configuração de backlog TCP de 511 não pode ser aplicada porque /proc/sys/net/core/somaxconn está definido para o valor inferior de 128.
3112:M 23 Dez 2021 01:56:55.105 # Servidor inicializado
3112:M 23 Dez 2021 01:56:55.105 # AVISO overcommit_memory está definido como 0! Salvamento em segundo plano pode falhar sob condição de pouca memória. Para corrigir este problema, adicione 'vm.overcommit_memory = 1' a /etc/sysctl.conf e, em seguida, reinicie ou execute o comando 'sysctl vm.overcommit_memory=1' para que isso tenha efeito.
3112:M 23 Dez 2021 01:56:55.401 * Carregando RDB produzido pela versão 6.2.6
3112:M 23 Dez 2021 01:56:55.401 * Idade do RDB 296 segundos
3112:M 23 Dez 2021 01:56:55.401 * Uso de memória do RDB quando criado 4.86 Mb
3112:M 23 Dez 2021 01:56:55.634 # Concluído o carregamento do RDB, chaves carregadas: 2751, chaves expiradas: 2.
3112:M 23 Dez 2021 01:56:55.634 * DB carregado do disco: 0.528 segundos
3112:M 23 Dez 2021 01:56:55.634 * Pronto para aceitar conexões
3112:M 23 Dez 2021 02:01:55.037 * 100 alterações em 300 segundos. Salvando...
3112:M 23 Dez 2021 02:01:55.038 * Salvamento em segundo plano iniciado pelo pid 3523
3523:C 23 Dez 2021 02:01:55.140 * DB salvo em disco
3523:C 23 Dez 2021 02:01:55.142 * RDB: 0 MB de memória usada por cópia em gravação
3112:M 23 Dez 2021 02:01:55.239 * Salvamento em segundo plano encerrado com sucesso
3112:M 23 Dez 2021 02:06:56.065 * 100 alterações em 300 segundos. Salvando...
3112:M 23 Dez 2021 02:06:56.065 * Salvamento em segundo plano iniciado pelo pid 3831
3831:C 23 Dez 2021 02:06:56.134 * DB salvo em disco
3831:C 23 Dez 2021 02:06:56.136 * RDB: 0 MB de memória usada por cópia em gravação
3112:M 23 Dez 2021 02:06:56.166 * Salvamento em segundo plano encerrado com sucesso
3112:M 23 Dez 2021 02:11:57.071 * 100 alterações em 300 segundos. Salvando...
3112:M 23 Dez 2021 02:11:57.071 * Salvamento em segundo plano iniciado pelo pid 4138
4138:C 23 Dez 2021 02:11:57.135 * DB salvo em disco
4138:C 23 Dez 2021 02:11:57.137 * RDB: 0 MB de memória usada por cópia em gravação
3112:M 23 Dez 2021 02:11:57.172 * Salvamento em segundo plano encerrado com sucesso
3112:M 23 Dez 2021 02:16:58.000 * 100 alterações em 300 segundos. Salvando...
3112:M 23 Dez 2021 02:16:58.001 * Salvamento em segundo plano iniciado pelo pid 4448
4448:C 23 Dez 2021 02:16:58.064 * DB salvo em disco
4448:C 23 Dez 2021 02:16:58.066 * RDB: 0 MB de memória usada por cópia em gravação
3112:M 23 Dez 2021 02:16:58.101 * Salvamento em segundo plano encerrado com sucesso

L30110 · Dezembro 23, 2021, 3:02am

O Rdis parece estar em loop repetidamente com isso e nunca atinge um estado onde está aguardando conexões:

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 · Dezembro 23, 2021, 9:03am

Pode valer a pena verificar a memória:

free
vmstat 5 5 
uptime

Enquanto estamos nisso, talvez também verificar o espaço em disco
df -h /

E, se você não receber nenhum conselho específico, outra reconstrução pode valer a pena. Certifique-se de ter um backup e de tê-lo baixado também, por precaução.

Mas realmente parece que você precisa de conselhos mais específicos.

L30110 · Dezembro 23, 2021, 4:37pm

Olá. Tenho cerca de uma semana de backups do Discourse localmente, embora neste momento eu não saiba como usá-los. Muita memória livre (pelo menos 1,5G) e disco livre. Tentarei outra reconstrução agora. Obrigado.

L30110 · Dezembro 23, 2021, 5:10pm

Reconstruído. Em resumo, ainda está quebrado da mesma forma, embora tenha havido algumas mudanças que notei ao longo do caminho. Durante a compilação, observei:

139:C 23 Dez 2021 16:40:32.625 # oO0OoO0OoO0Oo Redis está iniciando oO0OoO0OoO0Oo
139:C 23 Dez 2021 16:40:32.625 # Versão do Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=139, recém-iniciado
139:C 23 Dez 2021 16:40:32.626 # Configuração carregada
139:M 23 Dez 2021 16:40:32.627 * Relógio monotônico: POSIX clock_gettime
139:M 23 Dez 2021 16:40:32.627 # Aviso: Não foi possível criar o socket TCP do servidor escutando *:6379: bind: Endereço já em uso
139:M 23 Dez 2021 16:40:32.628 # Falha ao escutar na porta 6379 (TCP), abortando.

Mais tarde, vi isso, que era semelhante ao loop que vi anteriormente. No entanto, diz que usou 1 MB de memória para cópia em gravação, e o loop do log do redis dizia 0 MB.

112:M 23 Dez 2021 16:46:08.703 * Salvamento em segundo plano iniciado pelo pid 715
715:C 23 Dez 2021 16:46:08.822 * DB salvo em disco
715:C 23 Dez 2021 16:46:08.824 * RDB: 1 MB de memória usado por cópia em gravação
112:M 23 Dez 2021 16:46:08.905 * Salvamento em segundo plano encerrado com sucesso

O log atual do redis:

4161:M 23 Dez 2021 16:55:11.867 * Carregando RDB produzido pela versão 6.2.6
4161:M 23 Dez 2021 16:55:11.867 * Idade do RDB 281 segundos
4161:M 23 Dez 2021 16:55:11.867 * Uso de memória do RDB quando criado 4.61 Mb
4161:M 23 Dez 2021 16:55:12.086 # RDB carregado, chaves carregadas: 2743, chaves expiradas: 0.
4161:M 23 Dez 2021 16:55:12.086 * DB carregado do disco: 0.265 segundos
4161:M 23 Dez 2021 16:55:12.086 * Pronto para aceitar conexões
4161:M 23 Dez 2021 17:00:12.088 * 100 alterações em 300 segundos. Salvando...
4161:M 23 Dez 2021 17:00:12.098 * Salvamento em segundo plano iniciado pelo pid 4612
4612:C 23 Dez 2021 17:00:12.189 * DB salvo em disco
4612:C 23 Dez 2021 17:00:12.191 * RDB: 0 MB de memória usado por cópia em gravação
4161:M 23 Dez 2021 17:00:12.199 * Salvamento em segundo plano encerrado com sucesso

Estou vendo novamente esse aviso de cópia em gravação de 0 MB, mas não sei se isso é normal ou não. Não consigo abrir uma conexão telnet nessa máquina para localhost 6379, recebo o erro:
Impossível conectar ao host remoto: Não é possível atribuir o endereço solicitado

O log de produção mostra muitos blocos como antes:

/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'
Exceção do trabalho: nenhum endereço para meta.discourse.org (Resolv::ResolvError)

michaeld · Dezembro 23, 2021, 5:46pm

Essa saída do Redis é normal e não indica necessariamente que o Redis não está escutando. É um salvamento em segundo plano que sempre ocorre a cada poucos minutos. Não significa que está “em loop” em vez de funcionar. Acho que é um bom sinal que ele esteja mostrando essa saída. Portanto, algo mais deve estar errado. Talvez esteja em uma porta diferente, talvez não possa ser alcançado por algum outro motivo.

L30110 · Dezembro 23, 2021, 5:50pm

Muito obrigado por isso. Quais seriam outras possibilidades para todos esses blocos estarem sendo registrados e os comandos ficarem pendentes?

michaeld · Dezembro 23, 2021, 5:51pm

L30110:

139:M 23 Dec 2021 16:40:32.627 # Warning: Could not create server TCP listening socket *:6379: bind: Address already in use
139:M 23 Dec 2021 16:40:32.628 # Failed listening on port 6379 (TCP), aborting.

Parece que outra coisa já está escutando nessa porta. Considere reiniciar.

Ed_S · Dezembro 23, 2021, 6:03pm

Para ver qual processo está escutando em uma porta, tente
sudo lsof -n -i -P | egrep LISTEN

L30110 · Dezembro 23, 2021, 6:30pm

Consigo ver pelo ps que o redis está em execução e quer escutar na porta 6379

/usr/bin/redis-server *:6379

mas o lsof não mostra nada realmente escutando nessa porta.

Ed_S · Dezembro 23, 2021, 6:32pm

Para referência, este é o redis iniciando no meio da minha reconstrução mais recente:

111:C 22 Dec 2021 20:36:16.773 # oO0OoO0OoO0Oo Redis está iniciando oO0OoO0OoO0Oo
111:C 22 Dec 2021 20:36:16.773 # Versão do Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=111, recém-iniciado
111:C 22 Dec 2021 20:36:16.773 # Configuração carregada
111:M 22 Dec 2021 20:36:16.774 * Relógio monotônico: POSIX clock_gettime
111:M 22 Dec 2021 20:36:16.775 * Modo de execução=standalone, porta=6379.
111:M 22 Dec 2021 20:36:16.776 # AVISO: A configuração de backlog TCP de 511 não pode ser imposta porque /proc/sys/net/core/somaxconn está definido para o valor inferior de 128.
111:M 22 Dec 2021 20:36:16.776 # Servidor inicializado
111:M 22 Dec 2021 20:36:16.777 * Carregando RDB produzido pela versão 6.2.1
111:M 22 Dec 2021 20:36:16.777 * Idade do RDB 22 segundos
111:M 22 Dec 2021 20:36:16.777 * Uso de memória do RDB quando criado 19.89 Mb
111:M 22 Dec 2021 20:36:16.823 # Concluído o carregamento do RDB, chaves carregadas: 4451, chaves expiradas: 9.
111:M 22 Dec 2021 20:36:16.823 * DB carregado do disco: 0.047 segundos
111:M 22 Dec 2021 20:36:16.823 * Pronto para aceitar conexões

um pouco mais tarde, vejo

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 está iniciando oO0OoO0OoO0Oo
139:C 22 Dec 2021 20:36:27.086 # Versão do Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=139, recém-iniciado
139:C 22 Dec 2021 20:36:27.086 # Configuração carregada
139:M 22 Dec 2021 20:36:27.087 * Relógio monotônico: POSIX clock_gettime
139:M 22 Dec 2021 20:36:27.087 # Aviso: Não foi possível criar o socket de escuta TCP do servidor *:6379: bind: Endereço já em uso
139:M 22 Dec 2021 20:36:27.087 # Falha ao escutar na porta 6379 (TCP), abortando.
Verificando arquivos: 100% (26188/26188), concluído.
I, [2021-12-22T20:36:30.153161 #1]  INFO -- : HEAD agora está em eb82849c FIX: filtro de todas as categorias e nenhum (#14999)

L30110 · Dezembro 23, 2021, 6:33pm

Sim, isso parece com o que vejo da compilação desta manhã. Mas nada está realmente escutando nessa porta. É bizarro.

Ed_S · Dezembro 23, 2021, 6:37pm

Estranhamente, minha configuração está funcionando bem, eu tenho

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

e ainda assim eu também não vejo (do lsof, dentro ou fora do contêiner) nada escutando nessa porta.

L30110 · Dezembro 23, 2021, 6:50pm

Isso é meio encorajador. E meio que não…

Ed_S · Dezembro 23, 2021, 7:17pm

Meu log mostra um monte de entradas a cada 5 minutos. Talvez isso seja normal e seus problemas no fórum não estejam relacionados ao redis??

$ less /var/discourse/shared/standalone/log/var-log/redis/current
23478:C 23 Dec 2021 18:47:35.233 * DB salvo em disco
23478:C 23 Dec 2021 18:47:35.234 * RDB: 1 MB de memória usada por cópia em gravação
52:M 23 Dec 2021 18:47:35.290 * Salvamento em segundo plano encerrado com sucesso
52:M 23 Dec 2021 18:52:36.033 * 100 alterações em 300 segundos. Salvando...
52:M 23 Dec 2021 18:52:36.034 * Salvamento em segundo plano iniciado pelo pid 23804
23804:C 23 Dec 2021 18:52:36.177 * DB salvo em disco
23804:C 23 Dec 2021 18:52:36.178 * RDB: 1 MB de memória usada por cópia em gravação
52:M 23 Dec 2021 18:52:36.235 * Salvamento em segundo plano encerrado com sucesso
52:M 23 Dec 2021 18:57:37.085 * 100 alterações em 300 segundos. Salvando...
52:M 23 Dec 2021 18:57:37.086 * Salvamento em segundo plano iniciado pelo pid 24137
24137:C 23 Dec 2021 18:57:37.221 * DB salvo em disco
24137:C 23 Dec 2021 18:57:37.222 * RDB: 1 MB de memória usada por cópia em gravação
52:M 23 Dec 2021 18:57:37.287 * Salvamento em segundo plano encerrado com sucesso
52:M 23 Dec 2021 19:02:38.033 * 100 alterações em 300 segundos. Salvando...
52:M 23 Dec 2021 19:02:38.034 * Salvamento em segundo plano iniciado pelo pid 24466

L30110 · Dezembro 23, 2021, 7:45pm

Obrigado. Embora isso sugira que estou de volta ao zero com um fórum quebrado… Ai.

Tópico		Respostas	Visualizações
Error connecting to Redis Self-hosting	17	7111	21 de Março de 2023
Discourse failing due to expired certificates, rebuilt app, now discourse not working Self-hosting	17	948	30 de Março de 2023
502 bad gateway with clean rebuild and no plugins except discourse docker Self-hosting	5	425	14 de Fevereiro de 2024
Installed OK. Working fine for one day. Suddenly stopped working Self-hosting	14	2680	20 de Junho de 2018
Redis Error after upgrade Self-hosting	14	1700	3 de Julho de 2020

Problemas com Redis? (Fórum quebrado após atualização)

Tópicos relacionados