I am using stunnel v5.32 compiled on a RHEL 6.7 with openssl-1.0.1e-42.el6.x86_64.
The stunnel.conf cache settings are (for testing cache behaviour):
*sessionCacheSize = 3sessionCacheTimeout = 60* What I expect is that after sessioncache size is reached, the memory (RSS) allocated to stunnel process does not grow with new sessions which are not in cache. Instead of this the stunnel allocates about 28K for any new session which does not have a stored session in cache and does not free this anymore. For new connections, but with session stored in cache, the memory does not grow. This lead me to a problem in memory deallocation for expired session in internal session cache.( I know that openssl frees expired session cache entries at every 255 sessions).
See example below: --> stunnel start (see RSS) USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND stunnel 20655 0.0 0.0 117760 1440 ? Ss 15:49 0:00 /usr/local/bin/stunnel5 --> after 3 sessions with no cache hits stunnel 20655 0.0 0.0 117828 2976 ? Ss 15:49 0:00 /usr/local/bin/stunnel5 - stunnel log 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: New session callback 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 4 server accept(s) requested 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 4 server accept(s) succeeded 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 0 server renegotiation(s) requested 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 0 session reuse(s) 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 3 internal session cache item(s) 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 0 internal session cache fill-up(s) 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 0 internal session cache miss(es) 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 0 external session cache hit(s) 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: 0 expired session(s) retrieved 2016.05.11 15:50:57 LOG6[kngHAM6DLUpVRXEqHcUMIt]: SSL accepted: new session negotiated 2016.05.11 15:50:57 LOG7[kngHAM6DLUpVRXEqHcUMIt]: Remove session callback ----------------------------------------------------- --> after another 1 request with cache hit: as you can see no RSS memory was added stunnel 20655 0.0 0.0 117828 2976 ? Ss 15:49 0:00 /usr/local/bin/stunnel5 - stunnel log 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: SSL state (accept): SSLv3 read finished A 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 5 server accept(s) requested 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 5 server accept(s) succeeded 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 0 server renegotiation(s) requested 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 1 session reuse(s) 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 3 internal session cache item(s) 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 1 internal session cache fill-up(s) 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 0 internal session cache miss(es) 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 0 external session cache hit(s) 2016.05.11 15:51:57 LOG7[Slq6WdqS97Ox4G8eOKfGg0]: 0 expired session(s) retrieved 2016.05.11 15:51:57 LOG6[Slq6WdqS97Ox4G8eOKfGg0]: SSL accepted: previous session reused ---------------------------------------------------- --> after another 1 request with no cache hit (now we have the first cache fill-up) stunnel 20655 0.0 0.0 117828 3000 ? Ss 15:49 0:00 /usr/local/bin/stunnel5
- stunnel log 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: New session callback 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 6 server accept(s) requested 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 6 server accept(s) succeeded 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 0 server renegotiation(s) requested 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 1 session reuse(s) 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 3 internal session cache item(s) 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 1 internal session cache fill-up(s) 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 0 internal session cache miss(es) 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 0 external session cache hit(s) 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: 0 expired session(s) retrieved 2016.05.11 15:53:31 LOG6[P8n33mFxzHVAZEeRwnFccK]: SSL accepted: new session negotiated 2016.05.11 15:53:31 LOG7[P8n33mFxzHVAZEeRwnFccK]: Remove session callback ---------------------------------------------------- --> after another 300 new session with no cache hits and after waiting 1 minute for entries in session cache to expire (as said in documentation openssl must free expired entries every 255 sessions) stunnel 20655 0.0 0.2 117828 11632 ? Ss 15:49 0:03 /usr/local/bin/stunnel5
- stunnel log 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: New session callback 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 306 server accept(s) requested 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 306 server accept(s) succeeded 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 0 server renegotiation(s) requested 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 1 session reuse(s) 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 3 internal session cache item(s) 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 301 internal session cache fill-up(s) 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 0 internal session cache miss(es) 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 0 external session cache hit(s) 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: 0 expired session(s) retrieved 2016.05.11 16:13:26 LOG6[vWvoFT1DXuJ9x0eEfFnQBf]: SSL accepted: new session negotiated 2016.05.11 16:13:26 LOG7[vWvoFT1DXuJ9x0eEfFnQBf]: Remove session callback
----------------------------------------------------
What I can see is tat memory grows with ~28K for every new session after session cache was filled and never deallocates this memory. In my production env. this really creates problems because after 2 weeks stunnel fils all 32GB of server RAM.
*Anyone has encountered a similar problem? *
Of course the stunnel service restart clears the memory but I loose all cache entries and is not acceptable.
After some code analysis between different versions of stunnel I can see that between v5.26 ans v5.27 the ctx callbacks functions was changed. In my tests with versions prior to 5.27 I can see that this memory problems does not appear. See logs below:
---- stunnel v5.26 -------- 2016.05.12 13:08:14 LOG5[ui]: stunnel 5.26 on x86_64-unknown-linux-gnu platform 2016.05.12 13:08:14 LOG5[ui]: Compiled/running with OpenSSL 1.0.1e-fips 11 Feb 2013
stunnel 27402 0.0 0.0 117604 1316 ? Ss 13:08 0:00 /usr/local/bin/stunnel5 stunnel 27402 0.0 0.0 117672 2756 ? Ss 13:08 0:00 /usr/local/bin/stunnel5 stunnel 27402 0.0 0.0 117672 2804 ? Ss 13:08 0:00 /usr/local/bin/stunnel5 stunnel 27402 0.0 0.0 117672 2828 ? Ss 13:08 0:00 /usr/local/bin/stunnel5 stunnel 27402 0.0 0.0 117672 2868 ? Ss 13:08 0:00 /usr/local/bin/stunnel5 cache fill-up 2016.05.12 13:11:01 LOG7[FdNYw7uGlV9xNElZSPBfyh]: 0 session reuse(s) 2016.05.12 13:11:01 LOG7[FdNYw7uGlV9xNElZSPBfyh]: 3 internal session cache item(s) 2016.05.12 13:11:01 LOG7[FdNYw7uGlV9xNElZSPBfyh]: 1 internal session cache fill-up(s)
stunnel 27402 0.0 0.0 117672 2868 ? Ss 13:08 0:00 /usr/local/bin/stunnel5 stunnel 27402 0.0 0.0 117672 2868 ? Ss 13:08 0:00 /usr/local/bin/stunnel5 after 100 fill-ups 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: SSL state (accept): SSLv3 flush data 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 107 server accept(s) requested 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 107 server accept(s) succeeded 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 0 server renegotiation(s) requested 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 1 session reuse(s) 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 3 internal session cache item(s) 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 102 internal session cache fill-up(s) 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 0 internal session cache miss(es) 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 0 external session cache hit(s) 2016.05.12 13:13:55 LOG7[TWO1OFFPYvsW4qdjyJ0IZK]: 0 expired session(s) retrieved 2016.05.12 13:13:55 LOG6[TWO1OFFPYvsW4qdjyJ0IZK]: SSL accepted: new session negotiated
stunnel 27402 0.1 0.0 117672 2872 ? Ss 13:08 0:00 /usr/local/bin/stunnel5
after another 100 fill-ups 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: SSL state (accept): SSLv3 flush data 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 207 server accept(s) requested 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 207 server accept(s) succeeded 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 0 server renegotiation(s) requested 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 1 session reuse(s) 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 3 internal session cache item(s) 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 202 internal session cache fill-up(s) 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 0 internal session cache miss(es) 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 0 external session cache hit(s) 2016.05.12 13:19:03 LOG7[InwkBBOxJrfptxYx6wXTxU]: 0 expired session(s) retrieved 2016.05.12 13:19:03 LOG6[InwkBBOxJrfptxYx6wXTxU]: SSL accepted: new session negotiated
stunnel 27402 0.0 0.0 117672 2872 ? Ss 13:08 0:01 /usr/local/bin/stunnel5
Code: --->>> callbacks in v5.26 L605
*NOEXPORT int sess_new_cb(SSL *ssl, SSL_SESSION *sess) { unsigned char *val, *val_tmp; ssize_t val_len; const unsigned char *session_id; unsigned int session_id_length; val_len=i2d_SSL_SESSION(sess, NULL); val_tmp=val=str_alloc((size_t)val_len); i2d_SSL_SESSION(sess, &val_tmp);#if OPENSSL_VERSION_NUMBER>=0x0090800fL session_id=SSL_SESSION_get_id(sess, &session_id_length);#else session_id=(const unsigned char *)sess->session_id; session_id_length=sess->session_id_length;#endif cache_transfer(SSL_get_SSL_CTX(ssl), CACHE_CMD_NEW, SSL_SESSION_get_timeout(sess), session_id, session_id_length, val, (size_t)val_len, NULL, NULL); str_free(val); return 1; /* leave the session in local cache for reuse */}NOEXPORT SSL_SESSION *sess_get_cb(SSL *ssl, unsigned char *key, int key_len, int *do_copy) { unsigned char *val, *val_tmp=NULL; ssize_t val_len=0; SSL_SESSION *sess; *do_copy = 0; /* allow the session to be freed autmatically */ cache_transfer(SSL_get_SSL_CTX(ssl), CACHE_CMD_GET, 0, key, (size_t)key_len, NULL, 0, &val, (size_t *)&val_len); if(!val) return NULL; val_tmp=val; sess=d2i_SSL_SESSION(NULL,#if OPENSSL_VERSION_NUMBER>=0x0090800fL (const unsigned char **)#endif /* OpenSSL version >= 0.8.0 */ &val_tmp, val_len); str_free(val);*
--->>> callbacks in v5.32 /**************************************** session callbacks */
*NOEXPORT int sess_new_cb(SSL *ssl, SSL_SESSION *sess) { CLI *c; s_log(LOG_DEBUG, "New session callback"); c=SSL_get_ex_data(ssl, index_cli); if(c->opt->option.sessiond) cache_new(ssl, sess); return 1; /* leave the session in local cache for reuse */}NOEXPORT SSL_SESSION *sess_get_cb(SSL *ssl,#if OPENSSL_VERSION_NUMBER>=0x10100000L const#endif unsigned char *key, int key_len, int *do_copy) { CLI *c; s_log(LOG_DEBUG, "Get session callback"); *do_copy=0; /* allow the session to be freed automatically */ c=SSL_get_ex_data(ssl, index_cli); if(c->opt->option.sessiond) return cache_get(ssl, key, key_len); return NULL; /* no session to resume */}NOEXPORT void sess_remove_cb(SSL_CTX *ctx, SSL_SESSION *sess) { SERVICE_OPTIONS *opt; s_log(LOG_DEBUG, "Remove session callback"); opt=SSL_CTX_get_ex_data(ctx, index_opt); if(opt->option.sessiond) cache_remove(ctx, sess);}*
In production env. I have downgraded today at stunnel v5.26 and memory seems to be OK (untill now).
Regards,
Adrian Irimescu