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 Installation	17	6981	21 de Março de 2023
Discourse failing due to expired certificates, rebuilt app, now discourse not working Installation	17	860	30 de Março de 2023
502 bad gateway with clean rebuild and no plugins except discourse docker Installation	5	371	14 de Fevereiro de 2024
Installed OK. Working fine for one day. Suddenly stopped working Installation	14	2596	20 de Junho de 2018
Redis Error after upgrade Installation	14	1595	3 de Julho de 2020

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

Tópicos relacionados