Error-like LOG when connecting with SSL for password authentication

Started by Michael Paquierover 8 years ago10 messages
#1Michael Paquier
michael.paquier@gmail.com
1 attachment(s)

Hi all,

When attempting to connect using password authentication through SSL,
the backend will complain in its log with the following entry before
calling sendAuthRequest(), which asks the client for a password:
LOG: could not receive data from client: Connection reset by peer

After a short talk with Heikki, it seems that be_tls_read() complains
on SSL_ERROR_ZERO_RETURN, which is documented here:
https://wiki.openssl.org/index.php/Manual:SSL_get_error(3)
The TLS/SSL connection has been closed. If the protocol version is SSL
3.0 or TLS 1.0, this result code is returned only if a closure alert
has occurred in the protocol, i.e. if the connection has been closed
cleanly. Note that in this case SSL_ERROR_ZERO_RETURN does not
necessarily indicate that the underlying transport has been closed.

As this is a clean shutdown of the SSL connection, shouldn't
be_tls_read() return 0 to the caller instead of -1? This would map
with what the non-SSL code path does for raw reads.

This is basically harmless, but the error message is confusing I
think, and there is no equivalent for the non-SSL code path.

Attached is an idea of patch.
Thoughts?
--
Michael

Attachments:

ssl-read-commerr.patchapplication/octet-stream; name=ssl-read-commerr.patchDownload
diff --git a/src/backend/libpq/be-secure-openssl.c b/src/backend/libpq/be-secure-openssl.c
index 44c84a7869..5aace0eb78 100644
--- a/src/backend/libpq/be-secure-openssl.c
+++ b/src/backend/libpq/be-secure-openssl.c
@@ -688,11 +688,13 @@ be_tls_read(Port *port, void *ptr, size_t len, int *waitfor)
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
 					 errmsg("SSL error: %s", SSLerrmessage(ecode))));
-			/* fall through */
-		case SSL_ERROR_ZERO_RETURN:
 			errno = ECONNRESET;
 			n = -1;
 			break;
+		case SSL_ERROR_ZERO_RETURN:
+			/* connection was cleanly shut down by peer */
+			n = 0;
+			break;
 		default:
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
@@ -748,11 +750,13 @@ be_tls_write(Port *port, void *ptr, size_t len, int *waitfor)
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
 					 errmsg("SSL error: %s", SSLerrmessage(ecode))));
-			/* fall through */
-		case SSL_ERROR_ZERO_RETURN:
 			errno = ECONNRESET;
 			n = -1;
 			break;
+		case SSL_ERROR_ZERO_RETURN:
+			/* connection was cleanly shut down by peer */
+			n = 0;
+			break;
 		default:
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
diff --git a/src/interfaces/libpq/fe-secure-openssl.c b/src/interfaces/libpq/fe-secure-openssl.c
index a7c3d7af64..d14d7497c9 100644
--- a/src/interfaces/libpq/fe-secure-openssl.c
+++ b/src/interfaces/libpq/fe-secure-openssl.c
@@ -261,12 +261,12 @@ rloop:
 			/*
 			 * Per OpenSSL documentation, this error code is only returned for
 			 * a clean connection closure, so we should not report it as a
-			 * server crash.
+			 * server crash. Similarly to the non-SSL code path, this is
+			 * equivalent to nothing received to adapt accordindly.
 			 */
 			printfPQExpBuffer(&conn->errorMessage,
 			 libpq_gettext("SSL connection has been closed unexpectedly\n"));
-			result_errno = ECONNRESET;
-			n = -1;
+			n = 0;
 			break;
 		default:
 			printfPQExpBuffer(&conn->errorMessage,
@@ -370,12 +370,12 @@ pgtls_write(PGconn *conn, const void *ptr, size_t len)
 			/*
 			 * Per OpenSSL documentation, this error code is only returned for
 			 * a clean connection closure, so we should not report it as a
-			 * server crash.
+			 * server crash. Similarly to the non-SSL code path, this is
+			 * equivalent to nothing received to adapt accordindly.
 			 */
 			printfPQExpBuffer(&conn->errorMessage,
 			 libpq_gettext("SSL connection has been closed unexpectedly\n"));
-			result_errno = ECONNRESET;
-			n = -1;
+			n = 0;
 			break;
 		default:
 			printfPQExpBuffer(&conn->errorMessage,
#2Vaishnavi Prabakaran
vaishnaviprabakaran@gmail.com
In reply to: Michael Paquier (#1)
Re: Error-like LOG when connecting with SSL for password authentication

On Mon, May 22, 2017 at 5:10 PM, Michael Paquier <michael.paquier@gmail.com>
wrote:

If the protocol version is SSL
3.0 or TLS 1.0, this result code is returned only if a closure alert
has occurred in the protocol, i.e. if the connection has been closed
cleanly. Note that in this case SSL_ERROR_ZERO_RETURN does not
necessarily indicate that the underlying transport has been closed.

I guess this error code exist even for SSL2 protocol, In that case, don't
we need to keep the current code for this error code?

Regards,
Vaishnavi,
Fujitsu Australia.

#3Heikki Linnakangas
hlinnaka@iki.fi
In reply to: Michael Paquier (#1)
Re: Error-like LOG when connecting with SSL for password authentication

On 05/22/2017 03:10 AM, Michael Paquier wrote:

Hi all,

When attempting to connect using password authentication through SSL,
the backend will complain in its log with the following entry before
calling sendAuthRequest(), which asks the client for a password:
LOG: could not receive data from client: Connection reset by peer

After a short talk with Heikki, it seems that be_tls_read() complains
on SSL_ERROR_ZERO_RETURN, which is documented here:
https://wiki.openssl.org/index.php/Manual:SSL_get_error(3)
The TLS/SSL connection has been closed. If the protocol version is SSL
3.0 or TLS 1.0, this result code is returned only if a closure alert
has occurred in the protocol, i.e. if the connection has been closed
cleanly. Note that in this case SSL_ERROR_ZERO_RETURN does not
necessarily indicate that the underlying transport has been closed.

As this is a clean shutdown of the SSL connection, shouldn't
be_tls_read() return 0 to the caller instead of -1? This would map
with what the non-SSL code path does for raw reads.

Yeah. The be_tls_read() change looks OK to me.

Can SSL_ERROR_ZERO_RETURN also happen in a write? I suppose it can, but
returning 0 from secure_write() seems iffy. My man page for send(2)
doesn't say that it would return 0 if the connection has been closed by
the peer, so that would be different from the non-SSL codepath. Looking
at the only caller to secure_write(), it does check for 0, and would
treat it correctly as EOF, so it would work. But it makes me a bit
nervous, a comment in secure_write() at least would be in order, to
point out that it can return 0 to indicate EOF, unlike the raw write(2)
or send(2) system functions.

In libpq, do we want to set the "SSL connection has been closed
unexpectedly" message? In the non-SSL case, pqsecure_raw_read() doesn't
set any error message on EOF. Also, even though the comment in
pgtls_read() says "... we should not report it as a server crash",
looking at pqReadData, ISTM that returning 0 will in fact lead to the
"server closed the connection unexpectedly" message. And it seems like a
good assumption anyway, that the server did in fact terminate
abnormally, if that happens. We don't expect the server to disconnect
the client without notice, even though it's not unusual for the client
to disconnect without notifying the server.

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#4Heikki Linnakangas
hlinnaka@iki.fi
In reply to: Vaishnavi Prabakaran (#2)
Re: Error-like LOG when connecting with SSL for password authentication

On 05/22/2017 10:11 PM, Vaishnavi Prabakaran wrote:

On Mon, May 22, 2017 at 5:10 PM, Michael Paquier <michael.paquier@gmail.com>
wrote:

If the protocol version is SSL
3.0 or TLS 1.0, this result code is returned only if a closure alert
has occurred in the protocol, i.e. if the connection has been closed
cleanly. Note that in this case SSL_ERROR_ZERO_RETURN does not
necessarily indicate that the underlying transport has been closed.

I guess this error code exist even for SSL2 protocol, In that case, don't
we need to keep the current code for this error code?

If I understand correctly, with SSLv2, SSL_ERROR_ZERO_RETURN does mean
that the underlying transport has been closed. Returning 0 seems
appropriate in that case, too.

But the point is moot anyway, because PostgreSQL doesn't allow SSLv2
anymore.

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#5Michael Paquier
michael.paquier@gmail.com
In reply to: Heikki Linnakangas (#4)
Re: Error-like LOG when connecting with SSL for password authentication

On Tue, May 23, 2017 at 6:36 AM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:

On 05/22/2017 10:11 PM, Vaishnavi Prabakaran wrote:

On Mon, May 22, 2017 at 5:10 PM, Michael Paquier
<michael.paquier@gmail.com>
wrote:

If the protocol version is SSL
3.0 or TLS 1.0, this result code is returned only if a closure alert
has occurred in the protocol, i.e. if the connection has been closed
cleanly. Note that in this case SSL_ERROR_ZERO_RETURN does not
necessarily indicate that the underlying transport has been closed.

I guess this error code exist even for SSL2 protocol, In that case, don't
we need to keep the current code for this error code?

If I understand correctly, with SSLv2, SSL_ERROR_ZERO_RETURN does mean that
the underlying transport has been closed. Returning 0 seems appropriate in
that case, too.

Am I reading the docs incorrectly then? I understand that with SSLv2
the transport may not be closed after SSL_ERROR_ZERO_RETURN.

But the point is moot anyway, because PostgreSQL doesn't allow SSLv2
anymore.

And SSL_OP_NO_SSLv2 is enforced anyway.

Side note.. Looking at the openssl docs, I am just noticing that
SSLv23_method has been marked as deprecated in 1.1.0:
https://www.openssl.org/docs/man1.1.0/ssl/SSLv23_method.html
And has been replaced by TLS_method. Something to keep in mind.
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#6Michael Paquier
michael.paquier@gmail.com
In reply to: Heikki Linnakangas (#3)
1 attachment(s)
Re: Error-like LOG when connecting with SSL for password authentication

On Tue, May 23, 2017 at 6:26 AM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:

Yeah. The be_tls_read() change looks OK to me.

Can SSL_ERROR_ZERO_RETURN also happen in a write? I suppose it can, but
returning 0 from secure_write() seems iffy.

It seems to me that it could be the case, the man page of SSL_write
tells me that:
0 The write operation was not successful. Probably the
underlying connection was closed. Call SSL_get_error() with the return
value ret to find out, whether an error occurred or the connection was
shut down cleanly (SSL_ERROR_ZERO_RETURN).

My man page for send(2) doesn't
say that it would return 0 if the connection has been closed by the peer, so
that would be different from the non-SSL codepath.

errno maps to ECONNRESET in this case. So send() can return 0 only if
the caller has specified 0 as the number of bytes to send?

Looking at the only
caller to secure_write(), it does check for 0, and would treat it correctly
as EOF, so it would work. But it makes me a bit nervous, a comment in
secure_write() at least would be in order, to point out that it can return 0
to indicate EOF, unlike the raw write(2) or send(2) system functions.

Yep. Agreed. Hopefully improved in the attached.

In libpq, do we want to set the "SSL connection has been closed
unexpectedly" message?

Perhaps not.

In the non-SSL case, pqsecure_raw_read() doesn't set
any error message on EOF. Also, even though the comment in pgtls_read() says
"... we should not report it as a server crash", looking at pqReadData, ISTM
that returning 0 will in fact lead to the "server closed the connection
unexpectedly" message. And it seems like a good assumption anyway, that the
server did in fact terminate abnormally, if that happens. We don't expect
the server to disconnect the client without notice, even though it's not
unusual for the client to disconnect without notifying the server.

Yes.

Attached is an updated patch.
--
Michael

Attachments:

ssl-read-commerr-v2.patchapplication/octet-stream; name=ssl-read-commerr-v2.patchDownload
diff --git a/src/backend/libpq/be-secure-openssl.c b/src/backend/libpq/be-secure-openssl.c
index 44c84a7869..5aace0eb78 100644
--- a/src/backend/libpq/be-secure-openssl.c
+++ b/src/backend/libpq/be-secure-openssl.c
@@ -688,11 +688,13 @@ be_tls_read(Port *port, void *ptr, size_t len, int *waitfor)
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
 					 errmsg("SSL error: %s", SSLerrmessage(ecode))));
-			/* fall through */
-		case SSL_ERROR_ZERO_RETURN:
 			errno = ECONNRESET;
 			n = -1;
 			break;
+		case SSL_ERROR_ZERO_RETURN:
+			/* connection was cleanly shut down by peer */
+			n = 0;
+			break;
 		default:
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
@@ -748,11 +750,13 @@ be_tls_write(Port *port, void *ptr, size_t len, int *waitfor)
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
 					 errmsg("SSL error: %s", SSLerrmessage(ecode))));
-			/* fall through */
-		case SSL_ERROR_ZERO_RETURN:
 			errno = ECONNRESET;
 			n = -1;
 			break;
+		case SSL_ERROR_ZERO_RETURN:
+			/* connection was cleanly shut down by peer */
+			n = 0;
+			break;
 		default:
 			ereport(COMMERROR,
 					(errcode(ERRCODE_PROTOCOL_VIOLATION),
diff --git a/src/backend/libpq/be-secure.c b/src/backend/libpq/be-secure.c
index 785dadb6c2..655810e436 100644
--- a/src/backend/libpq/be-secure.c
+++ b/src/backend/libpq/be-secure.c
@@ -235,6 +235,10 @@ secure_raw_read(Port *port, void *ptr, size_t len)
 
 /*
  *	Write data to a secure connection.
+ *
+ * be_tls_write() can return 0 to caller if connection has been reset cleanly
+ * by peer when using a SSL connection, unlike its counterpart in
+ * secure_raw_write().
  */
 ssize_t
 secure_write(Port *port, void *ptr, size_t len)
diff --git a/src/interfaces/libpq/fe-secure-openssl.c b/src/interfaces/libpq/fe-secure-openssl.c
index a7c3d7af64..08f122cbe6 100644
--- a/src/interfaces/libpq/fe-secure-openssl.c
+++ b/src/interfaces/libpq/fe-secure-openssl.c
@@ -261,12 +261,10 @@ rloop:
 			/*
 			 * Per OpenSSL documentation, this error code is only returned for
 			 * a clean connection closure, so we should not report it as a
-			 * server crash.
+			 * server crash. Similarly to the non-SSL code path, this is
+			 * equivalent to nothing received to adapt accordindly.
 			 */
-			printfPQExpBuffer(&conn->errorMessage,
-			 libpq_gettext("SSL connection has been closed unexpectedly\n"));
-			result_errno = ECONNRESET;
-			n = -1;
+			n = 0;
 			break;
 		default:
 			printfPQExpBuffer(&conn->errorMessage,
@@ -370,12 +368,10 @@ pgtls_write(PGconn *conn, const void *ptr, size_t len)
 			/*
 			 * Per OpenSSL documentation, this error code is only returned for
 			 * a clean connection closure, so we should not report it as a
-			 * server crash.
+			 * server crash. Similarly to the non-SSL code path, this is
+			 * equivalent to nothing sent to adapt accordindly.
 			 */
-			printfPQExpBuffer(&conn->errorMessage,
-			 libpq_gettext("SSL connection has been closed unexpectedly\n"));
-			result_errno = ECONNRESET;
-			n = -1;
+			n = 0;
 			break;
 		default:
 			printfPQExpBuffer(&conn->errorMessage,
#7Heikki Linnakangas
hlinnaka@iki.fi
In reply to: Michael Paquier (#6)
Re: Error-like LOG when connecting with SSL for password authentication

On 05/24/2017 05:29 PM, Michael Paquier wrote:

Attached is an updated patch.

Thanks, I've pushed the backend read part of this patch. That's enough
to fix the original complaint with password authentication. I think the
rest was a bit dubious, and I'm hesitant to commit that (or at least to
backport):

* Backend write: you wouldn't really expect a client to disconnect,
while the backend is trying to send something to it. You'll get an error
in the non-SSL case too, although I guess the error message would be
different.

* Frontend read: pqReadData has this, after calling pqsecure_read:

/*
* A return value of 0 could mean just that no data is now available, or
* it could mean EOF --- that is, the server has closed the connection.
* Since we have the socket in nonblock mode, the only way to tell the
* difference is to see if select() is saying that the file is ready.
* Grumble. Fortunately, we don't expect this path to be taken much,
* since in normal practice we should not be trying to read data unless
* the file selected for reading already.
*
* In SSL mode it's even worse: SSL_read() could say WANT_READ and then
* data could arrive before we make the pqReadReady() test, but the second
* SSL_read() could still say WANT_READ because the data received was not
* a complete SSL record. So we must play dumb and assume there is more
* data, relying on the SSL layer to detect true EOF.
*/

#ifdef USE_SSL
if (conn->ssl_in_use)
return 0;
#endif

* Frontend write: Same as in the backend, I think having the server
disconnect while you're trying to send to it is not expected. Not sure
if the error message is here again different, but seems best to just
leave it alone.

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#8Michael Paquier
michael.paquier@gmail.com
In reply to: Heikki Linnakangas (#7)
Re: Error-like LOG when connecting with SSL for password authentication

On Mon, Jul 3, 2017 at 9:02 PM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:

Thanks, I've pushed the backend read part of this patch.

Thanks.
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#9Ryan Murphy
ryanfmurphy@gmail.com
In reply to: Michael Paquier (#8)
Re: Error-like LOG when connecting with SSL for password authentication

Hi Michael,

I tried to apply your patch to HEAD and it failed. But I think that's because some version of it has already been committed, correct? I see some of your ECONNRESET and "SSL connection has been closed unexpectedly" code already in HEAD.

Best,
Ryan

The new status of this patch is: Waiting on Author

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#10Michael Paquier
michael.paquier@gmail.com
In reply to: Ryan Murphy (#9)
Re: Re: Error-like LOG when connecting with SSL for password authentication

On Thu, Jul 6, 2017 at 12:45 AM, Ryan Murphy <ryanfmurphy@gmail.com> wrote:

I tried to apply your patch to HEAD and it failed.
But I think that's because some version of it has already been committed, correct? I see some of your ECONNRESET and "SSL connection has been closed unexpectedly" code already in HEAD.

Thanks Ryan for the reminder. Heikki has pushed a minimum patch set as
b93827c7. So I have updated the CF app accordingly.
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers