Docker部署Redis与ioredis随机断连问题排查求助

Docker Compose Redis配置 #

redis:
  image: "redis:latest"
  volumes:
    - redis_data:/data

注：此为最简配置，暂未发现问题

Node.js ioredis连接代码 #

import Redis from "ioredis";

export const redis = new Redis(process.env.REDIS_URL ?? '');

Redis启动日志 #

redis_1  | 1:C 09 Jan 2023 06:00:49.251 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
redis_1  | 1:C 09 Jan 2023 06:00:49.252 # Redis version=7.0.10, bits=64, commit=00000000, modified=0, pid=1, just started
redis_1  | 1:C 09 Jan 2023 06:00:49.252 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
redis_1  | 1:M 09 Jan 2023 06:00:49.254 * monotonic clock: POSIX clock_gettime
redis_1  | 1:M 09 Jan 2023 06:00:49.258 * Running mode=standalone, port=6379.
redis_1  | 1:M 09 Jan 2023 06:00:49.258 # Server initialized
redis_1  | 1:M 09 Jan 2023 06:00:49.259 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
redis_1  | 1:M 09 Jan 2023 06:00:49.260 * Loading RDB produced by version 7.0.10
redis_1  | 1:M 09 Jan 2023 06:00:49.261 * RDB age 120617 seconds
redis_1  | 1:M 09 Jan 2023 06:00:49.261 * RDB memory usage when created 274.70 Mb
redis_1  | 1:M 09 Jan 2023 06:00:51.257 * Done loading RDB, keys loaded: 1201, keys expired: 0.
redis_1  | 1:M 09 Jan 2023 06:00:51.258 * DB loaded from disk: 1.998 seconds
redis_1  | 1:M 09 Jan 2023 06:00:51.259 * Ready to accept connections

Redis日常运行日志（多日重复） #

redis_1  | 1:M 09 May 2023 15:49:24.506 * 1 changes in 3600 seconds. Saving...
redis_1  | 1:M 09 May 2023 15:49:24.517 * Background saving started by pid 207
redis_1  | 207:C 09 May 2023 15:49:29.023 * DB saved on disk
redis_1  | 207:C 09 May 2023 15:49:29.025 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
redis_1  | 1:M 09 May 2023 15:49:29.094 * Background saving terminated with success
redis_1  | 1:M 09 May 2023 16:49:30.043 * 1 changes in 3600 seconds. Saving...
redis_1  | 1:M 09 May 2023 16:49:30.061 * Background saving started by pid 208
redis_1  | 208:C 09 May 2023 16:49:31.606 * DB saved on disk
redis_1  | 208:C 09 May 2023 16:49:31.608 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 0 MB
redis_1  | 1:M 09 May 2023 16:49:31.666 * Background saving terminated with success

应用连接故障日志 #

app_1    | [ioredis] Unhandled error event: Error: connect ECONNREFUSED 172.18.0.11:6379
app_1    |     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)
app_1    | [ioredis] Unhandled error event: Error: connect ECONNREFUSED 172.18.0.11:6379
app_1    |     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)
app_1    | [ioredis] Unhandled error event: Error: connect ECONNREFUSED 172.18.0.11:6379
app_1    |     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)
app_1    | finished in 1875996ms
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | [ioredis] Unhandled error event: Error: getaddrinfo EAI_AGAIN redis
app_1    |     at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
app_1    | /opt/app/node_modules/ioredis/built/redis/event_handler.js:182
app_1    |                     self.flushQueue(new errors_1.MaxRetriesPerRequestError(maxRetriesPerRequest));
app_1    |                                     ^
app_1    | 
app_1    | MaxRetriesPerRequestError: Reached the max retries per request limit (which is 20). Refer to "maxRetriesPerRequest" option for details.
app_1    |     at Socket.<anonymous> (/opt/app/node_modules/ioredis/built/redis/event_handler.js:182:37)
app_1    |     at Object.onceWrapper (node:events:628:26)
app_1    |     at Socket.emit (node:events:513:28)
app_1    |     at TCP.<anonymous> (node:net:322:12)

Redis恢复后日志（故障2小时后） #

redis_1  | 1:M 09 May 2023 18:38:33.833 * 1 changes in 3600 seconds. Saving...
redis_1  | 1:M 09 May 2023 18:38:33.842 * Background saving started by pid 209
redis_1  | 209:C 09 May 2023 18:38:35.505 * DB saved on disk
redis_1  | 209:C 09 May 2023 18:38:35.506 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 0 MB
redis_1  | 1:M 09 May 2023 18:38:35.553 * Background saving terminated with success
redis_1  | 1:M 09 May 2023 19:38:36.096 * 1 changes in 3600 seconds. Saving...
redis_1  | 1:M 09 May 2023 19:38:36.108 * Background saving started by pid 210
redis_1  | 210:C 09 May 2023 19:38:37.452 * DB saved on disk
redis_1  | 210:C 09 May 2023 19:38:37.454 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 0 MB
redis_1  | 1:M 09 May 2023 19:38:37.512 * Background saving terminated with success
redis_1  | 1:M 10 May 2023 09:19:02.490 * 1 changes in 3600 seconds. Saving...
redis_1  | 1:M 10 May 2023 09:19:02.538 * Background saving started by pid 211
redis_1  | 211:C 10 May 2023 09:19:06.152 * DB saved on disk

当前临时解决方法 #

• 每隔几分钟ping服务器检查Redis连接状态
• 检测到连接失败时，登录服务器执行以下命令：

docker-compose down
docker-compose up

注：此方法有效，但不够优雅，且未从根源解决问题

需求 #

1. 明确连接故障的根本原因
2. 提供更优雅的解决方案，避免手动重启服务

内容的提问来源于stack exchange，提问作者Daniel