$ssl_protocol in nodejs POST requests after 1.9.4

[Maxim Dounin]

Hello!

On Sat, May 08, 2021 at 07:33:07PM +0300, Reinis Rozitis wrote:

> Hello.
> I have a strange issue where for a POST request having any form data Nginx
> after version 1.9.4 doesn't log $ssl_protocol (or any other $ssl_*)
> variable.
> 
> 
> I have a configured custom accesslog:
> 
> log_format main '... $ssl_protocol $ssl_cipher $server_port';
> 
> A simple script ( for example from
> https://nodejs.dev/learn/make-an-http-post-request-using-nodejs ) will
> generate following accesslog entry with all the variables being empty:
> 
> [08/May/2021:19:11:50 +0300] ...  "axios/0.21.1" - - 443
> 
> 
> The moment you remove the form data everything is being logged:
> 
> [08/May/2021:19:10:58 +0300] ...  HTTP/1.1" 200 772 "-" "axios/0.21.1"
> TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 443
> 
> 
> I tried to debug the requests and see the difference (besides
> Content-Length) but I wasn't able to pinpoint the issue. 
> I tried various nodejs libraries ('request' etc) and also native approach -
> all produce same results - empty POST requests are fine, the moment you post
> any form data the $ssl_* become empty.
> I can't reproduce it with curl - tried varios requests with and without
> data, with chunked encoding etc - everything is being logged as expected.
> 
> 
> One could say that the problem is on the Node side - but what has changed
> between 1.9.4 and 1.9.5 that breaks the logging? 
> 
> Maybe someone has any suggestions or ideas how to investigate this further?

Thanks for the report, it looks like this change broke things:

changeset:   7738:554c6ae25ffc
user:        Ruslan Ermilov <ru at nginx.com>
date:        Fri Nov 06 23:44:54 2020 +0300
summary:     SSL: fixed non-working SSL shutdown on lingering close.

If the connection is being closed with lingering close, nginx now 
shuts down the SSL connection before lingering close, and this 
happens before the request is logged.  As a result $ssl_* 
variables are not available during request logging.

An easy way to reproduce this with arbitrary requests is to use 
"lingering_close always;".

The only fix I can think of is to rewrite the lingering close so 
it will happen after the request is logged.

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