Discussion:
[stunnel-users] stunnel v5.32 (and older) strange session cache behavior on memory (de)allocation
(too old to reply)
Adrian Irimescu
2016-05-16 07:42:22 UTC
Permalink
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
Michał Trojnara
2016-05-16 19:45:03 UTC
Permalink
Post by Adrian Irimescu
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.
Please try:
https://www.stunnel.org/downloads/beta/stunnel-5.33b2.tar.gz
In my tests this fixes the memory leak you reported.

Best regards,
Mike
Adrian Irimescu
2016-05-20 08:24:12 UTC
Permalink
Hi,
I've done some tests with stunnel v5.33b2 and I can confirm that this
version fixes the memory leak I reported (and after the session cache is
filled with entries, stunnel does not allocate more memory for next
sessions).

One more question: do you have any recommendation for session cache size?
On my systems I have set this to 30000. I have 32 GB of RAM so the memory
is not the problem. My concerns are about time spent to search for entries
in cache if I grow session cache size over 100000 entries.

Thank you for your response.

Best Regards,
Adrian Irimescu

On Mon, May 16, 2016 at 10:45 PM, Michał Trojnara <
Post by Michał Trojnara
Post by Adrian Irimescu
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.
https://www.stunnel.org/downloads/beta/stunnel-5.33b2.tar.gz
In my tests this fixes the memory leak you reported.
Best regards,
Mike
_______________________________________________
stunnel-users mailing list
https://www.stunnel.org/cgi-bin/mailman/listinfo/stunnel-users
Loading...