search

openssl / openssl

TLS/SSL and crypto library
https://www.openssl.org
Apache License 2.0
24.89k stars 9.93k forks source link

SSL Routines: SSL shutdown: Shutdown while init #13897

Open jaripog opened 3 years ago

jaripog commented 3 years ago

Reproduction steps IDPprovider: Auth0, Protocol: SAML 2.0, while logging in intermittently we are facing this error internal server error 500 in the apache level.

the debug log is below [Fri Jan 08 10:00:49.238914 2021] [ssl:info] [pid 4129:tid 140534936950528] [client 172.19.19.184:54012] AH01992: SSL library error 1 reading data [Fri Jan 08 10:00:49.238937 2021] [ssl:info] [pid 4129:tid 140534936950528] SSL Library Error: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init [ 2021-01-08 10:00:49.2390 4129/7fd0d6fed700 apache2/Hooks.cpp:732 ]: Unexpected error in mod_passenger: An error occurred while receiving HTTP upload data: Internal error (specific information not available) (20014) Backtrace: in 'boost::shared_ptrPassenger::BufferedUpload Hooks::receiveRequestBody(request_rec)' (Hooks.cpp:1190) in 'int Hooks::handleRequest(request_rec)' (Hooks.cpp:546)

Expected behavior SSL handshake should be successful

Actual behavior out of 10 logins attempts 1, is failure login which SSL is causing this

Operating system(s) tested centos 7 , Ruby 2.7.1 Phusion Passenger - 4.0.59 OpenSSL 1.0.2k-fips 26 Jan 2017

Sample image 1

mattcaswell commented 3 years ago

[Fri Jan 08 10:00:49.238937 2021] [ssl:info] [pid 4129:tid 140534936950528] SSL Library Error: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init

This means that the application called the the OpenSSL API SSL_shutdown, but the handshake was not complete and so it was not a valid time to call SSL_shutdown.

[Fri Jan 08 10:00:49.238914 2021] [ssl:info] [pid 4129:tid 140534936950528] [client 172.19.19.184:54012] AH01992: SSL library error 1 reading data

This sounds like the start of the problems. What was the "error reading data" that causes this log message?

jaripog commented 3 years ago

don't know. how to get more details on this 'error reading data'?

this issue happens during login, the interaction is between a SAML provider and apache, the catch here is IdP is able to send the Success SAML response and after couple of seconds refreshing the browser doesn't bring up the errors

Please guide.

mattcaswell commented 3 years ago

don't know. how to get more details on this 'error reading data'?

You need to investigate whatever application it was that generated that log message. The log message isn't coming directly from OpenSSL, although it could be the result of an OpenSSL API error. "SSL library error 1" sounds like it could be referring to SSL_ERROR_SSL (which has a value of 1) - which can be returned for some IO failures. If so then we need to get the application to print the OpenSSL error stack information to get more information about what caused it. The logging data doesn't have the full error details.

jaripog commented 3 years ago

how do i make my application to print the SSL(stack trace) error as it is not reaching my application, are u suggesting changing the logging way of SSL engine code?

or is there is any way to print the SSL error ( stack trace ) at the apache level.

mattcaswell commented 3 years ago

or is there is any way to print the SSL error ( stack trace ) at the apache level.

That I don't know - I don't know apache (BTW its not actually a stack trace we're after here, but the OpenSSL error stack, which is slightly different). But I can only guide you from an OpenSSL perspective of the information we need to get. Maybe there is some apache way of getting more verbose logging??

jaripog commented 3 years ago

We have enabled the trace8 verbose logging for ssl and we are able to see that SSL handshake is failing because of I/O error. Please find the attachment for more details regarding ssl BIOdump. Herwith i have added the Log

PLease guide

Wed Jan 20 10:03:37.428354 2021] [ssl:trace4] [pid 4201:tid 140713345849088] ssl_engine_io.c(2128): [client 172.19.19.184:56762] OpenSSL: I/O error, 5 bytes expected to read on BIO#7ffa30000ff0 [mem: 7ffa4c0072d3] [Wed Jan 20 10:03:37.428367 2021] [ssl:info] [pid 4201:tid 140713345849088] [client 172.19.19.184:56762] AH01992: SSL library error 1 reading data [Wed Jan 20 10:03:37.428391 2021] [ssl:info] [pid 4201:tid 140713345849088] SSL Library Error: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init [ E 2021-01-20 10:03:37.4285 4201/T0 apa/Hooks.cpp:751 ]: Unexpected error in mod_passenger : An error occurred while receiving HTTP upload data: Internal error (specific information not available) (20014) Backtrace: in 'void Passenger::Apache2Module::Hooks::sendRequestBody(const Passenger::FileDescriptor&, request_rec, bool)' (Hooks.cpp:1230) in 'int Passenger::Apache2Module::Hooks::handleRequest(request_rec)' (Hooks.cpp:622)

masked.txt

mattcaswell commented 3 years ago

Unfortunately I don't think this tells us much more than we knew before - although perhaps a bit. This line:

[Wed Jan 20 10:03:37.428354 2021] [ssl:trace4] [pid 4201:tid 140713345849088] ssl_engine_io.c(2128): [client 172.19.19.184:56762] OpenSSL: I/O error, 5 bytes expected to read on BIO#7ffa30000ff0 [mem: 7ffa4c0072d3]

Looks like trace logging saying that an attempt was made to read 5 bytes of data. That log line seems to come from here:

https://github.com/omnigroup/Apache/blob/526ef6bb9f1988be6583cecea96598b6cb1b0d6b/httpd/modules/ssl/ssl_engine_io.c#L2021-L2025

I can see from that that all we can learn from this is that an attempt was made and it failed. That failure is not necessarily fatal in itself and is independent of the subsequent "shutdown while init" line. Sometime between that IO error occurring and the subsequent "shutdown while init" error, the application has decided to shutdown the connection for unknown reasons (possibly because of the IO error, possibly not). The shutdown attempt failed because the connection is "in init" - meaning it is in (or has not yet started) a handshake. That is a little weird because it can be clearly seen earlier in the log that application data is being transferred over the connection. So either we are now attempting a renegotiation (i.e. gone back into handshake), or something else strange has happened to the state of the SSL object.

Either way, nothing so far makes me think this is a problem in OpenSSL itself. I'd suggest raising an issue with Apache.

nhorman commented 3 weeks ago

Marking as inactive, to be closed at the end of the 3.4 dev cycle barring further input