Subject: Re: backtrace_on_internal_error

From: Tom Lane <[email-masked]>
Date: Fri, 08 Dec 2023 13:23:50 -0500

Andres Freund <[email-masked]> writes:
> On 2023-12-08 10:05:09 -0500, Tom Lane wrote:
>> ... there was already opinion upthread that this should be on by
>> default, which I agree with.  You shouldn't be hitting cases like
>> this commonly (if so, they're bugs to fix or the errcode should be
>> rethought), and the failure might be pretty hard to reproduce.

> FWIW, I did some analysis on aggregated logs on a larger number of machines,
> and it does look like that'd be a measurable increase in log volume. There are
> a few voluminous internal errors in core, but the bigger issue is
> extensions. They are typically much less disciplined about assigning error
> codes than core PG is.

Well, I don't see much wrong with making a push to assign error codes
to more calls.  We've had other discussions about doing that.
Certainly these SSL failures are not "internal" errors.

> could not accept SSL connection: %m - with zero errno
> ...
> I'm a bit confused about the huge number of "could not accept SSL connection:
> %m" with a zero errno. I guess we must be clearing errno somehow, but I don't
> immediately see where. Or perhaps we need to actually look at what
> SSL_get_error() returns?

Hmm, don't suppose you have a way to reproduce that?

			regards, tom lane

---

From: Andres Freund <[email-masked]>
Date: Fri, 8 Dec 2023 10:34:40 -0800

Hi,

On 2023-12-08 13:23:50 -0500, Tom Lane wrote:
> to more calls.

Oh, very much agreed. But I suspect we won't quickly do the same for
out-of-core extensions...

> Hmm, don't suppose you have a way to reproduce that?

After a bit of trying, yes.  I put an abort() into pgtls_open_client(), after
initialize_SSL(). Connecting does result in:

LOG:  could not accept SSL connection: Success

Greetings,

Andres Freund

---

From: Tom Lane <[email-masked]>
Date: Fri, 08 Dec 2023 13:46:07 -0500

> LOG:  could not accept SSL connection: Success

OK.  I can dig into that, unless you're already on it?

			regards, tom lane

---

From: Andres Freund <[email-masked]>
Date: Fri, 8 Dec 2023 10:51:01 -0800

Hi,

> OK.  I can dig into that, unless you're already on it?

I think I figured it it out. Looks like we need to translate a closed socket
(recvfrom() returning 0) to ECONNRESET or such.

Greetings,

Andres Freund

---

From: Andres Freund <[email-masked]>
Date: Fri, 8 Dec 2023 11:33:16 -0800

Hi,

> (recvfrom() returning 0) to ECONNRESET or such.

I think we might just need to expand the existing branch for EOF:

				if (r < 0)
					ereport(COMMERROR,
							(errcode_for_socket_access(),
							 errmsg("could not accept SSL connection: %m")));
				else
					ereport(COMMERROR,
							(errcode(ERRCODE_PROTOCOL_VIOLATION),
							 errmsg("could not accept SSL connection: EOF detected")));

The openssl docs say:

 The following return values can occur:

0

    The TLS/SSL handshake was not successful but was shut down controlled and by the specifications of the TLS/SSL protocol. Call SSL_get_error() with the return value ret to find out the reason.
1

    The TLS/SSL handshake was successfully completed, a TLS/SSL connection has been established.
<0

    The TLS/SSL handshake was not successful because a fatal error occurred either at the protocol level or a connection failure occurred. The shutdown was not clean. It can also occur if action is needed to continue the operation for nonblocking BIOs. Call SSL_get_error() with the return value ret to find out the reason.

Which fits with my reproducer - due to the abort the connection was *not* shut
down via SSL in a controlled manner, therefore r < 0.

Hm, oddly enough, there's this tidbit in the SSL_get_error() manpage:

 On an unexpected EOF, versions before OpenSSL 3.0 returned SSL_ERROR_SYSCALL,
 nothing was added to the error stack, and errno was 0. Since OpenSSL 3.0 the
 returned error is SSL_ERROR_SSL with a meaningful error on the error stack.

But I reproduced this with 3.1.

Seems like we should just treat errno == 0 as a reason to emit the "EOF
detected" message?

I wonder if we should treat send/recv returning 0 different from an error
message perspective during an established connection. Right now we produce
  could not receive data from client: Connection reset by peer

because be_tls_read() sets errno to ECONNRESET - despite that not having been
returned by the OS.  But I guess that's a topic for another day.

Greetings,

Andres Freund

---

From: Andres Freund <[email-masked]>
Date: Fri, 8 Dec 2023 14:15:54 -0800

Hi,

On 2023-12-08 11:33:16 -0800, Andres Freund wrote:
> [...]

I thought it'd be nice to have a test for this, particularly because it's not
clear that the behaviour is consistent across openssl versions.

I couldn't think of a way to do that with psql. But it's just a few lines of
perl to gin up an "SSL" startup packet and then close the socket.  I couldn't
quite figure out when IO::Socket::INET was added, but I think it's likely been
long enough, I see references from 1999.

This worked easily on linux and freebsd, but not on windows and macos, where
it seems to cause ECONNRESET. I thought that explicitly shutting down the
socket might help, but that just additionally caused freebsd to fail.

Windows uses an older openssl, so it could also be caused by the behaviour
differing back then.

To deal with that, I changed the test to instead check if "not accept SSL
connection: Success" is not logged.  I'm not sure that actually would be
logged on windows, it does seem to have different strings for errors than
other platforms.

Greetings,

Andres Freund
>From d5133a5783b743c0235e016dcb438d2dda82a07b Mon Sep 17 00:00:00 2001
From: Andres Freund <[email-masked]>
Date: Fri, 8 Dec 2023 13:09:38 -0800
Subject: [PATCH v1] WIP: Fix error message for client disconnects during SSL
 startup

Author:
Reviewed-by:
Discussion: https://postgr.es/m/[email-masked]
Backpatch:
---
 src/backend/libpq/be-secure-openssl.c |  7 ++++-
 src/test/ssl/t/001_ssltests.pl        | 42 +++++++++++++++++++++++++++
 2 files changed, 48 insertions(+), 1 deletion(-)

diff --git a/src/backend/libpq/be-secure-openssl.c b/src/backend/libpq/be-secure-openssl.c
index 6b8125695a3..3c182c2d3a4 100644
--- a/src/backend/libpq/be-secure-openssl.c
+++ b/src/backend/libpq/be-secure-openssl.c
@@ -496,7 +496,12 @@ aloop:
 										 WAIT_EVENT_SSL_OPEN_SERVER);
 				goto aloop;
 			case SSL_ERROR_SYSCALL:
-				if (r < 0)
+				/*
+				 * If errno is 0, the client closed the socket without
+				 * shutting down the SSL connection, e.g. because the client
+				 * terminated.
+				 */
+				if (r < 0 && errno != 0)
 					ereport(COMMERROR,
 							(errcode_for_socket_access(),
 							 errmsg("could not accept SSL connection: %m")));
diff --git a/src/test/ssl/t/001_ssltests.pl b/src/test/ssl/t/001_ssltests.pl
index d921f1dde9f..e23300b318e 100644
--- a/src/test/ssl/t/001_ssltests.pl
+++ b/src/test/ssl/t/001_ssltests.pl
@@ -213,6 +213,48 @@ $node->connect_fails(
 	? qr/server accepted connection without a valid SSL certificate/
 	: qr/sslcertmode value "require" is not supported/);
 
+
+# Check log message makes sense when initiating SSL connection establishment
+# but then closing the socket immediately. In the past that sometimes was
+# logged as "could not accept SSL connection: Success", which is misleading.
+# Such disconnects happens regularly in real workloads, but can't easily be
+# tested with psql. Therefore just establish the connection the hard way -
+# it's easy enough here, because we just need to send a startup packet asking
+# for SSL to be initiated.
+{
+	use IO::Socket::INET;
+
+	my $sock = IO::Socket::INET->new(
+		PeerAddr => $SERVERHOSTADDR,
+		PeerPort => $node->port,
+		Proto => 'tcp');
+
+	my $log_location = -s $node->logfile;
+
+	# ssl request is message length as 32 bit big endian, 4 byte magic "ssl"
+	# protocol version, terminated by a 0  byte.
+	my $message = pack "NNx", 4 + 4 + 1, (1234 << 16) | 5679;
+
+	$sock->send($message);
+	$sock->close();
+
+	# On at least macos and windows closing the socket leads to a ECONNRESET
+	# on the server side. Therefore we don't check if the right message is
+	# logged, but that the "Success" message isn't.
+	#
+	# First wait for the connection attempt to be logged, so we can test for
+	# the absence of the "Success" message without a race.
+	ok( $node->wait_for_log(
+			qr/could not accept SSL connection:/,
+			$log_location),
+		'aborted connection attempt is logged');
+
+	$node->log_check("aborted connection attempt is logged as failure",
+		$log_location,
+		(log_unlike => [qr/could not accept SSL connection: Success/]));
+}
+
+
 # CRL tests
 
 # Invalid CRL filename is the same as no CRL, succeeds
-- 
2.38.0

---

From: Tom Lane <[email-masked]>
Date: Fri, 08 Dec 2023 17:29:45 -0500

> Seems like we should just treat errno == 0 as a reason to emit the "EOF

Agreed.  I think we want to do that after the initial handshake,
too, so maybe as attached.

			regards, tom lane

diff --git a/src/backend/libpq/be-secure-openssl.c b/src/backend/libpq/be-secure-openssl.c
index 6b8125695a..f0b35f08c6 100644
--- a/src/backend/libpq/be-secure-openssl.c
+++ b/src/backend/libpq/be-secure-openssl.c
@@ -460,6 +460,7 @@ aloop:
 	 * per-thread error queue following another call to an OpenSSL I/O
 	 * routine.
 	 */
+	errno = 0;
 	ERR_clear_error();
 	r = SSL_accept(port->ssl);
 	if (r <= 0)
@@ -496,7 +497,7 @@ aloop:
 										 WAIT_EVENT_SSL_OPEN_SERVER);
 				goto aloop;
 			case SSL_ERROR_SYSCALL:
-				if (r < 0)
+				if (r < 0 && errno != 0)
 					ereport(COMMERROR,
 							(errcode_for_socket_access(),
 							 errmsg("could not accept SSL connection: %m")));
@@ -732,7 +733,7 @@ be_tls_read(Port *port, void *ptr, size_t len, int *waitfor)
 			break;
 		case SSL_ERROR_SYSCALL:
 			/* leave it to caller to ereport the value of errno */
-			if (n != -1)
+			if (n != -1 || errno == 0)
 			{
 				errno = ECONNRESET;
 				n = -1;

---

From: Tom Lane <[email-masked]>
Date: Fri, 08 Dec 2023 17:35:26 -0500

> clear that the behaviour is consistent across openssl versions.

Perhaps, but ...

> connection: Success" is not logged.

... testing only that much seems entirely not worth the cycles, given the
shape of the patches we both just made.  If we can't rely on "errno != 0"
to ensure we won't get "Success", there is one heck of a lot of other
code that will be broken worse than this.

			regards, tom lane

---

From: Robert Haas <[email-masked]>
Date: Tue, 19 Dec 2023 11:11:35 -0500

> out-of-core extensions...

I feel like this is a problem that will sort itself out just fine. The
rules about using ereport() and elog() could probably be better
documented than they are, but doing that won't cause people to follow
the practices any more rigorously than they have been. However, a
change like this just might. If we make this policy change in core,
then extension authors will probably get pressure from users to clean
up any calls that are emitting excessively verbose log output, and
that seems like a good thing.

It's impossible to make an omelet without breaking some eggs, but the
thing we're talking about here is, IMHO, extremely important. Users
are forever hitting weird errors in production that aren't easy to
reproduce on test systems, and because most elog() calls are written
with the expectation that they won't be hit, they often contain
minimal information, which IME makes it really difficult to understand
what went wrong. A lot of these are things like - oh, this function
expected a valid value of some sort, say a relkind, and it got some
nonsense value, say a zero byte. But where did that nonsense value
originate? That elog message can't tell you that, but a stack trace
will.

The last change we made in this area that, at least for me, massively
improved debuggability was the change to log the current query string
when a backend crashes. That's such a huge help; I can't imagine going
back to the old way where you had basically no idea what made things
go boom. I think doing something like this can have a similarly
positive impact. It is going to take some work - from us and from
extension authors - to tidy things up so that it doesn't produce a
bunch of unwanted output, but the payoff will be the ability to
actually find and fix the bugs instead of just saying to a customer
"hey, sucks that you hit a bug, let us know if you find a reproducer."

-- 
Robert Haas
EDB: http://www.enterprisedb.com

---

From: Tom Lane <[email-masked]>
Date: Tue, 19 Dec 2023 11:29:26 -0500

> "hey, sucks that you hit a bug, let us know if you find a reproducer."

IMO, we aren't really going to get a massive payoff from this with
the current backtrace output; it's just not detailed enough.  It's
better than nothing certainly, but to really move the goalposts
we'd need something approaching gdb's "bt full" output.  I wonder
if it'd be sane to try to auto-invoke gdb.  That's just blue sky
for now, though.  In the meantime, I agree with the proposal as it
stands (that is, auto-backtrace on any XX000 error).  We'll soon find
out whether it's useless, or needs more detail to be really helpful,
or is just right as it is.  Once we have some practical experience
with it, we can course-correct as needed.

			regards, tom lane

---

From: Robert Haas <[email-masked]>
Date: Tue, 19 Dec 2023 14:22:36 -0500

> with it, we can course-correct as needed.

That all seems fair to me. I'm more optimistic than you are about
getting something useful out of the current backtrace output, but (1)
I could be wrong, (2) I'd still like to have something better, and (3)
improving the backtrace output is a separate project from including
backtraces more frequently.

---

From: Jelte Fennema-Nio <[email-masked]>
Date: Wed, 20 Dec 2023 10:30:33 +0100

> that seems like a good thing.

As an extension author I wanted to make clear that Andres his concern
is definitely not theoretical. Citus (as well as most other extensions
me and our team at Microsoft maintains) use ereport without an error
code very often. And while we try to use elog actually only for
internal errors, there's definitely places where we haven't.

We've had "adding error codes to all our errors" on our backlog for
years though. I'm guessing this is mostly a combination of it being a
boring task, it being a lot of work, and the impact not being
particularly huge (i.e. now users can check error codes for all our
errors wohoo!). If ereport without an errorcode would suddenly cause a
log flood in the next postgres release then suddenly the impact of
adding error codes would increase drastically. And as Robert said we'd
basically be forced to adopt the pattern. Which I agree isn't
necessarily a bad thing.

But I'm not sure that smaller extensions that are not maintained by a
team that's paid to do so would be happy about this change. Also I
think we'd even change our extension to add errror codes to all
ereport calls if the stack traces are useful enough, because then the
impact of adding error codes suddenly increases a lot. So I think
having a way for extensions to opt-in/opt-out of this change for their
extension would be very much appreciated by those authors.

---

From: Peter Eisentraut <[email-masked]>
Date: Sat, 30 Dec 2023 12:11:59 +0100

> with it, we can course-correct as needed.

Based on this, I have committed my original patch.