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

[Sergey Kandaurov]

> On 17 Sep 2022, at 01:01, Maxim Dounin <mdounin at mdounin.ru> wrote:
> 
> 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.

Ok, fair enough.

> 
>>>    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);
> 

Yeah, this is mostly cosmetics and doesn't buy anything,
but still prefer to make it explicit for completeness
and to be safe in future hypothetical changes.

-- 
Sergey Kandaurov