Problèmes Redis ? (Forum HS après mise à niveau)

On m’a demandé de mettre à jour aujourd’hui, puis j’ai été obligé de faire la compilation via le lanceur. Depuis, Discourse est pratiquement cassé. Les utilisateurs déjà connectés peuvent voir la page d’accueil et sélectionner des messages à partir de là pour les afficher, mais pratiquement toutes les fonctions utilisateur et administrateur se bloquent avec le throbber qui tourne. Le journal de production est vide. J’ai essayé d’arrêter et de redémarrer, bien sûr. Je ne sais même pas par où commencer à chercher. Des idées ? Merci !

MISE À JOUR : Comme indiqué dans mes différentes réponses ci-dessous, il semble que la cause profonde du problème soit que rdis n’accepte pas les connexions, et l’extrait du journal rdis ci-dessous montre rdis apparemment en boucle, commençant chaque fois par :

100 changements en 300 secondes. Sauvegarde…

et n’atteignant jamais l’état de « attente de connexion ». Toute suggestion sur la façon de résoudre ce problème serait très appréciée. Merci.

1 « J'aime »

Un journal précédent montre une variété de blocs, par exemple :

/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 « J'aime »

Le redémarrage complet du système n’a pas résolu le problème. La situation est exactement la même après un redémarrage complet.

1 « J'aime »

unicorn.stderr.log affiche de nombreuses erreurs liées à la connexion à Redis, par exemple :

Échec du signalement de l’erreur : Erreur de connexion à Redis sur localhost:6379 (Errno::EADDRNOTAVAIL)

1 « J'aime »

Voici le journal redis actuel :

3112:C 23 déc. 2021 01:56:54.912 # oO0OoO0OoO0Oo Redis démarre oO0OoO0OoO0Oo
3112:C 23 déc. 2021 01:56:54.912 # Version Redis=6.2.6, bits=64, commit=00000000, modifié=0, pid=3112, vient de démarrer
3112:C 23 déc. 2021 01:56:54.912 # Configuration chargée
3112:M 23 déc. 2021 01:56:54.914 * Horloge monotone : POSIX clock_gettime
3112:M 23 déc. 2021 01:56:55.105 * Mode d'exécution=standalone, port=6379.
3112:M 23 déc. 2021 01:56:55.105 # ATTENTION : Le paramètre de backlog TCP de 511 ne peut pas être appliqué car /proc/sys/net/core/somaxconn est défini sur la valeur inférieure de 128.
3112:M 23 déc. 2021 01:56:55.105 # Serveur initialisé
3112:M 23 déc. 2021 01:56:55.105 # ATTENTION overcommit_memory est défini sur 0 ! La sauvegarde en arrière-plan peut échouer en cas de faible mémoire. Pour résoudre ce problème, ajoutez 'vm.overcommit_memory = 1' à /etc/sysctl.conf puis redémarrez ou exécutez la commande 'sysctl vm.overcommit_memory=1' pour que cela prenne effet.
3112:M 23 déc. 2021 01:56:55.401 * Chargement du RDB produit par la version 6.2.6
3112:M 23 déc. 2021 01:56:55.401 * Âge du RDB 296 secondes
3112:M 23 déc. 2021 01:56:55.401 * Utilisation de la mémoire RDB lors de la création 4.86 Mo
3112:M 23 déc. 2021 01:56:55.634 # Chargement du RDB terminé, clés chargées : 2751, clés expirées : 2.
3112:M 23 déc. 2021 01:56:55.634 * DB chargée depuis le disque : 0.528 secondes
3112:M 23 déc. 2021 01:56:55.634 * Prêt à accepter les connexions
3112:M 23 déc. 2021 02:01:55.037 * 100 changements en 300 secondes. Sauvegarde en cours...
3112:M 23 déc. 2021 02:01:55.038 * Sauvegarde en arrière-plan démarrée par le pid 3523
3523:C 23 déc. 2021 02:01:55.140 * DB sauvegardée sur disque
3523:C 23 déc. 2021 02:01:55.142 * RDB : 0 Mo de mémoire utilisée par la copie sur écriture
3112:M 23 déc. 2021 02:01:55.239 * Sauvegarde en arrière-plan terminée avec succès
3112:M 23 déc. 2021 02:06:56.065 * 100 changements en 300 secondes. Sauvegarde en cours...
3112:M 23 déc. 2021 02:06:56.065 * Sauvegarde en arrière-plan démarrée par le pid 3831
3831:C 23 déc. 2021 02:06:56.134 * DB sauvegardée sur disque
3831:C 23 déc. 2021 02:06:56.136 * RDB : 0 Mo de mémoire utilisée par la copie sur écriture
3112:M 23 déc. 2021 02:06:56.166 * Sauvegarde en arrière-plan terminée avec succès
3112:M 23 déc. 2021 02:11:57.071 * 100 changements en 300 secondes. Sauvegarde en cours...
3112:M 23 déc. 2021 02:11:57.071 * Sauvegarde en arrière-plan démarrée par le pid 4138
4138:C 23 déc. 2021 02:11:57.135 * DB sauvegardée sur disque
4138:C 23 déc. 2021 02:11:57.137 * RDB : 0 Mo de mémoire utilisée par la copie sur écriture
3112:M 23 déc. 2021 02:11:57.172 * Sauvegarde en arrière-plan terminée avec succès
3112:M 23 déc. 2021 02:16:58.000 * 100 changements en 300 secondes. Sauvegarde en cours...
3112:M 23 déc. 2021 02:16:58.001 * Sauvegarde en arrière-plan démarrée par le pid 4448
4448:C 23 déc. 2021 02:16:58.064 * DB sauvegardée sur disque
4448:C 23 déc. 2021 02:16:58.066 * RDB : 0 Mo de mémoire utilisée par la copie sur écriture
3112:M 23 déc. 2021 02:16:58.101 * Sauvegarde en arrière-plan terminée avec succès
1 « J'aime »

Rdis semble boucler de manière répétée avec ceci et n’atteint jamais un état où il attend des connexions :

3112:M 23 déc. 2021 03:02:07.032 * 100 changements en 300 secondes. Sauvegarde en cours...
3112:M 23 déc. 2021 03:02:07.033 * Sauvegarde en arrière-plan démarrée par le processus 7243
7243:C 23 déc. 2021 03:02:07.104 * DB sauvegardée sur disque
7243:C 23 déc. 2021 03:02:07.105 * RDB : 0 Mo de mémoire utilisée par la copie sur écriture
3112:M 23 déc. 2021 03:02:07.134 * Sauvegarde en arrière-plan terminée avec succès
2 « J'aime »

Il pourrait être utile de vérifier la mémoire :

free
vmstat 5 5 
uptime

Pendant que nous y sommes, vérifions peut-être aussi l’espace disque
df -h /

Et, si vous n’obtenez pas de conseils spécifiques, une autre reconstruction pourrait valoir la peine d’être tentée. Assurez-vous d’avoir une sauvegarde, et de l’avoir également téléchargée, juste au cas où.

Mais vraiment, on a l’impression que vous avez besoin de conseils plus spécifiques.

2 « J'aime »

Salut. J’ai environ une semaine de sauvegardes Discourse localement, bien qu’à ce stade je ne sache pas comment les utiliser. Il y a beaucoup de mémoire libre (au moins 1,5 Go) et de disque libre. Je vais essayer une autre reconstruction maintenant. Merci.

1 « J'aime »

Reconstruit. En fin de compte, il est toujours cassé de la même manière, bien qu’il y ait eu quelques changements que j’ai remarqués en cours de route. Pendant la construction, j’ai remarqué :

139:C 23 déc. 2021 16:40:32.625 # oO0OoO0OoO0Oo Redis démarre oO0OoO0OoO0Oo
139:C 23 déc. 2021 16:40:32.625 # Version Redis=6.2.6, bits=64, commit=00000000, modifié=0, pid=139, vient de démarrer
139:C 23 déc. 2021 16:40:32.626 # Configuration chargée
139:M 23 déc. 2021 16:40:32.627 * Horloge monotone : POSIX clock_gettime
139:M 23 déc. 2021 16:40:32.627 # Avertissement : Impossible de créer le socket d'écoute TCP du serveur *:6379 : bind : Adresse déjà utilisée
139:M 23 déc. 2021 16:40:32.628 # Échec de l'écoute sur le port 6379 (TCP), abandon.

Plus tard, j’ai vu ceci, qui était similaire à la boucle que j’avais vue plus tôt. Cependant, il indique 1 Mo de mémoire utilisé pour la copie sur écriture, et la boucle du journal Redis indiquait 0 Mo.

112:M 23 déc. 2021 16:46:08.703 * Sauvegarde en arrière-plan démarrée par le processus 715
715:C 23 déc. 2021 16:46:08.822 * DB sauvegardé sur disque
715:C 23 déc. 2021 16:46:08.824 * RDB : 1 Mo de mémoire utilisé par la copie sur écriture
112:M 23 déc. 2021 16:46:08.905 * Sauvegarde en arrière-plan terminée avec succès

Le journal Redis actuel :

4161:M 23 déc. 2021 16:55:11.867 * Chargement du RDB produit par la version 6.2.6
4161:M 23 déc. 2021 16:55:11.867 * Âge du RDB 281 secondes
4161:M 23 déc. 2021 16:55:11.867 * Utilisation de la mémoire RDB lors de la création 4.61 Mo
4161:M 23 déc. 2021 16:55:12.086 # Chargement du RDB terminé, clés chargées : 2743, clés expirées : 0.
4161:M 23 déc. 2021 16:55:12.086 * DB chargé depuis le disque : 0.265 secondes
4161:M 23 déc. 2021 16:55:12.086 * Prêt à accepter les connexions
4161:M 23 déc. 2021 17:00:12.088 * 100 changements en 300 secondes. Sauvegarde...
4161:M 23 déc. 2021 17:00:12.098 * Sauvegarde en arrière-plan démarrée par le processus 4612
4612:C 23 déc. 2021 17:00:12.189 * DB sauvegardé sur disque
4612:C 23 déc. 2021 17:00:12.191 * RDB : 0 Mo de mémoire utilisé par la copie sur écriture
4161:M 23 déc. 2021 17:00:12.199 * Sauvegarde en arrière-plan terminée avec succès

Je vois à nouveau cet avis de copie sur écriture de 0 Mo, mais je ne sais pas si c’est normal ou non. Je ne peux pas ouvrir de connexion telnet sur cette machine vers localhost 6379, j’obtiens l’erreur :
Impossible de se connecter à l’hôte distant : Impossible d’attribuer l’adresse demandée

Le journal de production montre de nombreux blocages comme auparavant :

/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'
Exception du travail : aucune adresse pour meta.discourse.org (Resolv::ResolvError)
1 « J'aime »

Cette sortie Redis est normale et n’indique pas nécessairement que Redis n’écoute pas. Il s’agit d’une sauvegarde en arrière-plan qui se produit toujours toutes les quelques minutes. Cela ne signifie pas qu’il est en “boucle” au lieu de fonctionner. Je pense que c’est en fait un bon signe qu’il affiche cette sortie. Quelque chose d’autre doit donc mal fonctionner. Peut-être est-il sur un port différent, peut-être qu’il ne peut pas être atteint pour une autre raison.

2 « J'aime »

Merci beaucoup pour cela. Quelles seraient d’autres possibilités pour que tous ces blocs soient enregistrés et que les commandes restent bloquées ?

1 « J'aime »

Il semble que quelque chose d’autre écoute déjà sur ce port. Envisagez un redémarrage.

1 « J'aime »

Pour voir quel processus écoute sur un port, essayez
sudo lsof -n -i -P | egrep LISTEN

1 « J'aime »

Je vois d’après ps que redis s’exécute et souhaite écouter sur le port 6379

/usr/bin/redis-server *:6379

mais lsof ne montre rien qui écoute réellement sur ce port.

1 « J'aime »

Pour référence, voici redis qui démarre au milieu de ma dernière reconstruction :

111:C 22 déc. 2021 20:36:16.773 # oO0OoO0OoO0Oo Redis démarre oO0OoO0OoO0Oo
111:C 22 déc. 2021 20:36:16.773 # Version Redis=6.2.6, bits=64, commit=00000000, modifié=0, pid=111, vient de démarrer
111:C 22 déc. 2021 20:36:16.773 # Configuration chargée
111:M 22 déc. 2021 20:36:16.774 * Horloge monotone : POSIX clock_gettime
111:M 22 déc. 2021 20:36:16.775 * Mode d'exécution=standalone, port=6379.
111:M 22 déc. 2021 20:36:16.776 # ATTENTION : Le paramètre de backlog TCP de 511 ne peut pas être appliqué car /proc/sys/net/core/somaxconn est défini sur la valeur inférieure de 128.
111:M 22 déc. 2021 20:36:16.776 # Serveur initialisé
111:M 22 déc. 2021 20:36:16.777 * Chargement du RDB produit par la version 6.2.1
111:M 22 déc. 2021 20:36:16.777 * Âge du RDB 22 secondes
111:M 22 déc. 2021 20:36:16.777 * Utilisation de la mémoire RDB lors de la création 19,89 Mo
111:M 22 déc. 2021 20:36:16.823 # Chargement du RDB terminé, clés chargées : 4451, clés expirées : 9.
111:M 22 déc. 2021 20:36:16.823 * DB chargé depuis le disque : 0,047 secondes
111:M 22 déc. 2021 20:36:16.823 * Prêt à accepter les connexions

un peu plus tard, je vois

I, [2021-12-22T20:36:27.079511 #1]  INFO -- : cd /var/www/discourse & git reset --hard
139:C 22 déc. 2021 20:36:27.084 # oO0OoO0OoO0Oo Redis démarre oO0OoO0OoO0Oo
139:C 22 déc. 2021 20:36:27.086 # Version Redis=6.2.6, bits=64, commit=00000000, modifié=0, pid=139, vient de démarrer
139:C 22 déc. 2021 20:36:27.086 # Configuration chargée
139:M 22 déc. 2021 20:36:27.087 * Horloge monotone : POSIX clock_gettime
139:M 22 déc. 2021 20:36:27.087 # Avertissement : Impossible de créer le socket d'écoute TCP du serveur *:6379 : bind : Adresse déjà utilisée
139:M 22 déc. 2021 20:36:27.087 # Échec de l'écoute sur le port 6379 (TCP), abandon.
Vérification des fichiers : 100 % (26188/26188), terminé.
I, [2021-12-22T20:36:30.153161 #1]  INFO -- : HEAD est maintenant à eb82849c FIX : aucun filtre de catégorie et tous les filtres (#14999)
1 « J'aime »

Ouais, ça ressemble à ce que je vois du build de ce matin. Mais rien n’écoute réellement sur ce port. C’est bizarre.

1 « J'aime »

Étrangement, ma configuration fonctionne correctement, j’ai

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

et pourtant, je ne vois pas non plus (depuis lsof, à l’intérieur ou à l’extérieur du conteneur) quoi que ce soit en écoute sur ce port.

1 « J'aime »

C’est un peu encourageant. Et un peu pas …

1 « J'aime »

Mon journal affiche une série d’entrées toutes les 5 minutes. C’est peut-être normal, et vos problèmes de forum ne sont pas liés à redis ??

$ less /var/discourse/shared/standalone/log/var-log/redis/current
23478:C 23 Dec 2021 18:47:35.233 * DB saved on disk
23478:C 23 Dec 2021 18:47:35.234 * RDB: 1 MB of memory used by copy-on-write
52:M 23 Dec 2021 18:47:35.290 * Background saving terminated with success
52:M 23 Dec 2021 18:52:36.033 * 100 changes in 300 seconds. Saving...
52:M 23 Dec 2021 18:52:36.034 * Background saving started by pid 23804
23804:C 23 Dec 2021 18:52:36.177 * DB saved on disk
23804:C 23 Dec 2021 18:52:36.178 * RDB: 1 MB of memory used by copy-on-write
52:M 23 Dec 2021 18:52:36.235 * Background saving terminated with success
52:M 23 Dec 2021 18:57:37.085 * 100 changes in 300 seconds. Saving...
52:M 23 Dec 2021 18:57:37.086 * Background saving started by pid 24137
24137:C 23 Dec 2021 18:57:37.221 * DB saved on disk
24137:C 23 Dec 2021 18:57:37.222 * RDB: 1 MB of memory used by copy-on-write
52:M 23 Dec 2021 18:57:37.287 * Background saving terminated with success
52:M 23 Dec 2021 19:02:38.033 * 100 changes in 300 seconds. Saving...
52:M 23 Dec 2021 19:02:38.034 * Background saving started by pid 24466
1 « J'aime »

Merci. Bien que cela suggère que je suis de retour à la case départ avec un forum cassé… Aïe.

1 « J'aime »