¿Problemas con Redis? (Foro roto después de la actualización)

L30110 · 23 Diciembre, 2021 01:22

Se me solicitó actualizar hoy y luego se me exigió realizar la compilación a través del lanzador. Desde entonces, Discourse se ha roto básicamente. Los usuarios que ya han iniciado sesión pueden ver la página de inicio y seleccionar mensajes desde allí para mostrarlos, pero prácticamente todas las funciones, tanto de usuario como de administrador, se cuelgan con el indicador de progreso girando. El registro de producción está vacío. He intentado detener y reiniciar, por supuesto. Ni siquiera estoy seguro por dónde empezar a buscar. ¿Ideas? ¡Gracias!

ACTUALIZACIÓN: Como se indica en mis diversas respuestas a continuación, parece que la raíz del problema es que rdis no está aceptando conexiones, y el extracto del registro de rdis a continuación muestra que rdis aparentemente está en un bucle, comenzando cada vez con:

100 cambios en 300 segundos. Guardando…

y nunca llega a un estado de “esperando conexión”. Cualquier sugerencia sobre cómo solucionar este problema sería muy apreciada. Gracias.

L30110 · 23 Diciembre, 2021 01:32

Un registro anterior muestra una variedad de bloques, por ejemplo:

/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 Diciembre, 2021 01:59

El reinicio completo del sistema no resolvió el problema. La situación es exactamente la misma después del reinicio completo.

L30110 · 23 Diciembre, 2021 02:21

unicorn.stderr.log muestra muchos errores relacionados con la conexión a Redis, por ejemplo:

Error al informar error: Error al conectar a Redis en localhost:6379 (Errno::EADDRNOTAVAIL)

L30110 · 23 Diciembre, 2021 02:26

Aquí está el registro actual de redis:

3112:C 23 Dec 2021 01:56:54.912 # oO0OoO0OoO0Oo Redis está iniciando oO0OoO0OoO0Oo
3112:C 23 Dec 2021 01:56:54.912 # Versión de Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=3112, recién iniciado
3112:C 23 Dec 2021 01:56:54.912 # Configuración cargada
3112:M 23 Dec 2021 01:56:54.914 * Reloj monotónico: POSIX clock_gettime
3112:M 23 Dec 2021 01:56:55.105 * Modo de ejecución=standalone, puerto=6379.
3112:M 23 Dec 2021 01:56:55.105 # ADVERTENCIA: La configuración del backlog TCP de 511 no se puede aplicar porque /proc/sys/net/core/somaxconn está establecido en el valor inferior de 128.
3112:M 23 Dec 2021 01:56:55.105 # Servidor inicializado
3112:M 23 Dec 2021 01:56:55.105 # ADVERTENCIA overcommit_memory está establecido en 0. El guardado en segundo plano puede fallar en condiciones de poca memoria. Para solucionar este problema, agregue 'vm.overcommit_memory = 1' a /etc/sysctl.conf y luego reinicie o ejecute el comando 'sysctl vm.overcommit_memory=1' para que esto tenga efecto.
3112:M 23 Dec 2021 01:56:55.401 * Cargando RDB producido por la versión 6.2.6
3112:M 23 Dec 2021 01:56:55.401 * Edad del RDB 296 segundos
3112:M 23 Dec 2021 01:56:55.401 * Uso de memoria del RDB cuando se creó 4.86 Mb
3112:M 23 Dec 2021 01:56:55.634 # Carga del RDB completada, claves cargadas: 2751, claves expiradas: 2.
3112:M 23 Dec 2021 01:56:55.634 * DB cargada desde disco: 0.528 segundos
3112:M 23 Dec 2021 01:56:55.634 * Listo para aceptar conexiones
3112:M 23 Dec 2021 02:01:55.037 * 100 cambios en 300 segundos. Guardando...
3112:M 23 Dec 2021 02:01:55.038 * Guardado en segundo plano iniciado por el pid 3523
3523:C 23 Dec 2021 02:01:55.140 * DB guardada en disco
3523:C 23 Dec 2021 02:01:55.142 * RDB: 0 MB de memoria utilizada por copy-on-write
3112:M 23 Dec 2021 02:01:55.239 * Guardado en segundo plano terminado con éxito
3112:M 23 Dec 2021 02:06:56.065 * 100 cambios en 300 segundos. Guardando...
3112:M 23 Dec 2021 02:06:56.065 * Guardado en segundo plano iniciado por el pid 3831
3831:C 23 Dec 2021 02:06:56.134 * DB guardada en disco
3831:C 23 Dec 2021 02:06:56.136 * RDB: 0 MB de memoria utilizada por copy-on-write
3112:M 23 Dec 2021 02:06:56.166 * Guardado en segundo plano terminado con éxito
3112:M 23 Dec 2021 02:11:57.071 * 100 cambios en 300 segundos. Guardando...
3112:M 23 Dec 2021 02:11:57.071 * Guardado en segundo plano iniciado por el pid 4138
4138:C 23 Dec 2021 02:11:57.135 * DB guardada en disco
4138:C 23 Dec 2021 02:11:57.137 * RDB: 0 MB de memoria utilizada por copy-on-write
3112:M 23 Dec 2021 02:11:57.172 * Guardado en segundo plano terminado con éxito
3112:M 23 Dec 2021 02:16:58.000 * 100 cambios en 300 segundos. Guardando...
3112:M 23 Dec 2021 02:16:58.001 * Guardado en segundo plano iniciado por el pid 4448
4448:C 23 Dec 2021 02:16:58.064 * DB guardada en disco
4448:C 23 Dec 2021 02:16:58.066 * RDB: 0 MB de memoria utilizada por copy-on-write
3112:M 23 Dec 2021 02:16:58.101 * Guardado en segundo plano terminado con éxito

L30110 · 23 Diciembre, 2021 03:02

Rdis parece estar en un bucle repetido con esto y nunca llega a un estado en el que esté esperando conexiones:

3112:M 23 Dec 2021 03:02:07.032 * 100 cambios en 300 segundos. Guardando...
3112:M 23 Dec 2021 03:02:07.033 * Guardado en segundo plano iniciado por el proceso 7243
7243:C 23 Dec 2021 03:02:07.104 * DB guardado en disco
7243:C 23 Dec 2021 03:02:07.105 * RDB: 0 MB de memoria utilizada por copia en escritura
3112:M 23 Dec 2021 03:02:07.134 * Guardado en segundo plano finalizado con éxito

Ed_S · 23 Diciembre, 2021 09:03

Podría valer la pena revisar la memoria:

free
vmstat 5 5 
uptime

Ya que estamos, quizás también revisar el espacio en disco
df -h /

Y, si no recibe ningún consejo específico, otra reconstrucción podría valer la pena. Asegúrese de tener una copia de seguridad y de tenerla descargada también, por si acaso.

Pero realmente parece que necesita un consejo más específico.

L30110 · 23 Diciembre, 2021 16:37

Hola. Tengo copias de seguridad de Discourse de aproximadamente una semana localmente, aunque en este momento no sé cómo usarlas. Tengo mucha memoria libre (al menos 1.5G) y disco libre. Intentaré reconstruir de nuevo ahora. Gracias.

L30110 · 23 Diciembre, 2021 17:10

Reconstruido. En resumen, sigue roto de la misma manera, aunque hubo algunos cambios que vi en el camino. Durante la compilación noté:

139:C 23 Dec 2021 16:40:32.625 # oO0OoO0OoO0Oo Redis está iniciando oO0OoO0OoO0Oo
139:C 23 Dec 2021 16:40:32.625 # Versión de Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=139, recién iniciado
139:C 23 Dec 2021 16:40:32.626 # Configuración cargada
139:M 23 Dec 2021 16:40:32.627 * Reloj monotónico: POSIX clock_gettime
139:M 23 Dec 2021 16:40:32.627 # Advertencia: No se pudo crear el socket TCP de escucha del servidor *:6379: bind: Dirección ya en uso
139:M 23 Dec 2021 16:40:32.628 # Falló la escucha en el puerto 6379 (TCP), abortando.

Más tarde vi esto, que era similar al bucle que vi antes. Sin embargo, dice que usó 1 MB de memoria para copy-on-write, y el bucle del registro de Redis decía 0 MB.

112:M 23 Dec 2021 16:46:08.703 * Guardado en segundo plano iniciado por el pid 715
715:C 23 Dec 2021 16:46:08.822 * DB guardado en disco
715:C 23 Dec 2021 16:46:08.824 * RDB: 1 MB de memoria utilizada por copy-on-write
112:M 23 Dec 2021 16:46:08.905 * Guardado en segundo plano finalizado con éxito

El registro actual de Redis:

4161:M 23 Dec 2021 16:55:11.867 * Carga de RDB producida por la versión 6.2.6
4161:M 23 Dec 2021 16:55:11.867 * Edad de RDB 281 segundos
4161:M 23 Dec 2021 16:55:11.867 * Uso de memoria RDB al crearse 4.61 MB
4161:M 23 Dec 2021 16:55:12.086 # Carga de RDB completada, claves cargadas: 2743, claves expiradas: 0.
4161:M 23 Dec 2021 16:55:12.086 * DB cargado desde disco: 0.265 segundos
4161:M 23 Dec 2021 16:55:12.086 * Listo para aceptar conexiones
4161:M 23 Dec 2021 17:00:12.088 * 100 cambios en 300 segundos. Guardando...
4161:M 23 Dec 2021 17:00:12.098 * Guardado en segundo plano iniciado por el pid 4612
4612:C 23 Dec 2021 17:00:12.189 * DB guardado en disco
4612:C 23 Dec 2021 17:00:12.191 * RDB: 0 MB de memoria utilizada por copy-on-write
4161:M 23 Dec 2021 17:00:12.199 * Guardado en segundo plano finalizado con éxito

Vuelvo a ver ese aviso de copy-on-write de 0 MB, pero no sé si es normal o no. No puedo abrir una conexión telnet en esa máquina a localhost 6379, obtengo el error:
No se puede conectar al host remoto: No se puede asignar la dirección solicitada

El registro de producción muestra muchos bloqueos 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'
Excepción del trabajo: sin dirección para meta.discourse.org (Resolv::ResolvError)

michaeld · 23 Diciembre, 2021 17:46

Esa salida de Redis es normal y no indica necesariamente que Redis no esté escuchando. Es un guardado en segundo plano que siempre ocurre cada pocos minutos. No significa que se esté “repitiendo” en lugar de funcionar. Creo que es una buena señal que muestre esta salida. Así que algo más debe estar mal. Tal vez esté en un puerto diferente, tal vez no se pueda alcanzar por alguna otra razón.

L30110 · 23 Diciembre, 2021 17:50

Muchas gracias por eso. ¿Cuáles serían otras posibilidades para que todos estos bloques se registren y los comandos se queden colgados?

michaeld · 23 Diciembre, 2021 17:51

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 algo más ya está escuchando en ese puerto. Considera reiniciar.

Ed_S · 23 Diciembre, 2021 18:03

Para ver qué proceso está escuchando en un puerto, intente
sudo lsof -n -i -P | egrep LISTEN

L30110 · 23 Diciembre, 2021 18:30

Puedo ver desde ps que redis se está ejecutando y quiere escuchar en 6379

/usr/bin/redis-server *:6379

pero lsof no muestra nada escuchando realmente en ese puerto.

Ed_S · 23 Diciembre, 2021 18:32

Como referencia, este es redis iniciando en medio de mi reconstrucción más reciente:

111:C 22 Dec 2021 20:36:16.773 # oO0OoO0OoO0Oo Redis está iniciando oO0OoO0OoO0Oo
111:C 22 Dec 2021 20:36:16.773 # Versión de Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=111, recién iniciado
111:C 22 Dec 2021 20:36:16.773 # Configuración cargada
111:M 22 Dec 2021 20:36:16.774 * Reloj monotónico: POSIX clock_gettime
111:M 22 Dec 2021 20:36:16.775 * Modo de ejecución=standalone, puerto=6379.
111:M 22 Dec 2021 20:36:16.776 # ADVERTENCIA: La configuración del backlog TCP de 511 no se puede aplicar porque /proc/sys/net/core/somaxconn está configurado en el valor inferior de 128.
111:M 22 Dec 2021 20:36:16.776 # Servidor inicializado
111:M 22 Dec 2021 20:36:16.777 * Cargando RDB producido por la versión 6.2.1
111:M 22 Dec 2021 20:36:16.777 * Edad del RDB 22 segundos
111:M 22 Dec 2021 20:36:16.777 * Uso de memoria del RDB cuando se creó 19.89 Mb
111:M 22 Dec 2021 20:36:16.823 # Carga del RDB completada, claves cargadas: 4451, claves expiradas: 9.
111:M 22 Dec 2021 20:36:16.823 * DB cargada desde disco: 0.047 segundos
111:M 22 Dec 2021 20:36:16.823 * Listo para aceptar conexiones

un poco más tarde 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 está iniciando oO0OoO0OoO0Oo
139:C 22 Dec 2021 20:36:27.086 # Versión de Redis=6.2.6, bits=64, commit=00000000, modificado=0, pid=139, recién iniciado
139:C 22 Dec 2021 20:36:27.086 # Configuración cargada
139:M 22 Dec 2021 20:36:27.087 * Reloj monotónico: POSIX clock_gettime
139:M 22 Dec 2021 20:36:27.087 # Advertencia: No se pudo crear el socket de escucha TCP del servidor *:6379: bind: Dirección ya en uso
139:M 22 Dec 2021 20:36:27.087 # Falló la escucha en el puerto 6379 (TCP), abortando.
Comprobando archivos: 100% (26188/26188), hecho.
I, [2021-12-22T20:36:30.153161 #1]  INFO -- : HEAD está ahora en eb82849c FIX: filtro de categorías none y all (#14999)

L30110 · 23 Diciembre, 2021 18:33

Sí, eso se parece a lo que veo en la compilación de esta mañana. Pero en realidad nada está escuchando en ese puerto. Es extraño.

Ed_S · 23 Diciembre, 2021 18:37

Curiosamente, mi configuración funciona bien, tengo

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

y sin embargo, yo tampoco veo (desde lsof, dentro o fuera del contenedor) nada escuchando en ese puerto.

L30110 · 23 Diciembre, 2021 18:50

Eso es algo alentador. Y algo no…

Ed_S · 23 Diciembre, 2021 19:17

Mi registro muestra un montón de entradas cada 5 minutos. Quizás esto sea normal, ¿y tus problemas con el foro no están relacionados con redis?

$ less /var/discourse/shared/standalone/log/var-log/redis/current
23478:C 23 Dec 2021 18:47:35.233 * DB guardado en disco
23478:C 23 Dec 2021 18:47:35.234 * RDB: 1 MB de memoria utilizada por copia en escritura
52:M 23 Dec 2021 18:47:35.290 * Guardado en segundo plano terminado con éxito
52:M 23 Dec 2021 18:52:36.033 * 100 cambios en 300 segundos. Guardando...
52:M 23 Dec 2021 18:52:36.034 * Guardado en segundo plano iniciado por el proceso 23804
23804:C 23 Dec 2021 18:52:36.177 * DB guardado en disco
23804:C 23 Dec 2021 18:52:36.178 * RDB: 1 MB de memoria utilizada por copia en escritura
52:M 23 Dec 2021 18:52:36.235 * Guardado en segundo plano terminado con éxito
52:M 23 Dec 2021 18:57:37.085 * 100 cambios en 300 segundos. Guardando...
52:M 23 Dec 2021 18:57:37.086 * Guardado en segundo plano iniciado por el proceso 24137
24137:C 23 Dec 2021 18:57:37.221 * DB guardado en disco
24137:C 23 Dec 2021 18:57:37.222 * RDB: 1 MB de memoria utilizada por copia en escritura
52:M 23 Dec 2021 18:57:37.287 * Guardado en segundo plano terminado con éxito
52:M 23 Dec 2021 19:02:38.033 * 100 cambios en 300 segundos. Guardando...
52:M 23 Dec 2021 19:02:38.034 * Guardado en segundo plano iniciado por el proceso 24466

L30110 · 23 Diciembre, 2021 19:45

Gracias. Sin embargo, esto sugiere que vuelvo a empezar de cero con un foro roto… Ay.

Tema		Respuestas	Vistas
Error connecting to Redis Installation	17	6978	21 Marzo 2023
Discourse failing due to expired certificates, rebuilt app, now discourse not working Installation	17	860	30 Marzo 2023
502 bad gateway with clean rebuild and no plugins except discourse docker Installation	5	371	14 Febrero 2024
Installed OK. Working fine for one day. Suddenly stopped working Installation	14	2596	20 Junio 2018
Redis Error after upgrade Installation	14	1588	3 Julio 2020

¿Problemas con Redis? (Foro roto después de la actualización)

Temas relacionados