Redis instance on docker disconnect once per few month randomly from ioredis, how to debug?
I am using node library ioredis. And have redis on docker-compose configured like this:
redis:
image: "redis:latest"
volumes:
- redis_data:/data
It is simplest possible config, so I hope nothing is broken here.
My connection is also simplest possible
import Redis from "ioredis";
export const redis = new Redis(process.env.REDIS_URL ?? '');
when I typing docker-compose up I can see logs
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
then I see many days repeating
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 operate normally and suddenly in app I can see logs
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)
but 2 hours later there are produced new logs from redis showing that redis works
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
My current strategy is:
- ping server every few minutes checking if I can connect with redis, if no, then login to server and run
docker-compose down
docker-compose up
It always works perfectly, but I would like to fix this problem in more elegant way, and understand what is reason of this error.
I was able to reproduce this behaviour on few independent services that I am maintaining, but it is very hard to predict when error will occur.
Solution
Logs shows timeouts but real reason was in limited memory on server, that was not monitored. When I was logged in after incident, memory was on normal level, but lack of memory was direct reason of these problems.
Long term solutions:
- limit memory available for redis container and select correct eviction policy
- setup monitoring of memory to prevent these situation
- What does "npm:" prefix in dependency section in package.json mean?
- NextJS NodeJS multi processes
- How to decode Image with multiple QR images in Javascript
- AWS elastic Beanstalk / nginx : connect() failed (111: Connection refused
- Getting ReferenceError: readFile is not defined
- Problem with permissions during deployment firebase cloud function v2
- Mock Multer for multiple tests (vitest and Typescript)
- AWS ECS exec /usr/local/bin/docker-entrypoint.sh: exec format error
- How can I delete folder on S3 with Node.js?
- Error: Could not find matching close tag for "<%="
- Lib working in netlify dev, in netlify preview PR but not in production (Nuxt)
- Internal Error: EACCES: permission denied, symlink '../lib/node_modules/corepack/dist/pnpm.js' -> '/usr/local/bin/pnpm'
- How to loop through result in sequelize
- Programmatic Webpack & Jest (ESM): can't resolve module without '.js' file extension
- Get current URL of browser
- Error building nextjs app on docker but not locally
- name can only contain URL-friendly characters
- Node cannot find module "fs" when using webpack
- Running rs.status() throws BSONError: Invalid UTF-8 string in BSON document in mongosh
- Cannot POST / error using express
- Using multer and express with typescript
- Neo4J always defaults NodeJS numbers as float when using parametrized queries
- I'm getting this error during connecting mongoose to nodejs
- Fs.readFile on FTP server
- How do I uninstall a package installed using npm link?
- How To Fix "Lexical declaration cannot appear in a single-statement context"
- Angular 18 error after update:An unhandled exception occurred: (0 , os_1.availableParallelism) is not a function
- Create a modular npm package
- React + Material-UI - Warning: Prop className did not match
- What could cause an error related to npm not being able to find a file? No contents in my node_modules subfolder. Why is that?