Проблемы с Redis? (Форум не работает после обновления)

Поддержка Самостоятельное хостинг
1

Мне сегодня предложили обновить систему, после чего потребовалось выполнить сборку через лаунчер. С тех пор Discourse практически не работает. Пользователи, уже вошедшие в систему, могут видеть главную страницу и выбирать сообщения для отображения, но практически все функции для пользователей и администраторов зависают, а индикатор загрузки продолжает крутиться. Журнал production пуст. Я, конечно, пробовал останавливать и перезапускать систему. Даже не уверен, с чего начать поиск проблемы. Есть какие-то идеи? Спасибо!

ОБНОВЛЕНИЕ: Как указано в моих различных ответах ниже, похоже, что корень проблемы заключается в том, что rdis не принимает соединения. В приведённом ниже фрагменте журнала rdis видно, что процесс, по-видимому, зацикливается, каждый раз начиная с:

100 изменений за 300 секунд. Сохранение…

и никогда не переходя в состояние «ожидание соединения». Буду очень признателен за любые предложения по решению этой проблемы. Спасибо.

2

В предыдущем логе отображается множество блоков, например:

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

Полная перезагрузка системы не решила проблему. Ситуация после полной перезагрузки осталась точно такой же.

4

unicorn.stderr.log показывает множество ошибок, связанных с подключением к Redis, например:

Не удалось сообщить об ошибке: Ошибка подключения к Redis на localhost:6379 (Errno::EADDRNOTAVAIL)

5

Вот текущий лог Redis:

3112:C 23 Dec 2021 01:56:54.912 # oO0OoO0OoO0Oo Redis запускается oO0OoO0OoO0Oo
3112:C 23 Dec 2021 01:56:54.912 # Версия Redis=6.2.6, разрядность=64, коммит=00000000, изменён=0, pid=3112, только что запущен
3112:C 23 Dec 2021 01:56:54.912 # Конфигурация загружена
3112:M 23 Dec 2021 01:56:54.914 * Монохронные часы: POSIX clock_gettime
3112:M 23 Dec 2021 01:56:55.105 * Режим работы=standalone, порт=6379.
3112:M 23 Dec 2021 01:56:55.105 # ПРЕДУПРЕЖДЕНИЕ: Настройка TCP backlog, равная 511, не может быть применена, так как /proc/sys/net/core/somaxconn установлено в меньшее значение 128.
3112:M 23 Dec 2021 01:56:55.105 # Сервер инициализирован
3112:M 23 Dec 2021 01:56:55.105 # ПРЕДУПРЕЖДЕНИЕ: overcommit_memory установлено в 0! Фоновое сохранение может завершиться неудачей при нехватке памяти. Чтобы исправить эту проблему, добавьте 'vm.overcommit_memory = 1' в файл /etc/sysctl.conf, затем перезагрузите систему или выполните команду 'sysctl vm.overcommit_memory=1', чтобы изменения вступили в силу.
3112:M 23 Dec 2021 01:56:55.401 * Загрузка RDB, созданного в версии 6.2.6
3112:M 23 Dec 2021 01:56:55.401 * Возраст RDB: 296 секунд
3112:M 23 Dec 2021 01:56:55.401 * Использование памяти RDB при создании: 4.86 Мб
3112:M 23 Dec 2021 01:56:55.634 # Загрузка RDB завершена, загружено ключей: 2751, истекших ключей: 2.
3112:M 23 Dec 2021 01:56:55.634 * База данных загружена с диска за: 0.528 секунд
3112:M 23 Dec 2021 01:56:55.634 * Готов принять подключения
3112:M 23 Dec 2021 02:01:55.037 * 100 изменений за 300 секунд. Сохранение...
3112:M 23 Dec 2021 02:01:55.038 * Фоновое сохранение запущено процессом с pid 3523
3523:C 23 Dec 2021 02:01:55.140 * База данных сохранена на диск
3523:C 23 Dec 2021 02:01:55.142 * RDB: 0 МБ памяти использовано механизмом copy-on-write
3112:M 23 Dec 2021 02:01:55.239 * Фоновое сохранение завершено успешно
3112:M 23 Dec 2021 02:06:56.065 * 100 изменений за 300 секунд. Сохранение...
3112:M 23 Dec 2021 02:06:56.065 * Фоновое сохранение запущено процессом с pid 3831
3831:C 23 Dec 2021 02:06:56.134 * База данных сохранена на диск
3831:C 23 Dec 2021 02:06:56.136 * RDB: 0 МБ памяти использовано механизмом copy-on-write
3112:M 23 Dec 2021 02:06:56.166 * Фоновое сохранение завершено успешно
3112:M 23 Dec 2021 02:11:57.071 * 100 изменений за 300 секунд. Сохранение...
3112:M 23 Dec 2021 02:11:57.071 * Фоновое сохранение запущено процессом с pid 4138
4138:C 23 Dec 2021 02:11:57.135 * База данных сохранена на диск
4138:C 23 Dec 2021 02:11:57.137 * RDB: 0 МБ памяти использовано механизмом copy-on-write
3112:M 23 Dec 2021 02:11:57.172 * Фоновое сохранение завершено успешно
3112:M 23 Dec 2021 02:16:58.000 * 100 изменений за 300 секунд. Сохранение...
3112:M 23 Dec 2021 02:16:58.001 * Фоновое сохранение запущено процессом с pid 4448
4448:C 23 Dec 2021 02:16:58.064 * База данных сохранена на диск
4448:C 23 Dec 2021 02:16:58.066 * RDB: 0 МБ памяти использовано механизмом copy-on-write
3112:M 23 Dec 2021 02:16:58.101 * Фоновое сохранение завершено успешно
6

Похоже, что Rdis зацикливается на этом и никогда не переходит в состояние ожидания подключений:

3112:M 23 Dec 2021 03:02:07.032 * 100 изменений за 300 секунд. Сохранение...
3112:M 23 Dec 2021 03:02:07.033 * Фоновое сохранение запущено процессом с PID 7243
7243:C 23 Dec 2021 03:02:07.104 * База данных сохранена на диск
7243:C 23 Dec 2021 03:02:07.105 * RDB: 0 МБ памяти использовано при копировании при записи
3112:M 23 Dec 2021 03:02:07.134 * Фоновое сохранение завершено успешно
7

Стоит проверить память:

free
vmstat 5 5 
uptime

Пока мы говорим об этом, возможно, стоит также проверить свободное место на диске:
df -h /

И, если вы не получите конкретных рекомендаций, возможно, стоит попробовать выполнить повторную сборку. Обязательно сделайте резервную копию и убедитесь, что она также загружена, на всякий случай.

Но на самом деле кажется, что вам нужны более конкретные рекомендации.

8

Привет. У меня есть локальные резервные копии Discourse примерно за неделю, но пока я не знаю, как их использовать. Свободной памяти достаточно (минимум 1,5 ГБ), также свободно место на диске. Сейчас попробую выполнить ещё одну пересборку. Спасибо.

9

Переустановлено. Если говорить коротко, проблема осталась прежней, хотя я заметил некоторые изменения в процессе. Во время сборки я обратил внимание на следующее:

139:C 23 Dec 2021 16:40:32.625 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
139:C 23 Dec 2021 16:40:32.625 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=139, just started
139:C 23 Dec 2021 16:40:32.626 # Configuration loaded
139:M 23 Dec 2021 16:40:32.627 * monotonic clock: POSIX clock_gettime
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.

Позже я увидел следующее, что было похоже на циклические сообщения, которые я наблюдал ранее. Однако здесь указано, что для функции copy-on-write было использовано 1 МБ памяти, тогда как в циклическом логе Redis было указано 0 МБ.

112:M 23 Dec 2021 16:46:08.702 * 100 changes in 300 seconds. Saving...
112:M 23 Dec 2021 16:46:08.703 * Background saving started by pid 715
715:C 23 Dec 2021 16:46:08.822 * DB saved on disk
715:C 23 Dec 2021 16:46:08.824 * RDB: 1 MB of memory used by copy-on-write
112:M 23 Dec 2021 16:46:08.905 * Background saving terminated with success

Текущий лог Redis:

4161:M 23 Dec 2021 16:55:11.867 * Loading RDB produced by version 6.2.6
4161:M 23 Dec 2021 16:55:11.867 * RDB age 281 seconds
4161:M 23 Dec 2021 16:55:11.867 * RDB memory usage when created 4.61 Mb
4161:M 23 Dec 2021 16:55:12.086 # Done loading RDB, keys loaded: 2743, keys expired: 0.
4161:M 23 Dec 2021 16:55:12.086 * DB loaded from disk: 0.265 seconds
4161:M 23 Dec 2021 16:55:12.086 * Ready to accept connections
4161:M 23 Dec 2021 17:00:12.088 * 100 changes in 300 seconds. Saving...
4161:M 23 Dec 2021 17:00:12.098 * Background saving started by pid 4612
4612:C 23 Dec 2021 17:00:12.189 * DB saved on disk
4612:C 23 Dec 2021 17:00:12.191 * RDB: 0 MB of memory used by copy-on-write
4161:M 23 Dec 2021 17:00:12.199 * Background saving terminated with success

Я снова вижу уведомление о 0 МБ, используемых для copy-on-write, но не знаю, нормально ли это. Я не могу установить соединение telnet с этой машины на localhost:6379 — получаю ошибку:

Не удалось подключиться к удалённому хосту: невозможно назначить запрошенный адрес

В продакшн-логе, как и раньше, много блоков:

/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'
Job exception: no address for meta.discourse.org (Resolv::ResolvError)
10

Такой вывод Redis является нормальным и не обязательно указывает на то, что Redis не прослушивает запросы. Это фоновое сохранение, которое происходит регулярно каждые несколько минут. Это не означает, что процесс «зацикливается» вместо того, чтобы работать. На самом деле, появление такого вывода — хороший знак. Значит, проблема кроется в чём-то другом. Возможно, Redis работает на другом порту или недоступен по какой-то иной причине.

11

Огромное спасибо за это. Какие ещё могут быть причины того, что все эти блоки логируются, а команды просто зависают?

12

Похоже, что что-то другое уже прослушивает этот порт. Попробуйте перезагрузить систему.

13

Чтобы увидеть, какой процесс слушает порт, попробуйте
sudo lsof -n -i -P | egrep LISTEN

14

Я вижу из вывода ps, что Redis запущен и настроен на прослушивание порта 6379:

/usr/bin/redis-server *:6379

однако утилита lsof не показывает ничего, что фактически слушает этот порт.

15

Для справки, вот начало работы Redis в середине моей последней пересборки:

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

Чуть позже я вижу:

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)
16

Да, это примерно то же, что я вижу в сборке от этого утра. Но на этом порту ничего не слушает. Это странно.

17

Странно, мой setup работает нормально, у меня

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

и всё же я тоже не вижу (через lsof, внутри или снаружи контейнера) ничего, слушающего этот порт.

18

Это вроде ободряюще. А вроде и нет…

19

Мой лог показывает группу записей каждые 5 минут. Возможно, это нормально, и проблемы с вашим форумом не связаны с 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
20

Спасибо. Хотя это говорит о том, что я снова вернулся к нулю с неработающим форумом… Ой.