[stunnel-users] stunnel v5.32 (and older) strange session cache behavior on memory (de)allocation

Adrian Irimescu adrian.irimescu.iri at gmail.com
Mon May 16 09:42:22 CEST 2016


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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.stunnel.org/pipermail/stunnel-users/attachments/20160516/99b76b51/attachment.html>


More information about the stunnel-users mailing list