Logging $ssl_session_id can crash Nginx 1.5.9 worker

[mnordhoff]

I run the nginx.org mainline packages on Ubuntu 12.04, 32- and 64-bit. I use
a wacky custom log format, and after 1.5.9 was released today, I enabled
logging the $ssl_session_id variable. I later ran an SSL Labs SSL Server
Test, [0] which makes numerous HTTPS requests of various sorts, and lo and
behold, one of my worker processes core dumped. I fooled around with my
configuration and determined that the problem was logging $ssl_session_id.
If I don't log it, it's fine. If I enable a log that contains
$ssl_session_id -- even only $ssl_session_id -- it crashes.

Normal HTTPS requests -- well, I just tried curl and Firefox -- work fine. I
notice that curl does log a session ID, but for Firefox that field is just a
"-". I have no idea if that's an(other) Nginx bug or just a difference
between the two clients, but it smells funny to me. I briefly enabled
$ssl_session_id logging on 2013-12-17 with 1.5.7 or 1.5.8 and whatever
Firefox version was current at the time and it did log he session data. (I
never tried curl or SSL Labs then.)

nginx.conf: <https://mn9.us/tmp/nginx.conf> (my logging nonsense is at the
end)

Good and bad log snippets at <https://mn9.us/tmp/nginx.log> and pasted
below.

Bad:

==> /var/log/nginx/access13.log <==
173.203.79.216 36823 "www.mn9.us" 192.155.93.101 443 "mn9.us" 586 1 on
TLSv1.2 - "-" [2014-01-22T18:05:54+00:00] "GET / HTTP/1.0" 200 975 612 - "-"
"SSL Labs (https://www.ssllabs.com/about/assessment.html)" "-"
"ECDHE-RSA-AES128-SHA" "-"
173.203.79.216 36876 "-" 192.155.93.101 443 "mn9.us" 594 1 on TLSv1 - "-"
[2014-01-22T18:06:06+00:00] "HEAD
/?SSL_Labs_Renegotiation_Test=User_Agent_May_Not_Show HTTP/1.0" 400 0 0 -
"-" "SSL Labs (https://www.ssllabs.com/about/assessment.html)" "-"
"DHE-RSA-AES128-SHA" "-"

==> /var/log/nginx/error.log <==
2014/01/22 18:06:06 [notice] 24848#0: *595 SSL renegotiation disabled while
reading client request headers, client: 173.203.79.216, server: mn9.us,
request: "HEAD /?SSL_Labs_Renegotiation_Test=User_Agent_May_Not_Show
HTTP/1.0"
2014/01/22 18:06:07 [notice] 24681#0: signal 17 (SIGCHLD) received
2014/01/22 18:06:07 [alert] 24681#0: worker process 24848 exited on signal
11 (core dumped)
2014/01/22 18:06:07 [notice] 24681#0: start worker process 26865
2014/01/22 18:06:07 [notice] 24681#0: signal 29 (SIGIO) received

Good:

==> /var/log/nginx/access11.log <==
173.203.79.216 60618 "www.mn9.us" 192.155.93.101 443 "mn9.us" 1003 1 on
TLSv1.2 - "-" [2014-01-22T18:27:09+00:00] "GET / HTTP/1.0" 200 975 612 - "-"
"SSL Labs (https://www.ssllabs.com/about/assessment.html)" "-"
"ECDHE-RSA-AES128-SHA"
173.203.79.216 60701 "-" 192.155.93.101 443 "mn9.us" 1008 1 on TLSv1 - "-"
[2014-01-22T18:27:22+00:00] "HEAD
/?SSL_Labs_Renegotiation_Test=User_Agent_May_Not_Show HTTP/1.0" 400 0 0 -
"-" "SSL Labs (https://www.ssllabs.com/about/assessment.html)" "-"
"DHE-RSA-AES128-SHA"

==> /var/log/nginx/error.log <==
2014/01/22 18:27:22 [notice] 27156#0: *1009 SSL renegotiation disabled while
reading client request headers, client: 173.203.79.216, server: mn9.us,
request: "HEAD /?SSL_Labs_Renegotiation_Test=User_Agent_May_Not_Show
HTTP/1.0"

==> /var/log/nginx/access11.log <==
173.203.79.216 60948 "-" 192.155.93.101 443 "mn9.us" 1009 1 on TLSv1.2 - "-"
[2014-01-22T18:27:22+00:00] "HEAD
/?SSL_Labs_Renegotiation_Test=User_Agent_May_Not_Show HTTP/1.0" 400 0 0 -
"-" "SSL Labs (https://www.ssllabs.com/about/assessment.html)" "-" "(NONE)"

[0] <https://www.ssllabs.com/ssltest/index.html>

Cheers
--

Posted at Nginx Forum: http://forum.nginx.org/read.php?2,246716,246716#msg-246716