[PATCH 02 of 11] SSL: reduced logging of session cache failures (ticket #621)

[Maxim Dounin]

Hello!

On Thu, Sep 15, 2022 at 09:37:17AM +0400, Sergey Kandaurov wrote:

> > On 26 Aug 2022, at 07:01, Maxim Dounin <mdounin at mdounin.ru> wrote:
> > 
> > # HG changeset patch
> > # User Maxim Dounin <mdounin at mdounin.ru>
> > # Date 1661481947 -10800
> > #      Fri Aug 26 05:45:47 2022 +0300
> > # Node ID 5b137f110e84af974ef2b9efcf35bec2d883c187
> > # Parent  2cd8fbeb4edc5a99b725585edc02a16a8a0c503e
> > SSL: reduced logging of session cache failures (ticket #621).
> > 
> > Session cache allocations might fail as long as the new session is different
> > in size from the one least recently used (and freed when the first allocation
> > fails).  In particular, it might not be possible to allocate space for
> > sessions with client certificates, since they are noticeably bigger than
> > normal sessions.
> > 
> > To ensure such allocation failures won't clutter logs, logging level changed
> > to "warn", and logging is now limited to at most one warning per second.
> > 
> > diff --git a/src/event/ngx_event_openssl.c b/src/event/ngx_event_openssl.c
> > --- a/src/event/ngx_event_openssl.c
> > +++ b/src/event/ngx_event_openssl.c
> > @@ -3949,8 +3949,11 @@ failed:
> > 
> >     ngx_shmtx_unlock(&shpool->mutex);
> > 
> > -    ngx_log_error(NGX_LOG_ALERT, c->log, 0,
> > -                  "could not allocate new session%s", shpool->log_ctx);
> > +    if (cache->fail_time != ngx_time()) {
> > +        cache->fail_time = ngx_time();
> > +        ngx_log_error(NGX_LOG_WARN, c->log, 0,
> > +                      "could not allocate new session%s", shpool->log_ctx);
> > +    }
> > 
> 
> This makes three ngx_time() calls in this function in total.
> A good reason to cache value in a local variable.

Well, not really.

This is an error code path, which is not normally used.  In the 
hot path, there is still just one ngx_time() call.  Trying to 
provide appropriate cached value in all cases where this error 
path is followed means that it have to be done at the very start 
of the function, and it is going to make the function less 
readable, and might actually make it less optimal.

Further, the

    if (fail_time != ngx_time()) {
        fail_time = ngx_time();
        ...
    }

pattern is used elsewhere, and I would rather keep the code 
similar in all cases.

Not to mention that ngx_time() is not really a call, but rather a 
macro, which expands to ngx_cached_time->sec.  While it might be 
beneficial to cache the value if it is used multiple times, since 
ngx_cached_time is volatile, the performance impact is minimal.

> >     return 0;
> > }
> > diff --git a/src/event/ngx_event_openssl.h b/src/event/ngx_event_openssl.h
> > --- a/src/event/ngx_event_openssl.h
> > +++ b/src/event/ngx_event_openssl.h
> > @@ -150,6 +150,7 @@ typedef struct {
> >     ngx_rbtree_t                session_rbtree;
> >     ngx_rbtree_node_t           sentinel;
> >     ngx_queue_t                 expire_queue;
> > +    time_t                      fail_time;
> > } ngx_ssl_session_cache_t;
> > 
> 
> Missed initialization to something sensible (zero?).

It doesn't really matter here, but won't hurt anyway.  Added the following
chunk:

diff --git a/src/event/ngx_event_openssl.c b/src/event/ngx_event_openssl.c
--- a/src/event/ngx_event_openssl.c
+++ b/src/event/ngx_event_openssl.c
@@ -3770,6 +3770,8 @@ ngx_ssl_session_cache_init(ngx_shm_zone_
 
     ngx_queue_init(&cache->expire_queue);
 
+    cache->fail_time = 0;
+
     len = sizeof(" in SSL session shared cache \"\"") + shm_zone->shm.name.len;
 
     shpool->log_ctx = ngx_slab_alloc(shpool, len);

-- 
Maxim Dounin
http://mdounin.ru/