Redis Sentinel Leaks Memory when setting up TLS connections to downed nodes
I have Redis Sentinel 6.2.6 and have made sure I have updated OpenSSL libraries (1.1.1 on Oracle Linux). After rebuilding Redis to enable TLS support and setting it up, everything is working but memory usage of the sentinel steadily grows until system performance is affected, the sentinel goes into tilt mode, and eventually the sentinel process exits.
I've found that it grows based on nodes being down suspect that the ssl context is created but only safely destructed on a successful connection on the polling process for checking nodes.
To reproduce
In my setup I have 6 redis nodes each with their own key and certificate, a sentinel with it's own certificate, and all of them share a ca bundle. Two of the redis nodes are up while the other four are typically off since I only need a master, replica, and sentinel for dev purposes (I know you're supposed to have more in prod). Additionally, I have all nodes and the sentinel configured to only communicate over the encrypted ports with the regular port configured to 0 to disable it.
The basic Redis Config is as below, just change the tls files to one's you've got (naturally I can't just share them here without building up a whole new CA for you) and change the tls-port to the one you want to use for each redis instance (I use 7000-7005 but only 7000 and 7001 are kept online for this error):
bind 0.0.0.0
port 0
tls-port 7000
tls-cert-file ./redis.cert
tls-key-file ./redis.key
tls-ca-cert-file ./ca-chain.cert
tls-replication yes
tls-auth-clients yes
cluster-enabled no
replica-read-only yes
replica-serve-stale-data yes
On the redis instances, I bring up all 6, set 7001-7005 as replicas of 7000, let the sentinel pick them up, then turn off 7002-7005.
The Sentinel Config is much like the Redis Config (again swap your tls files):
bind 0.0.0.0
port 0
tls-port 5000
tls-cert-file ./redis.cert
tls-key-file ./redis.key
tls-ca-cert-file ./ca-chain.cert
tls-replication yes
tls-auth-clients yes
sentinel monitor master 127.0.0.1 7000 1
sentinel down-after-milliseconds master 1000
sentinel failover-timeout master 5000
sentinel parallel-syncs master 1
For the disconnected and leaking as well as the fully connected non-leaking runs below, I connected with the redis-cli to issue a shutdown after running the sentinel for a few minutes in valgrind. I didn't include the full valgrind log but this tail end of it should give you an idea of what's gone wrong here and it's fairly easy to replicate these results to go into a deeper debug effort.
Here's a section of valgrind with only 2/6 nodes up running the sentinel for a short duration:
==3777139== 32,944 bytes in 2 blocks are possibly lost in loss record 549 of 580
==3777139== at 0x4C34F0B: malloc (vg_replace_malloc.c:307)
==3777139== by 0x55F7D01: ??? (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x55F7DA6: ??? (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x5620056: ??? (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x560BCD7: SSL_do_handshake (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x56EEE6: redisSSLConnect (ssl.c:289)
==3777139== by 0x4A34C2: instanceLinkNegotiateTLS (sentinel.c:2405)
==3777139== by 0x4A8514: sentinelReconnectInstance (sentinel.c:2459)
==3777139== by 0x4AD068: sentinelHandleRedisInstance (sentinel.c:5010)
==3777139== by 0x4AD133: sentinelHandleDictOfRedisInstances (sentinel.c:5053)
==3777139== by 0x4AD16B: sentinelHandleDictOfRedisInstances (sentinel.c:5055)
==3777139== by 0x4AD204: sentinelTimer (sentinel.c:5100)
==3777139==
==3777139== 43,696 bytes in 2 blocks are possibly lost in loss record 559 of 580
==3777139== at 0x4C34F0B: malloc (vg_replace_malloc.c:307)
==3777139== by 0x593199F: BUF_MEM_grow (in /usr/lib64/libcrypto.so.1.1.1g)
==3777139== by 0x56209BE: ??? (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x560BCD7: SSL_do_handshake (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x56EEE6: redisSSLConnect (ssl.c:289)
==3777139== by 0x4A34C2: instanceLinkNegotiateTLS (sentinel.c:2405)
==3777139== by 0x4A84E9: sentinelReconnectInstance (sentinel.c:2429)
==3777139== by 0x4AD068: sentinelHandleRedisInstance (sentinel.c:5010)
==3777139== by 0x4AD133: sentinelHandleDictOfRedisInstances (sentinel.c:5053)
==3777139== by 0x4AD16B: sentinelHandleDictOfRedisInstances (sentinel.c:5055)
==3777139== by 0x4AD204: sentinelTimer (sentinel.c:5100)
==3777139== by 0x43B28C: serverCron (server.c:2229)
==3777139==
==3777139== 23,572,432 (2,022,160 direct, 21,550,272 indirect) bytes in 322 blocks are definitely lost in loss record 579 of 580
==3777139== at 0x4C34F0B: malloc (vg_replace_malloc.c:307)
==3777139== by 0x59ED86C: CRYPTO_zalloc (in /usr/lib64/libcrypto.so.1.1.1g)
==3777139== by 0x560E0C7: SSL_new (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x4A34B2: instanceLinkNegotiateTLS (sentinel.c:2402)
==3777139== by 0x4A8514: sentinelReconnectInstance (sentinel.c:2459)
==3777139== by 0x4AD068: sentinelHandleRedisInstance (sentinel.c:5010)
==3777139== by 0x4AD133: sentinelHandleDictOfRedisInstances (sentinel.c:5053)
==3777139== by 0x4AD16B: sentinelHandleDictOfRedisInstances (sentinel.c:5055)
==3777139== by 0x4AD204: sentinelTimer (sentinel.c:5100)
==3777139== by 0x43B28C: serverCron (server.c:2229)
==3777139== by 0x43333C: processTimeEvents (ae.c:318)
==3777139== by 0x43333C: aeProcessEvents (ae.c:457)
==3777139== by 0x43373C: aeMain (ae.c:487)
==3777139==
==3777139== 24,584,200 (2,097,520 direct, 22,486,680 indirect) bytes in 334 blocks are definitely lost in loss record 580 of 580
==3777139== at 0x4C34F0B: malloc (vg_replace_malloc.c:307)
==3777139== by 0x59ED86C: CRYPTO_zalloc (in /usr/lib64/libcrypto.so.1.1.1g)
==3777139== by 0x560E0C7: SSL_new (in /usr/lib64/libssl.so.1.1.1g)
==3777139== by 0x4A34B2: instanceLinkNegotiateTLS (sentinel.c:2402)
==3777139== by 0x4A84E9: sentinelReconnectInstance (sentinel.c:2429)
==3777139== by 0x4AD068: sentinelHandleRedisInstance (sentinel.c:5010)
==3777139== by 0x4AD133: sentinelHandleDictOfRedisInstances (sentinel.c:5053)
==3777139== by 0x4AD16B: sentinelHandleDictOfRedisInstances (sentinel.c:5055)
==3777139== by 0x4AD204: sentinelTimer (sentinel.c:5100)
==3777139== by 0x43B28C: serverCron (server.c:2229)
==3777139== by 0x43333C: processTimeEvents (ae.c:318)
==3777139== by 0x43333C: aeProcessEvents (ae.c:457)
==3777139== by 0x43373C: aeMain (ae.c:487)
==3777139==
==3777139== LEAK SUMMARY:
==3777139== definitely lost: 4,119,680 bytes in 656 blocks
==3777139== indirectly lost: 44,036,952 bytes in 20,389 blocks
==3777139== possibly lost: 162,884 bytes in 25 blocks
==3777139== still reachable: 371,224 bytes in 1,895 blocks
==3777139== suppressed: 0 bytes in 0 blocks
Here's a section of the same but with all 6 nodes up:
==3770888== 100 bytes in 5 blocks are possibly lost in loss record 261 of 511
==3770888== at 0x4C34F0B: malloc (vg_replace_malloc.c:307)
==3770888== by 0x4E5355: hi_malloc (alloc.h:58)
==3770888== by 0x4E5355: hi_sdsnewlen (sds.c:93)
==3770888== by 0x4DFEA9: __redisAsyncCommand (async.c:771)
==3770888== by 0x4E0F9A: redisvAsyncCommand (async.c:833)
==3770888== by 0x4E104C: redisAsyncCommand (async.c:842)
==3770888== by 0x4A84AF: sentinelReconnectInstance (sentinel.c:2477)
==3770888== by 0x4AD068: sentinelHandleRedisInstance (sentinel.c:5010)
==3770888== by 0x4AD133: sentinelHandleDictOfRedisInstances (sentinel.c:5053)
==3770888== by 0x4AD16B: sentinelHandleDictOfRedisInstances (sentinel.c:5055)
==3770888== by 0x4AD204: sentinelTimer (sentinel.c:5100)
==3770888== by 0x43B28C: serverCron (server.c:2229)
==3770888== by 0x43333C: processTimeEvents (ae.c:318)
==3770888== by 0x43333C: aeProcessEvents (ae.c:457)
==3770888==
==3770888== 288 bytes in 1 blocks are possibly lost in loss record 345 of 511
==3770888== at 0x4C3721A: calloc (vg_replace_malloc.c:760)
==3770888== by 0x40129FB: _dl_allocate_tls (in /usr/lib64/ld-2.28.so)
==3770888== by 0x5D52DB2: pthread_create@@GLIBC_2.2.5 (in /usr/lib64/libpthread-2.28.so)
==3770888== by 0x51A0D4: je_pthread_create_wrapper (background_thread.c:50)
==3770888== by 0x51A0D4: background_thread_create_signals_masked (background_thread.c:367)
==3770888== by 0x51A0D4: je_background_thread_create (background_thread.c:574)
==3770888== by 0x51A5E1: je_background_threads_enable (background_thread.c:625)
==3770888== by 0x527760: background_thread_ctl (ctl.c:1554)
==3770888== by 0x53C2F9: je_ctl_byname (ctl.c:1194)
==3770888== by 0x443A83: set_jemalloc_bg_thread (zmalloc.c:503)
==3770888== by 0x439418: InitServerLast (server.c:3371)
==3770888== by 0x430137: main (server.c:6385)
==3770888==
==3770888== 864 bytes in 3 blocks are possibly lost in loss record 421 of 511
==3770888== at 0x4C3721A: calloc (vg_replace_malloc.c:760)
==3770888== by 0x40129FB: _dl_allocate_tls (in /usr/lib64/ld-2.28.so)
==3770888== by 0x5D52DB2: pthread_create@@GLIBC_2.2.5 (in /usr/lib64/libpthread-2.28.so)
==3770888== by 0x49EB21: bioInit (bio.c:121)
==3770888== by 0x439408: InitServerLast (server.c:3369)
==3770888== by 0x430137: main (server.c:6385)
==3770888==
==3770888== 9,912 bytes in 6 blocks are possibly lost in loss record 492 of 511
==3770888== at 0x4C37419: realloc (vg_replace_malloc.c:834)
==3770888== by 0x4E5830: hi_realloc (alloc.h:66)
==3770888== by 0x4E5830: hi_sdsMakeRoomFor (sds.c:223)
==3770888== by 0x4E60EB: hi_sdscatlen (sds.c:381)
==3770888== by 0x4E8B24: redisReaderFeed (read.c:675)
==3770888== by 0x4E4C51: redisBufferRead (hiredis.c:944)
==3770888== by 0x56F2EA: redisSSLAsyncRead (ssl.c:480)
==3770888== by 0x4334E0: aeProcessEvents (ae.c:427)
==3770888== by 0x43373C: aeMain (ae.c:487)
==3770888== by 0x42FF48: main (server.c:6401)
==3770888==
==3770888== 54,304 bytes in 6 blocks are possibly lost in loss record 507 of 511
==3770888== at 0x4C34F0B: malloc (vg_replace_malloc.c:307)
==3770888== by 0x4E5742: hi_malloc (alloc.h:58)
==3770888== by 0x4E5742: hi_sdsMakeRoomFor (sds.c:229)
==3770888== by 0x4E60EB: hi_sdscatlen (sds.c:381)
==3770888== by 0x4E8B24: redisReaderFeed (read.c:675)
==3770888== by 0x4E4C51: redisBufferRead (hiredis.c:944)
==3770888== by 0x56F2EA: redisSSLAsyncRead (ssl.c:480)
==3770888== by 0x4334E0: aeProcessEvents (ae.c:427)
==3770888== by 0x43373C: aeMain (ae.c:487)
==3770888== by 0x42FF48: main (server.c:6401)
==3770888==
==3770888== LEAK SUMMARY:
==3770888== definitely lost: 0 bytes in 0 blocks
==3770888== indirectly lost: 0 bytes in 0 blocks
==3770888== possibly lost: 65,536 bytes in 34 blocks
==3770888== still reachable: 865,132 bytes in 3,763 blocks
==3770888== suppressed: 0 bytes in 0 blocks
Expected behavior
In general I'd expect low and constant memory usage over time as ssl contexts are set up to a maximum of the number of serviced nodes and clients. (Bonus points for reusing the ssl contexts to avoid the construction overhead next time around.)
Additional information
Since ssl contexts are quite large, the leak grows pretty fast. With 4 down nodes, 2 up nodes, and one sentinel, the sentinel grows at around 8MB per minute.
This issue won't occur when all nodes are up and well connected but when a number go down indefinitely or a network partition happens, this could potentially take down all the sentinels. On a process that's set to restart itself, it could keep working with periodic failures. In either case it will impact performance on the host machine as swapping becomes more and more time consuming until the sentinel finally crashes to clear its memory.
The large definite and indirect losses are circumvented by throwing an SSL_free into the error return of sentinel.c::instanceLinkNegotiateTLS but without looking at the rest of the code calling it, I don't know if that has any unintended consequences.
So where sentinel.c was:
static int instanceLinkNegotiateTLS(redisAsyncContext *context) {
#ifndef USE_OPENSSL
(void) context;
#else
if (!redis_tls_ctx) return C_ERR;
SSL *ssl = SSL_new(redis_tls_client_ctx ? redis_tls_client_ctx : redis_tls_ctx);
if (!ssl) return C_ERR;
if (redisInitiateSSL(&context->c, ssl) == REDIS_ERR) return C_ERR;
#endif
return C_OK;
}
I now have:
static int instanceLinkNegotiateTLS(redisAsyncContext *context) {
#ifndef USE_OPENSSL
(void) context;
#else
if (!redis_tls_ctx) return C_ERR;
SSL *ssl = SSL_new(redis_tls_client_ctx ? redis_tls_client_ctx : redis_tls_ctx);
if (!ssl) return C_ERR;
if (redisInitiateSSL(&context->c, ssl) == REDIS_ERR)
{
SSL__free(ssl);
return C_ERR;
}
#endif
return C_OK;
}
I've been running with the above change to sentinel.c for the last couple days now. Note: the valgrind logs were taken with the redis-executibles as is, without my changes. Running with the SSL_free change, the original 4-downed-nodes test now has roughly the same output as the fully connected test.
Comment From: hwware
Hey @DimensionalCode, can you share the config files you used and any other steps necessary to replicate the issue?
Comment From: DimensionalCode
I've updated the original post with the basic config info (it's all the relevant bits, the rest is just defaults I copied out of the original config files that ship with redis 6.2.6 with modified paths where needed) sans actual certs and keys. I also added my local code change for the SSL_free that has been working for me since the day after I reported this.