Thread: BUG #17391: While using --with-ssl=openssl and PG_TEST_EXTRA='ssl' options, SSL tests fail on OpenBSD 7.0

The following bug has been logged on the website:

Bug reference:      17391
Logged by:          Nazir Bilal Yavuz
Email address:      byavuz81@gmail.com
PostgreSQL version: 14.1
Operating system:   OpenBSD 7.0
Description:

Hi,

While installing PostgreSQL from source code,  SSL tests fail on OpenBSD
7.0.

The commands I used are:

./configure \
--enable-tap-tests \
--with-ssl=openssl \
\
--with-includes=/usr/local/include --with-libs=/usr/local/lib && \
gmake -s world-bin && gmake -s check-world PG_TEST_EXTRA='ssl' 

OS:
OpenBSD openbsd-host.my.domain 7.0 GENERIC#224 amd64

OpenSSL Version:
LibreSSL 3.4.1

Error message:
t/001_ssltests.pl (Wstat: 5632 Tests: 110 Failed: 22)
t/002_scram.pl   (Wstat: 1792 Tests: 11 Failed: 7)
t/003_sslinfo.pl (Wstat: 7424 Tests: 1 Failed: 1)

Example Logs(001_ssltests_primary.log and regress_log_001_ssltests):

001_ssltests_primary.log:

2022-02-03 00:26:51.127 +03 [88304] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:26:51.127 +03 [88304] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:26:51.147 +03 [63726] LOG:  database system was shut down at
2022-02-03 00:26:51 +03
2022-02-03 00:26:51.149 +03 [88304] LOG:  database system is ready to accept
connections
2022-02-03 00:26:51.172 +03 [59203] 001_ssltests.pl LOG:  statement: SHOW
ssl_library
2022-02-03 00:26:51.230 +03 [30464] 001_ssltests.pl LOG:  statement: CREATE
USER ssltestuser
2022-02-03 00:26:51.278 +03 [14697] 001_ssltests.pl LOG:  statement: CREATE
USER md5testuser
2022-02-03 00:26:51.302 +03 [3601] 001_ssltests.pl LOG:  statement: CREATE
USER anotheruser
2022-02-03 00:26:51.327 +03 [63049] 001_ssltests.pl LOG:  statement: CREATE
USER yetanotheruser
2022-02-03 00:26:51.533 +03 [3961] 001_ssltests.pl LOG:  statement: CREATE
DATABASE trustdb
2022-02-03 00:26:51.533 +03 [89906] LOG:  checkpoint starting: immediate
force wait flush-all
2022-02-03 00:26:51.535 +03 [89906] LOG:  checkpoint complete: wrote 10
buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.003 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=4 kB, estimate=4 kB
2022-02-03 00:26:52.959 +03 [89906] LOG:  checkpoint starting: immediate
force wait
2022-02-03 00:26:52.959 +03 [89906] LOG:  checkpoint complete: wrote 0
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=4 kB
2022-02-03 00:26:53.282 +03 [17946] 001_ssltests.pl LOG:  statement: CREATE
DATABASE certdb
2022-02-03 00:26:53.283 +03 [89906] LOG:  checkpoint starting: immediate
force wait flush-all
2022-02-03 00:26:53.284 +03 [89906] LOG:  checkpoint complete: wrote 4
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=1 kB, estimate=4 kB
2022-02-03 00:26:53.586 +03 [89906] LOG:  checkpoint starting: immediate
force wait
2022-02-03 00:26:53.587 +03 [89906] LOG:  checkpoint complete: wrote 0
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=3 kB
2022-02-03 00:26:53.679 +03 [69142] 001_ssltests.pl LOG:  statement: CREATE
DATABASE certdb_dn
2022-02-03 00:26:53.679 +03 [89906] LOG:  checkpoint starting: immediate
force wait flush-all
2022-02-03 00:26:53.680 +03 [89906] LOG:  checkpoint complete: wrote 4
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=1 kB, estimate=3 kB
2022-02-03 00:26:54.163 +03 [89906] LOG:  checkpoint starting: immediate
force wait
2022-02-03 00:26:54.163 +03 [89906] LOG:  checkpoint complete: wrote 0
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=3 kB
2022-02-03 00:26:54.597 +03 [87708] 001_ssltests.pl LOG:  statement: CREATE
DATABASE certdb_dn_re
2022-02-03 00:26:54.597 +03 [89906] LOG:  checkpoint starting: immediate
force wait flush-all
2022-02-03 00:26:54.598 +03 [89906] LOG:  checkpoint complete: wrote 4
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=1 kB, estimate=3 kB
2022-02-03 00:26:54.730 +03 [89906] LOG:  checkpoint starting: immediate
force wait
2022-02-03 00:26:54.730 +03 [89906] LOG:  checkpoint complete: wrote 0
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=2 kB
2022-02-03 00:26:54.874 +03 [73405] 001_ssltests.pl LOG:  statement: CREATE
DATABASE certdb_cn
2022-02-03 00:26:54.881 +03 [89906] LOG:  checkpoint starting: immediate
force wait flush-all
2022-02-03 00:26:54.882 +03 [89906] LOG:  checkpoint complete: wrote 4
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=2 kB, estimate=2 kB
2022-02-03 00:26:54.951 +03 [89906] LOG:  checkpoint starting: immediate
force wait
2022-02-03 00:26:54.951 +03 [89906] LOG:  checkpoint complete: wrote 0
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=2 kB
2022-02-03 00:26:55.254 +03 [83428] 001_ssltests.pl LOG:  statement: CREATE
DATABASE verifydb
2022-02-03 00:26:55.254 +03 [89906] LOG:  checkpoint starting: immediate
force wait flush-all
2022-02-03 00:26:55.257 +03 [89906] LOG:  checkpoint complete: wrote 4
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.003 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=2 kB, estimate=2 kB
2022-02-03 00:26:55.362 +03 [89906] LOG:  checkpoint starting: immediate
force wait
2022-02-03 00:26:55.363 +03 [89906] LOG:  checkpoint complete: wrote 0
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=2 kB
2022-02-03 00:26:55.542 +03 [88304] LOG:  received fast shutdown request
2022-02-03 00:26:55.542 +03 [88304] LOG:  aborting any active transactions
2022-02-03 00:26:55.544 +03 [88304] LOG:  background worker "logical
replication launcher" (PID 56614) exited with exit code 1
2022-02-03 00:26:55.544 +03 [89906] LOG:  shutting down
2022-02-03 00:26:55.544 +03 [89906] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:26:55.548 +03 [89906] LOG:  checkpoint complete: wrote 1
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.000 s,
sync=0.000 s, total=0.004 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=2 kB
2022-02-03 00:26:55.553 +03 [88304] LOG:  database system is shut down
2022-02-03 00:26:55.603 +03 [80056] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:26:55.603 +03 [80056] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:26:55.620 +03 [80056] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:26:55.678 +03 [41931] LOG:  database system was shut down at
2022-02-03 00:26:55 +03
2022-02-03 00:26:55.688 +03 [80056] LOG:  database system is ready to accept
connections
2022-02-03 00:26:55.825 +03 [80056] LOG:  received fast shutdown request
2022-02-03 00:26:55.825 +03 [80056] LOG:  aborting any active transactions
2022-02-03 00:26:55.827 +03 [80056] LOG:  background worker "logical
replication launcher" (PID 65521) exited with exit code 1
2022-02-03 00:26:55.827 +03 [87556] LOG:  shutting down
2022-02-03 00:26:55.827 +03 [87556] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:26:55.829 +03 [87556] LOG:  checkpoint complete: wrote 4
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:26:55.832 +03 [80056] LOG:  database system is shut down
2022-02-03 00:26:55.902 +03 [26092] FATAL:  could not load private key file
"server-password.key": bad decrypt
2022-02-03 00:26:55.902 +03 [26092] LOG:  database system is shut down
2022-02-03 00:26:56.194 +03 [59483] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:26:56.194 +03 [59483] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:26:56.194 +03 [59483] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:26:56.274 +03 [91273] LOG:  database system was shut down at
2022-02-03 00:26:55 +03
2022-02-03 00:26:56.279 +03 [59483] LOG:  database system is ready to accept
connections
2022-02-03 00:26:56.507 +03 [59483] LOG:  received fast shutdown request
2022-02-03 00:26:56.507 +03 [59483] LOG:  aborting any active transactions
2022-02-03 00:26:56.509 +03 [59483] LOG:  background worker "logical
replication launcher" (PID 21939) exited with exit code 1
2022-02-03 00:26:56.509 +03 [9455] LOG:  shutting down
2022-02-03 00:26:56.509 +03 [9455] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:26:56.511 +03 [9455] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:26:56.515 +03 [59483] LOG:  database system is shut down
2022-02-03 00:26:56.794 +03 [45020] FATAL:  could not set maximum SSL
protocol version
2022-02-03 00:26:56.794 +03 [45020] LOG:  database system is shut down
2022-02-03 00:26:56.990 +03 [56065] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:26:56.991 +03 [56065] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:26:56.991 +03 [56065] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:26:57.015 +03 [99076] LOG:  database system was shut down at
2022-02-03 00:26:56 +03
2022-02-03 00:26:57.017 +03 [56065] LOG:  database system is ready to accept
connections
2022-02-03 00:26:57.107 +03 [56065] LOG:  received fast shutdown request
2022-02-03 00:26:57.107 +03 [56065] LOG:  aborting any active transactions
2022-02-03 00:26:57.109 +03 [56065] LOG:  background worker "logical
replication launcher" (PID 34941) exited with exit code 1
2022-02-03 00:26:57.109 +03 [33335] LOG:  shutting down
2022-02-03 00:26:57.109 +03 [33335] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:26:57.110 +03 [33335] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:26:57.115 +03 [56065] LOG:  database system is shut down
2022-02-03 00:26:57.161 +03 [87966] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:26:57.162 +03 [87966] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:26:57.162 +03 [87966] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:26:57.187 +03 [29490] LOG:  database system was shut down at
2022-02-03 00:26:57 +03
2022-02-03 00:26:57.194 +03 [87966] LOG:  database system is ready to accept
connections
2022-02-03 00:26:57.262 +03 [68121] [unknown] LOG:  connection received:
host=localhost port=41336
2022-02-03 00:26:57.268 +03 [68121] [unknown] FATAL:  no pg_hba.conf entry
for host "127.0.0.1", user "ssltestuser", database "trustdb", no
encryption
2022-02-03 00:26:57.268 +03 [68121] [unknown] DETAIL:  Client IP address
resolved to "localhost", forward lookup not checked.
2022-02-03 00:26:57.328 +03 [84039] [unknown] LOG:  connection received:
host=localhost port=12182
2022-02-03 00:26:57.361 +03 [84039] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:26:57.376 +03 [84039] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test sslrootcert=invalid
sslmode=require$$
2022-02-03 00:26:57.415 +03 [76636] [unknown] LOG:  connection received:
host=localhost port=49071
2022-02-03 00:26:57.442 +03 [76636] [unknown] LOG:  could not accept SSL
connection: EOF detected
2022-02-03 00:26:57.469 +03 [63906] [unknown] LOG:  connection received:
host=localhost port=29901
2022-02-03 00:26:57.488 +03 [63906] [unknown] LOG:  could not accept SSL
connection: EOF detected
2022-02-03 00:26:57.550 +03 [57856] [unknown] LOG:  connection received:
host=localhost port=9741
2022-02-03 00:26:57.574 +03 [57856] [unknown] LOG:  could not accept SSL
connection: tlsv1 alert unknown ca
2022-02-03 00:26:57.609 +03 [10201] [unknown] LOG:  connection received:
host=localhost port=29429
2022-02-03 00:26:57.653 +03 [10201] [unknown] LOG:  could not accept SSL
connection: tlsv1 alert unknown ca
2022-02-03 00:26:57.690 +03 [22036] [unknown] LOG:  connection received:
host=localhost port=22975
2022-02-03 00:26:57.784 +03 [22036] [unknown] LOG:  could not accept SSL
connection: tlsv1 alert unknown ca
2022-02-03 00:26:57.823 +03 [42487] [unknown] LOG:  connection received:
host=localhost port=45404
2022-02-03 00:26:57.859 +03 [42487] [unknown] LOG:  could not accept SSL
connection: tlsv1 alert unknown ca
2022-02-03 00:26:57.967 +03 [80741] [unknown] LOG:  connection received:
host=localhost port=6033
2022-02-03 00:26:58.065 +03 [80741] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:26:58.078 +03 [80741] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=require$$
2022-02-03 00:26:58.149 +03 [89578] [unknown] LOG:  connection received:
host=localhost port=48381
2022-02-03 00:26:58.262 +03 [89578] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:26:58.269 +03 [89578] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=verify-ca$$
2022-02-03 00:26:58.412 +03 [55012] [unknown] LOG:  connection received:
host=localhost port=28357
2022-02-03 00:26:58.566 +03 [55012] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:26:58.595 +03 [55012] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=verify-full$$
2022-02-03 00:26:58.831 +03 [28146] [unknown] LOG:  connection received:
host=localhost port=24203
2022-02-03 00:26:59.245 +03 [28146] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:26:59.293 +03 [28146] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/both-cas-1.crt sslmode=verify-ca$$
2022-02-03 00:26:59.403 +03 [68249] [unknown] LOG:  connection received:
host=localhost port=31654
2022-02-03 00:26:59.614 +03 [68249] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:26:59.616 +03 [68249] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/both-cas-2.crt sslmode=verify-ca$$
2022-02-03 00:26:59.784 +03 [48189] [unknown] LOG:  connection received:
host=localhost port=29141
2022-02-03 00:27:00.017 +03 [48189] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:00.033 +03 [48189] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=verify-ca sslcrl=invalid$$
2022-02-03 00:27:00.156 +03 [66329] [unknown] LOG:  connection received:
host=localhost port=18238
2022-02-03 00:27:00.324 +03 [66329] [unknown] LOG:  could not accept SSL
connection: tlsv1 alert unknown ca
2022-02-03 00:27:00.491 +03 [24932] [unknown] LOG:  connection received:
host=localhost port=24603
2022-02-03 00:27:00.569 +03 [24932] [unknown] LOG:  could not accept SSL
connection: tlsv1 alert unknown ca
2022-02-03 00:27:00.856 +03 [37114] [unknown] LOG:  connection received:
host=localhost port=30183
2022-02-03 00:27:01.150 +03 [37114] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:01.183 +03 [37114] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=verify-ca
sslcrl=ssl/root+server.crl$$
2022-02-03 00:27:01.246 +03 [67656] [unknown] LOG:  connection received:
host=localhost port=42539
2022-02-03 00:27:01.333 +03 [67656] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:01.337 +03 [67656] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=verify-ca
sslcrldir=ssl/root+server-crldir$$
2022-02-03 00:27:01.398 +03 [52851] [unknown] LOG:  connection received:
host=localhost port=41360
2022-02-03 00:27:01.484 +03 [52851] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:01.498 +03 [52851] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=require
host=wronghost.test$$
2022-02-03 00:27:01.585 +03 [40160] [unknown] LOG:  connection received:
host=localhost port=37625
2022-02-03 00:27:01.987 +03 [40160] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:02.047 +03 [40160] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-ca
host=wronghost.test$$
2022-02-03 00:27:02.189 +03 [61439] [unknown] LOG:  connection received:
host=localhost port=42493
2022-02-03 00:27:02.436 +03 [87966] LOG:  received fast shutdown request
2022-02-03 00:27:02.436 +03 [87966] LOG:  aborting any active transactions
2022-02-03 00:27:02.441 +03 [87966] LOG:  background worker "logical
replication launcher" (PID 15053) exited with exit code 1
2022-02-03 00:27:02.441 +03 [95537] LOG:  shutting down
2022-02-03 00:27:02.441 +03 [95537] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:27:02.443 +03 [95537] LOG:  checkpoint complete: wrote 4
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:27:02.451 +03 [87966] LOG:  database system is shut down
2022-02-03 00:27:02.583 +03 [54211] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:27:02.583 +03 [54211] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:27:02.585 +03 [54211] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:27:02.632 +03 [33944] LOG:  database system was shut down at
2022-02-03 00:27:02 +03
2022-02-03 00:27:02.681 +03 [54211] LOG:  database system is ready to accept
connections
2022-02-03 00:27:02.854 +03 [5733] [unknown] LOG:  connection received:
host=localhost port=32424
2022-02-03 00:27:02.993 +03 [5733] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:03.114 +03 [5733] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-full
host=dns1.alt-name.pg-ssltest.test$$
2022-02-03 00:27:03.205 +03 [87701] [unknown] LOG:  connection received:
host=localhost port=15430
2022-02-03 00:27:03.314 +03 [87701] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:03.326 +03 [87701] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-full
host=dns2.alt-name.pg-ssltest.test$$
2022-02-03 00:27:03.472 +03 [99455] [unknown] LOG:  connection received:
host=localhost port=13487
2022-02-03 00:27:03.668 +03 [99455] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:03.694 +03 [99455] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-full
host=foo.wildcard.pg-ssltest.test$$
2022-02-03 00:27:03.958 +03 [56631] [unknown] LOG:  connection received:
host=localhost port=17831
2022-02-03 00:27:04.300 +03 [35125] [unknown] LOG:  connection received:
host=localhost port=48918
2022-02-03 00:27:04.949 +03 [54211] LOG:  received fast shutdown request
2022-02-03 00:27:04.949 +03 [54211] LOG:  aborting any active transactions
2022-02-03 00:27:04.953 +03 [54211] LOG:  background worker "logical
replication launcher" (PID 38490) exited with exit code 1
2022-02-03 00:27:04.953 +03 [69508] LOG:  shutting down
2022-02-03 00:27:04.953 +03 [69508] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:27:04.955 +03 [69508] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:27:04.961 +03 [54211] LOG:  database system is shut down
2022-02-03 00:27:06.096 +03 [65102] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:27:06.096 +03 [65102] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:27:06.097 +03 [65102] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:27:06.123 +03 [9859] LOG:  database system was shut down at
2022-02-03 00:27:04 +03
2022-02-03 00:27:06.131 +03 [65102] LOG:  database system is ready to accept
connections
2022-02-03 00:27:06.410 +03 [10840] [unknown] LOG:  connection received:
host=localhost port=10396
2022-02-03 00:27:07.129 +03 [10840] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:07.182 +03 [10840] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-full
host=single.alt-name.pg-ssltest.test$$
2022-02-03 00:27:07.417 +03 [18339] [unknown] LOG:  connection received:
host=localhost port=45593
2022-02-03 00:27:07.757 +03 [38783] [unknown] LOG:  connection received:
host=localhost port=43413
2022-02-03 00:27:07.977 +03 [65102] LOG:  received fast shutdown request
2022-02-03 00:27:07.977 +03 [65102] LOG:  aborting any active transactions
2022-02-03 00:27:07.980 +03 [65102] LOG:  background worker "logical
replication launcher" (PID 75820) exited with exit code 1
2022-02-03 00:27:07.980 +03 [39362] LOG:  shutting down
2022-02-03 00:27:07.980 +03 [39362] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:27:07.981 +03 [39362] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:27:07.985 +03 [65102] LOG:  database system is shut down
2022-02-03 00:27:08.117 +03 [28120] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:27:08.117 +03 [28120] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:27:08.117 +03 [28120] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:27:08.134 +03 [76752] LOG:  database system was shut down at
2022-02-03 00:27:07 +03
2022-02-03 00:27:08.136 +03 [28120] LOG:  database system is ready to accept
connections
2022-02-03 00:27:08.300 +03 [7921] [unknown] LOG:  connection received:
host=localhost port=1235
2022-02-03 00:27:08.575 +03 [7921] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:08.860 +03 [7921] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-full
host=dns1.alt-name.pg-ssltest.test$$
2022-02-03 00:27:09.027 +03 [33529] [unknown] LOG:  connection received:
host=localhost port=3769
2022-02-03 00:27:09.227 +03 [33529] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:09.234 +03 [33529] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-full
host=dns2.alt-name.pg-ssltest.test$$
2022-02-03 00:27:09.315 +03 [69195] [unknown] LOG:  connection received:
host=localhost port=39582
2022-02-03 00:27:09.525 +03 [28120] LOG:  received fast shutdown request
2022-02-03 00:27:09.525 +03 [28120] LOG:  aborting any active transactions
2022-02-03 00:27:09.528 +03 [28120] LOG:  background worker "logical
replication launcher" (PID 61885) exited with exit code 1
2022-02-03 00:27:09.528 +03 [4767] LOG:  shutting down
2022-02-03 00:27:09.529 +03 [4767] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:27:09.530 +03 [4767] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:27:09.535 +03 [28120] LOG:  database system is shut down
2022-02-03 00:27:09.707 +03 [50785] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:27:09.707 +03 [50785] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:27:09.707 +03 [50785] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:27:09.742 +03 [24937] LOG:  database system was shut down at
2022-02-03 00:27:09 +03
2022-02-03 00:27:09.754 +03 [50785] LOG:  database system is ready to accept
connections
2022-02-03 00:27:09.862 +03 [70733] [unknown] LOG:  connection received:
host=localhost port=31324
2022-02-03 00:27:09.971 +03 [70733] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:09.992 +03 [70733] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
sslrootcert=ssl/root+server_ca.crt hostaddr=127.0.0.1 sslmode=verify-ca
host=common-name.pg-ssltest.test$$
2022-02-03 00:27:10.151 +03 [42736] [unknown] LOG:  connection received:
host=localhost port=11626
2022-02-03 00:27:10.338 +03 [50785] LOG:  received fast shutdown request
2022-02-03 00:27:10.338 +03 [50785] LOG:  aborting any active transactions
2022-02-03 00:27:10.340 +03 [50785] LOG:  background worker "logical
replication launcher" (PID 25760) exited with exit code 1
2022-02-03 00:27:10.340 +03 [63437] LOG:  shutting down
2022-02-03 00:27:10.340 +03 [63437] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:27:10.343 +03 [63437] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.003 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:27:10.348 +03 [50785] LOG:  database system is shut down
2022-02-03 00:27:10.444 +03 [83429] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:27:10.444 +03 [83429] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:27:10.444 +03 [83429] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:27:10.459 +03 [64141] LOG:  database system was shut down at
2022-02-03 00:27:10 +03
2022-02-03 00:27:10.461 +03 [83429] LOG:  database system is ready to accept
connections
2022-02-03 00:27:10.598 +03 [59512] [unknown] LOG:  connection received:
host=localhost port=36151
2022-02-03 00:27:10.660 +03 [59512] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:10.870 +03 [59512] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=verify-ca$$
2022-02-03 00:27:10.998 +03 [44649] [unknown] LOG:  connection received:
host=localhost port=3558
2022-02-03 00:27:11.336 +03 [44649] [unknown] LOG:  could not accept SSL
connection: sslv3 alert certificate revoked
2022-02-03 00:27:11.430 +03 [36439] [unknown] LOG:  connection received:
host=localhost port=12757
2022-02-03 00:27:11.472 +03 [36439] [unknown] LOG:  could not accept SSL
connection: sslv3 alert certificate revoked
2022-02-03 00:27:11.543 +03 [27312] [unknown] LOG:  connection received:
host=localhost port=22355
2022-02-03 00:27:11.838 +03 [27312] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:11.897 +03 [27312] 001_ssltests.pl LOG:  statement: SELECT
* FROM pg_stat_ssl WHERE pid = pg_backend_pid()
2022-02-03 00:27:12.189 +03 [52690] [unknown] LOG:  connection received:
host=localhost port=23076
2022-02-03 00:27:12.245 +03 [52690] [unknown] LOG:  connection authorized:
user=ssltestuser database=trustdb application_name=001_ssltests.pl SSL
enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256)
2022-02-03 00:27:12.256 +03 [52690] 001_ssltests.pl LOG:  statement: SELECT
$$connected with user=ssltestuser dbname=trustdb sslcert=invalid
hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=ssl/root+server_ca.crt sslmode=require
ssl_min_protocol_version=TLSv1.2 ssl_max_protocol_version=TLSv1.2$$
2022-02-03 00:27:12.793 +03 [36971] [unknown] LOG:  connection received:
host=localhost port=2717
2022-02-03 00:27:12.851 +03 [36971] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:13.139 +03 [67032] [unknown] LOG:  connection received:
host=localhost port=14305
2022-02-03 00:27:13.215 +03 [67032] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:13.390 +03 [67442] [unknown] LOG:  connection received:
host=localhost port=13873
2022-02-03 00:27:13.434 +03 [67442] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:13.774 +03 [9375] [unknown] LOG:  connection received:
host=localhost port=20439
2022-02-03 00:27:13.834 +03 [9375] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:14.016 +03 [49711] [unknown] LOG:  connection received:
host=localhost port=19814
2022-02-03 00:27:14.052 +03 [49711] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:14.292 +03 [28112] [unknown] LOG:  connection received:
host=localhost port=44709
2022-02-03 00:27:14.356 +03 [28112] [unknown] LOG:  could not accept SSL
connection: EOF detected
2022-02-03 00:27:14.421 +03 [73952] [unknown] LOG:  connection received:
host=localhost port=26092
2022-02-03 00:27:14.433 +03 [73952] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:14.758 +03 [48484] [unknown] LOG:  connection received:
host=localhost port=19155
2022-02-03 00:27:14.773 +03 [48484] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:14.839 +03 [74476] [unknown] LOG:  connection received:
host=localhost port=20094
2022-02-03 00:27:14.851 +03 [74476] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:14.995 +03 [25958] [unknown] LOG:  connection received:
host=localhost port=5219
2022-02-03 00:27:15.008 +03 [25958] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:15.127 +03 [60506] [unknown] LOG:  connection received:
host=localhost port=41191
2022-02-03 00:27:15.159 +03 [60506] [unknown] LOG:  could not accept SSL
connection: EOF detected
2022-02-03 00:27:15.207 +03 [395] [unknown] LOG:  connection received:
host=localhost port=1925
2022-02-03 00:27:15.227 +03 [395] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:15.312 +03 [7195] [unknown] LOG:  connection received:
host=localhost port=4367
2022-02-03 00:27:15.332 +03 [7195] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:15.439 +03 [75715] [unknown] LOG:  connection received:
host=localhost port=44836
2022-02-03 00:27:15.457 +03 [75715] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:15.586 +03 [95142] [unknown] LOG:  connection received:
host=localhost port=8336
2022-02-03 00:27:15.606 +03 [95142] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:15.702 +03 [98682] [unknown] LOG:  connection received:
host=localhost port=12937
2022-02-03 00:27:15.729 +03 [98682] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:15.809 +03 [83429] LOG:  received fast shutdown request
2022-02-03 00:27:15.809 +03 [83429] LOG:  aborting any active transactions
2022-02-03 00:27:15.812 +03 [83429] LOG:  background worker "logical
replication launcher" (PID 47697) exited with exit code 1
2022-02-03 00:27:15.812 +03 [61954] LOG:  shutting down
2022-02-03 00:27:15.812 +03 [61954] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:27:15.813 +03 [61954] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:27:15.818 +03 [83429] LOG:  database system is shut down
2022-02-03 00:27:16.026 +03 [65607] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:27:16.026 +03 [65607] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:27:16.026 +03 [65607] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:27:16.130 +03 [46774] LOG:  database system was shut down at
2022-02-03 00:27:15 +03
2022-02-03 00:27:16.132 +03 [65607] LOG:  database system is ready to accept
connections
2022-02-03 00:27:16.166 +03 [163] [unknown] LOG:  connection received:
host=localhost port=30758
2022-02-03 00:27:16.210 +03 [163] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:16.381 +03 [81662] [unknown] LOG:  connection received:
host=localhost port=32497
2022-02-03 00:27:16.428 +03 [81662] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:16.576 +03 [65607] LOG:  received fast shutdown request
2022-02-03 00:27:16.576 +03 [65607] LOG:  aborting any active transactions
2022-02-03 00:27:16.579 +03 [65607] LOG:  background worker "logical
replication launcher" (PID 96725) exited with exit code 1
2022-02-03 00:27:16.579 +03 [84662] LOG:  shutting down
2022-02-03 00:27:16.579 +03 [84662] LOG:  checkpoint starting: shutdown
immediate
2022-02-03 00:27:16.581 +03 [84662] LOG:  checkpoint complete: wrote 3
buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s,
sync=0.001 s, total=0.003 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=0 kB
2022-02-03 00:27:16.585 +03 [65607] LOG:  database system is shut down
2022-02-03 00:27:16.979 +03 [47738] LOG:  starting PostgreSQL 15devel on
x86_64-unknown-openbsd7.0, compiled by OpenBSD clang version 11.1.0,
64-bit
2022-02-03 00:27:16.979 +03 [47738] LOG:  listening on IPv4 address
"127.0.0.1", port 56010
2022-02-03 00:27:16.980 +03 [47738] LOG:  listening on Unix socket
"/tmp/rkGcakKpBu/.s.PGSQL.56010"
2022-02-03 00:27:17.007 +03 [75810] LOG:  database system was shut down at
2022-02-03 00:27:16 +03
2022-02-03 00:27:17.009 +03 [47738] LOG:  database system is ready to accept
connections
2022-02-03 00:27:17.200 +03 [88500] [unknown] LOG:  connection received:
host=localhost port=27583
2022-02-03 00:27:17.286 +03 [88500] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
2022-02-03 00:27:17.306 +03 [5933] [unknown] LOG:  connection received:
host=localhost port=10939
2022-02-03 00:27:17.311 +03 [5933] [unknown] FATAL:  no pg_hba.conf entry
for host "127.0.0.1", user "ssltestuser", database "certdb", no encryption
2022-02-03 00:27:17.311 +03 [5933] [unknown] DETAIL:  Client IP address
resolved to "localhost", forward lookup not checked.
2022-02-03 00:27:17.631 +03 [47738] LOG:  received immediate shutdown
request
2022-02-03 00:27:17.637 +03 [47738] LOG:  database system is shut down


regress_log_001_ssltests:

1..110
# setting up data directory
# Checking port 56010
# Found port 56010
Name: primary
Data directory:
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
Backup directory:
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/backup
Archive directory:
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/archives
Connection string: port=56010 host=/tmp/rkGcakKpBu
Log file:
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
# Running: initdb -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-A trust -N
The files belonging to this database system will be owned by user
"postgres".
This user must also own the server process.

The database cluster will be initialized with locales
  COLLATE:  en_US.UTF-8
  CTYPE:    en_US.UTF-8
  MESSAGES: C
  MONETARY: en_US.UTF-8
  NUMERIC:  en_US.UTF-8
  TIME:     en_US.UTF-8
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".

Data page checksums are disabled.

creating directory
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Europe/Istanbul
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok

Sync to disk skipped.
The data directory might become corrupt if the operating system crashes.

Success. You can now start the database server using:

    pg_ctl -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l logfile start

# Running:
/home/postgres/postgres/src/test/ssl/../../../src/test/regress/pg_regress
--config-auth
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
### Starting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
-o --cluster-name=primary start
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 88304
ok 1 - ssl_library parameter
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 80056
# testing password-protected keys
# Running: pg_ctl -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down... done
server stopped
waiting for server to start.... stopped waiting
pg_ctl: could not start server
Examine the log output.
ok 2 - restart fails with password-protected key file with wrong password
# No postmaster PID for node "primary"
# Running: pg_ctl -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
pg_ctl: PID file
"/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata/postmaster.pid"
does not exist
Is server running?
trying to start server anyway
waiting for server to start.... done
server started
ok 3 - restart succeeds with password-protected key file
# Postmaster PID for node "primary" is 59483
# Running: pg_ctl -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... stopped waiting
pg_ctl: could not start server
Examine the log output.
ok 4 - restart fails with incorrect SSL protocol bounds
# Running: pg_ctl -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
pg_ctl: PID file
"/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata/postmaster.pid"
does not exist
Is server running?
trying to start server anyway
waiting for server to start.... done
server started
ok 5 - restart succeeds with correct SSL protocol bounds
# running client tests
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 87966
ok 6 - server doesn't accept non-SSL connections
ok 7 - server doesn't accept non-SSL connections: matches
ok 8 - connect without server root cert sslmode=require
ok 9 - connect without server root cert sslmode=verify-ca
ok 10 - connect without server root cert sslmode=verify-ca: matches
ok 11 - connect without server root cert sslmode=verify-full
ok 12 - connect without server root cert sslmode=verify-full: matches
ok 13 - connect with wrong server root cert sslmode=require
ok 14 - connect with wrong server root cert sslmode=require: matches
ok 15 - connect with wrong server root cert sslmode=verify-ca
ok 16 - connect with wrong server root cert sslmode=verify-ca: matches
ok 17 - connect with wrong server root cert sslmode=verify-full
ok 18 - connect with wrong server root cert sslmode=verify-full: matches
ok 19 - connect with server CA cert, without root CA
ok 20 - connect with server CA cert, without root CA: matches
ok 21 - connect with correct server CA cert file sslmode=require
ok 22 - connect with correct server CA cert file sslmode=verify-ca
ok 23 - connect with correct server CA cert file sslmode=verify-full
ok 24 - cert root file that contains two certificates, order 1
ok 25 - cert root file that contains two certificates, order 2
ok 26 - sslcrl option with invalid file name
ok 27 - CRL belonging to a different CA
ok 28 - CRL belonging to a different CA: matches
ok 29 - directory CRL belonging to a different CA
ok 30 - directory CRL belonging to a different CA: matches
ok 31 - CRL with a non-revoked cert
ok 32 - directory CRL with a non-revoked cert
ok 33 - mismatch between host name and server certificate sslmode=require
ok 34 - mismatch between host name and server certificate
sslmode=verify-ca
ok 35 - mismatch between host name and server certificate
sslmode=verify-full
ok 36 - mismatch between host name and server certificate
sslmode=verify-full: matches
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 54211
ok 37 - host name matching with X.509 Subject Alternative Names 1
ok 38 - host name matching with X.509 Subject Alternative Names 2
ok 39 - host name matching with X.509 Subject Alternative Names wildcard
ok 40 - host name not matching with X.509 Subject Alternative Names
ok 41 - host name not matching with X.509 Subject Alternative Names:
matches
ok 42 - host name not matching with X.509 Subject Alternative Names
wildcard
ok 43 - host name not matching with X.509 Subject Alternative Names
wildcard: matches
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 65102
ok 44 - host name matching with a single X.509 Subject Alternative Name
ok 45 - host name not matching with a single X.509 Subject Alternative
Name
ok 46 - host name not matching with a single X.509 Subject Alternative Name:
matches
ok 47 - host name not matching with a single X.509 Subject Alternative Name
wildcard
ok 48 - host name not matching with a single X.509 Subject Alternative Name
wildcard: matches
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 28120
ok 49 - certificate with both a CN and SANs 1
ok 50 - certificate with both a CN and SANs 2
ok 51 - certificate with both a CN and SANs ignores CN
ok 52 - certificate with both a CN and SANs ignores CN: matches
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 50785
ok 53 - server certificate without CN or SANs sslmode=verify-ca
ok 54 - server certificate without CN or SANs sslmode=verify-full
ok 55 - server certificate without CN or SANs sslmode=verify-full: matches
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 83429
ok 56 - connects without client-side CRL
ok 57 - does not connect with client-side CRL file
ok 58 - does not connect with client-side CRL file: matches
ok 59 - does not connect with client-side CRL directory
ok 60 - does not connect with client-side CRL directory: matches
# Running: psql -X -A -F , -P null=_null_ -d user=ssltestuser dbname=trustdb
sslcert=invalid hostaddr=127.0.0.1 host=common-name.pg-ssltest.test
sslrootcert=invalid -c SELECT * FROM pg_stat_ssl WHERE pid =
pg_backend_pid()
ok 61 - pg_stat_ssl view without client certificate: exit code 0
ok 62 - pg_stat_ssl view without client certificate: no stderr
ok 63 - pg_stat_ssl view without client certificate: matches
ok 64 - connection success with correct range of TLS protocol versions
ok 65 - connection failure with incorrect range of TLS protocol versions
ok 66 - connection failure with incorrect range of TLS protocol versions:
matches
ok 67 - connection failure with an incorrect SSL protocol minimum bound
ok 68 - connection failure with an incorrect SSL protocol minimum bound:
matches
ok 69 - connection failure with an incorrect SSL protocol maximum bound
ok 70 - connection failure with an incorrect SSL protocol maximum bound:
matches
# running server tests
ok 71 - certificate authorization fails without client cert
not ok 72 - certificate authorization fails without client cert: matches

#   Failed test 'certificate authorization fails without client cert:
matches'
#   at t/001_ssltests.pl line 402.
#                   'psql: error: connection to server at "127.0.0.1", port
56010 failed: SSL error: sslv3 alert illegal parameter'
#     doesn't match '(?^:connection requires a valid client certificate)'
not ok 73 - certificate authorization succeeds with correct client cert in
PEM format

#   Failed test 'certificate authorization succeeds with correct client cert
in PEM format'
#   at t/001_ssltests.pl line 408.
#          got: '2'
#     expected: '0'
not ok 74 - certificate authorization succeeds with correct client cert in
DER format

#   Failed test 'certificate authorization succeeds with correct client cert
in DER format'
#   at t/001_ssltests.pl line 414.
#          got: '2'
#     expected: '0'
not ok 75 - certificate authorization succeeds with correct client cert in
encrypted PEM format

#   Failed test 'certificate authorization succeeds with correct client cert
in encrypted PEM format'
#   at t/001_ssltests.pl line 420.
#          got: '2'
#     expected: '0'
not ok 76 - certificate authorization succeeds with correct client cert in
encrypted DER format

#   Failed test 'certificate authorization succeeds with correct client cert
in encrypted DER format'
#   at t/001_ssltests.pl line 426.
#          got: '2'
#     expected: '0'
ok 77 - certificate authorization fails with correct client cert and wrong
password in encrypted PEM format
ok 78 - certificate authorization fails with correct client cert and wrong
password in encrypted PEM format: matches
not ok 79 - certificate authorization succeeds with DN mapping

#   Failed test 'certificate authorization succeeds with DN mapping'
#   at t/001_ssltests.pl line 443.
#          got: '2'
#     expected: '0'
not ok 80 - certificate authorization succeeds with DN mapping: log
matches

#   Failed test 'certificate authorization succeeds with DN mapping: log
matches'
#   at t/001_ssltests.pl line 443.
#                   '2022-02-03 00:27:14.421 +03 [73952] [unknown] LOG:
connection received: host=localhost port=26092
# 2022-02-03 00:27:14.433 +03 [73952] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
# '
#     doesn't match '(?^:connection authenticated:
identity="CN=ssltestuser-dn,OU=Testing,OU=Engineering,O=PGDG"
method=cert)'
not ok 81 - certificate authorization succeeds with DN regex mapping

#   Failed test 'certificate authorization succeeds with DN regex mapping'
#   at t/001_ssltests.pl line 453.
#          got: '2'
#     expected: '0'
not ok 82 - certificate authorization succeeds with CN mapping

#   Failed test 'certificate authorization succeeds with CN mapping'
#   at t/001_ssltests.pl line 460.
#          got: '2'
#     expected: '0'
not ok 83 - certificate authorization succeeds with CN mapping: log
matches

#   Failed test 'certificate authorization succeeds with CN mapping: log
matches'
#   at t/001_ssltests.pl line 460.
#                   '2022-02-03 00:27:14.839 +03 [74476] [unknown] LOG:
connection received: host=localhost port=20094
# 2022-02-03 00:27:14.851 +03 [74476] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
# '
#     doesn't match '(?^:connection authenticated:
identity="CN=ssltestuser-dn,OU=Testing,OU=Engineering,O=PGDG"
method=cert)'
not ok 84 # TODO & SKIP Need Pty support
not ok 85 # TODO & SKIP Need Pty support
not ok 86 # TODO & SKIP Need Pty support
not ok 87 # TODO & SKIP Need Pty support
Hexadecimal number > 0xffffffff non-portable at t/001_ssltests.pl line
508.
# Running: psql -X -A -F , -P null=_null_ -d
sslrootcert=ssl/root+server_ca.crt sslmode=require dbname=certdb
hostaddr=127.0.0.1 user=ssltestuser sslcert=ssl/client.crt
sslkey=/home/postgres/postgres/src/test/ssl/tmp_check/tmp_test_b1a4/client.key
-c SELECT * FROM pg_stat_ssl WHERE pid = pg_backend_pid()
not ok 88 - pg_stat_ssl with client certificate: exit code 0

#   Failed test 'pg_stat_ssl with client certificate: exit code 0'
#   at t/001_ssltests.pl line 523.
not ok 89 - pg_stat_ssl with client certificate: no stderr

#   Failed test 'pg_stat_ssl with client certificate: no stderr'
#   at t/001_ssltests.pl line 523.
#          got: 'psql: error: connection to server at "127.0.0.1", port
56010 failed: SSL error: sslv3 alert illegal parameter
# '
#     expected: ''
not ok 90 - pg_stat_ssl with client certificate: matches

#   Failed test 'pg_stat_ssl with client certificate: matches'
#   at t/001_ssltests.pl line 523.
#                   ''
#     doesn't match
'(?^mx:^pid,ssl,version,cipher,bits,client_dn,client_serial,issuer_dn\r?\n
#
                ^\d+,t,TLSv[\d.]+,[\w-]+,\d+,/CN=ssltestuser,2315134995201656576,\/CN\=Test\
CA\ for\ PostgreSQL\ SSL\ regression\ test\ client\ certs\r?$)'
ok 91 - certificate authorization fails because of file permissions
ok 92 - certificate authorization fails because of file permissions:
matches
ok 93 - certificate authorization fails with client cert belonging to
another user
not ok 94 - certificate authorization fails with client cert belonging to
another user: matches

#   Failed test 'certificate authorization fails with client cert belonging
to another user: matches'
#   at t/001_ssltests.pl line 556.
#                   'psql: error: connection to server at "127.0.0.1", port
56010 failed: SSL error: sslv3 alert illegal parameter'
#     doesn't match '(?^:certificate authentication failed for user
"anotheruser")'
not ok 95 - certificate authorization fails with client cert belonging to
another user: log matches

#   Failed test 'certificate authorization fails with client cert belonging
to another user: log matches'
#   at t/001_ssltests.pl line 556.
#                   '2022-02-03 00:27:15.207 +03 [395] [unknown] LOG:
connection received: host=localhost port=1925
# 2022-02-03 00:27:15.227 +03 [395] [unknown] LOG:  could not accept SSL
connection: sslv3 alert illegal parameter
# '
#     doesn't match '(?^:connection authenticated: identity="CN=ssltestuser"
method=cert)'
ok 96 - certificate authorization fails with revoked client cert
not ok 97 - certificate authorization fails with revoked client cert:
matches

#   Failed test 'certificate authorization fails with revoked client cert:
matches'
#   at t/001_ssltests.pl line 565.
#                   'psql: error: connection to server at "127.0.0.1", port
56010 failed: SSL error: sslv3 alert illegal parameter'
#     doesn't match '(?^:SSL error: sslv3 alert certificate revoked)'
ok 98 - certificate authorization fails with revoked client cert: log does
not match
not ok 99 - auth_option clientcert=verify-full succeeds with matching
username and Common Name

#   Failed test 'auth_option clientcert=verify-full succeeds with matching
username and Common Name'
#   at t/001_ssltests.pl line 578.
#          got: '2'
#     expected: '0'
ok 100 - auth_option clientcert=verify-full succeeds with matching username
and Common Name: log does not match
ok 101 - auth_option clientcert=verify-full fails with mismatching username
and Common Name
not ok 102 - auth_option clientcert=verify-full fails with mismatching
username and Common Name: matches

#   Failed test 'auth_option clientcert=verify-full fails with mismatching
username and Common Name: matches'
#   at t/001_ssltests.pl line 584.
#                   'psql: error: connection to server at "127.0.0.1", port
56010 failed: SSL error: sslv3 alert illegal parameter'
#     doesn't match '(?^:FATAL: .* "trust" authentication failed for user
"anotheruser")'
ok 103 - auth_option clientcert=verify-full fails with mismatching username
and Common Name: log does not match
not ok 104 - auth_option clientcert=verify-ca succeeds with mismatching
username and Common Name

#   Failed test 'auth_option clientcert=verify-ca succeeds with mismatching
username and Common Name'
#   at t/001_ssltests.pl line 594.
#          got: '2'
#     expected: '0'
ok 105 - auth_option clientcert=verify-ca succeeds with mismatching username
and Common Name: log does not match
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 65607
not ok 106 - intermediate client certificate is provided by client

#   Failed test 'intermediate client certificate is provided by client'
#   at t/001_ssltests.pl line 605.
#          got: '2'
#     expected: '0'
ok 107 - intermediate client certificate is missing
not ok 108 - intermediate client certificate is missing: matches

#   Failed test 'intermediate client certificate is missing: matches'
#   at t/001_ssltests.pl line 608.
#                   'psql: error: connection to server at "127.0.0.1", port
56010 failed: SSL error: sslv3 alert illegal parameter'
#     doesn't match '(?^:SSL error: tlsv1 alert unknown ca)'
### Restarting node "primary"
# Running: pg_ctl -w -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-l
/home/postgres/postgres/src/test/ssl/tmp_check/log/001_ssltests_primary.log
restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 47738
ok 109 - certificate authorization fails with revoked client cert with
server-side CRL directory
not ok 110 - certificate authorization fails with revoked client cert with
server-side CRL directory: matches

#   Failed test 'certificate authorization fails with revoked client cert
with server-side CRL directory: matches'
#   at t/001_ssltests.pl line 618.
#                   'psql: error: connection to server at "127.0.0.1", port
56010 failed: SSL error: sslv3 alert illegal parameter
# connection to server at "127.0.0.1", port 56010 failed: FATAL:  no
pg_hba.conf entry for host "127.0.0.1", user "ssltestuser", database
"certdb", no encryption'
#     doesn't match '(?^:SSL error: sslv3 alert certificate revoked)'
### Stopping node "primary" using mode immediate
# Running: pg_ctl -D
/home/postgres/postgres/src/test/ssl/tmp_check/t_001_ssltests_primary_data/pgdata
-m immediate stop
waiting for server to shut down... done
server stopped
# No postmaster PID for node "primary"
# Looks like you failed 22 tests of 110.

Thanks,
Nazir Bilal Yavuz

Hi,

Daniel, Heikki, Michael CCing you as you seem to have worked most on those
tests and libressl fixes.

On 2022-02-02 19:19:22 +0000, PG Bug reporting form wrote:
> While installing PostgreSQL from source code,  SSL tests fail on OpenBSD
> 7.0.
> 
> OpenSSL Version:
> LibreSSL 3.4.1

Do we expect the SSL tests to pass when using libressl? If not, we should make
the ssl tests SKIP when using libressl...

Greetings,

Andres Freund

On Thu, Feb 3, 2022 at 10:39 AM Andres Freund <andres@anarazel.de> wrote:
> Daniel, Heikki, Michael CCing you as you seem to have worked most on those
> tests and libressl fixes.

I guess the previous commits mentioning libressl were just getting it
to compile on OpenBSD?  Very few BF animals actually run the ssl tests
(which requires setting PG_TEST_EXTRA="ssl").  That said, people are
definitely running PostgreSQL with SSL on OpenBSD in the wild, so it's
at least partially working.  I wonder if the problem is something that
needs to be configured in /etc/ssl/openssl.cnf (something like
https://obsd.solutions/en/blog/2020/06/08/libressl-error-due-to-missing-v3_ca-in-extension/
though that doesn't seem to be it).

Anyway, I can also reproduce this problem on my Vagrant image (OpenBSD
6.9 'cause I haven't got around to setting up 7).  Just in case it
helps someone who (unlike me) knows enough about libressl to debug
this and knows how to drive vagrant, here's a reproducer:

git clone https://github.com/macdice/postgresql-dev-vagrant.git
cd postgresql-dev-vagarant/openbsd6
vagrant up
... wait for installation and build ...
vagrant ssh
cd postgres/src/test/ssl
gmake check

Thomas Munro <thomas.munro@gmail.com> writes:
> Anyway, I can also reproduce this problem on my Vagrant image (OpenBSD
> 6.9 'cause I haven't got around to setting up 7).

I had an OpenBSD 6.8 image laying about, so I tried the ssl test
there, and it falls over in even more places:

Test Summary Report
-------------------
t/001_ssltests.pl (Wstat: 8448 Tests: 110 Failed: 33)
  Failed tests:  14, 16, 18-20, 28, 30-32, 58, 60, 72-76
                79-83, 88-90, 94-95, 97, 99, 102, 104, 106
                108, 110
  Non-zero exit status: 33
t/002_scram.pl   (Wstat: 1792 Tests: 11 Failed: 7)
  Failed tests:  1, 4-5, 7, 9-11
  Non-zero exit status: 7
t/003_sslinfo.pl (Wstat: 7424 Tests: 1 Failed: 1)
  Failed test:  1
  Non-zero exit status: 29
  Parse errors: Bad plan.  You planned 13 tests but ran 1.

A lot of the errors look like they didn't yet have support for
TLS 1.2; this is typical:

#   Failed test 'pg_stat_ssl with client certificate: no stderr'
#   at t/001_ssltests.pl line 523.
#          got: 'psql: error: connection to server at "127.0.0.1", port 57105 failed: SSL error: tlsv1 alert protocol
version
# This may indicate that the server does not support any SSL protocol version between TLSv1.2 and TLSv1.2.

The postmaster log entries corresponding to this look like

2022-02-02 20:13:49.420 EST [16352] [unknown] LOG:  connection received: host=localhost port=39596
2022-02-02 20:13:49.429 EST [16352] [unknown] LOG:  could not accept SSL connection: sslv3 alert illegal parameter

I don't see anything in /etc/ssl/openssl.cnf that looks related
to TLS protocol restrictions.

Perhaps 6.8 is too old to be of interest anymore, but that's
what I've got handy.

BTW, I also reproduced something that seems odd from the OP's
postmaster logs: there are what seem a quite excessive number
of checkpoints happening during these tests.  That happens
on my Linux box too, so it's not an OpenBSD issue.  It looks
like there are two per CREATE DATABASE --- I could understand
one maybe, but why two?

            regards, tom lane

Hi,

On 2022-02-02 20:31:52 -0500, Tom Lane wrote:
> BTW, I also reproduced something that seems odd from the OP's
> postmaster logs: there are what seem a quite excessive number
> of checkpoints happening during these tests.  That happens
> on my Linux box too, so it's not an OpenBSD issue.  It looks
> like there are two per CREATE DATABASE --- I could understand
> one maybe, but why two?

I think that's unfortunately normal. There's two RequestCheckpoint()s in
createdb(). We should optimize that someday...

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> On 2022-02-02 20:31:52 -0500, Tom Lane wrote:
>> BTW, I also reproduced something that seems odd from the OP's
>> postmaster logs: there are what seem a quite excessive number
>> of checkpoints happening during these tests.  That happens
>> on my Linux box too, so it's not an OpenBSD issue.  It looks
>> like there are two per CREATE DATABASE --- I could understand
>> one maybe, but why two?

> I think that's unfortunately normal. There's two RequestCheckpoint()s in
> createdb(). We should optimize that someday...

Hmm.  I wonder how much that slows down a check-world run.
I suppose the second checkpoint should be pretty speedy
for lack of anything to do, but still ...

            regards, tom lane

Hi,

On 2022-02-02 21:44:41 -0500, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > On 2022-02-02 20:31:52 -0500, Tom Lane wrote:
> >> BTW, I also reproduced something that seems odd from the OP's
> >> postmaster logs: there are what seem a quite excessive number
> >> of checkpoints happening during these tests.  That happens
> >> on my Linux box too, so it's not an OpenBSD issue.  It looks
> >> like there are two per CREATE DATABASE --- I could understand
> >> one maybe, but why two?
>
> > I think that's unfortunately normal. There's two RequestCheckpoint()s in
> > createdb(). We should optimize that someday...
>
> Hmm.  I wonder how much that slows down a check-world run.
> I suppose the second checkpoint should be pretty speedy
> for lack of anything to do, but still ...

There is a patch making CREATE DATABASE fully WAL logged [1].

cfbot timings aren't super reliable, but it provides perhaps a bit of
information.

It does seem to make individual create databases a bit faster. Comparing runs
with another patch and looking at windows (since that's the slowest and
doesn't run regression tests concurrently), we can see:

https://cirrus-ci.com/github/postgresql-cfbot/postgresql/commitfest/36/3314
https://cirrus-ci.com/github/postgresql-cfbot/postgresql/commitfest/36/3192


CF 3314:
[01:28:31.630] Checking plpgsql
[01:28:31.764] ============== creating database "pl_regression"      ==============
[01:28:32.631] CREATE DATABASE

[01:28:36.515] Checking plperl
[01:28:36.751] ============== creating database "pl_regression"      ==============
[01:28:37.560] CREATE DATABASE

[01:28:40.990] Checking plpythonu
[01:28:41.233] ============== creating database "pl_regression"      ==============
[01:28:42.057] CREATE DATABASE


CF 3192:
[07:03:54.861] Checking plpgsql
[07:03:54.986] ============== creating database "pl_regression"      ==============
[07:03:55.254] CREATE DATABASE

[07:03:58.950] Checking plperl
[07:03:59.234] ============== creating database "pl_regression"      ==============
[07:03:59.484] CREATE DATABASE

[07:04:02.724] Checking plpythonu
[07:04:02.960] ============== creating database "pl_regression"      ==============
[07:04:03.202] CREATE DATABASE

Which does seem to suggest createdb being noticably faster.

This is also visible in aggregate across several tests, e.g. "test_modules"
averaging ~45s for 36/3314, but ~30s for 36/3192.


For the longer running tap tests it doesn't seem to make much of a difference,
which make some sense.


Greetings,

Andres Freund

[1] https://commitfest.postgresql.org/36/3192/

I wrote:
> I had an OpenBSD 6.8 image laying about, so I tried the ssl test
> there, and it falls over in even more places:
> ...
> A lot of the errors look like they didn't yet have support for
> TLS 1.2; this is typical:

On further investigation, that's nonsense, because the postmaster logs
show that most if not all of the connections that are succeeding are
TLSv1.3, eg

2022-02-02 21:31:07.492 EST [96067] [unknown] LOG:  00000: connection authorized: user=ssltestuser database=trustdb
application_name=001_ssltests.plSSL enabled (protocol=TLSv1.3, cipher=AEAD-AES256-GCM-SHA384, bits=256) 

However, PG believes that the library only supports up to 1.2,
because TLS1_3_VERSION isn't defined.  I found this in
/usr/include/openssl/tls1.h:

#if defined(LIBRESSL_HAS_TLS1_3) || defined(LIBRESSL_INTERNAL)
#define TLS1_3_VERSION                  0x0304
#endif

LIBRESSL_HAS_TLS1_3 is not defined anywhere; in
/usr/include/openssl/opensslfeatures.h I find

/*
 * Feature flags for LibreSSL... so you can actually tell when things
 * are enabled, rather than not being able to tell when things are
 * enabled (or possibly not yet not implemented, or removed!).
 */
/* #define LIBRESSL_HAS_TLS1_3 */

which is about the best example I've seen lately of crappy code
falsifying the adjacent comment.

I added

#define LIBRESSL_HAS_TLS1_3 1

to pg_config.h to see what would happen.  It seems that about
the same number of tests fall over, but now the errors are
(mostly) not about TLS version.  Some look like they might
just be mismatched expectations of exactly what error will
be issued:

#   Failed test 'connect with wrong server root cert sslmode=require: matches'
#   at t/001_ssltests.pl line 170.
#                   'psql: error: connection to server at "127.0.0.1", port 62542 failed: SSL error: tlsv1 alert
unknownca' 
#     doesn't match '(?^:SSL error: certificate verify failed)'

I get the impression though that there's still some mismatch
about how to establish which CAs are trusted, and there are
still a few "tlsv1 alert protocol version" errors with no
obvious reason.

I thought for awhile that the library might be forcing a minimum
TLS version of 1.3 (despite the headers not even claiming to
support it at all), because that would fit right in with OpenBSD's
securer-than-thou ethos.  I still suspect that something like that
might be going on, but I don't have hard evidence.

            regards, tom lane

> On 3 Feb 2022, at 06:41, Tom Lane <tgl@sss.pgh.pa.us> wrote:

> However, PG believes that the library only supports up to 1.2,
> because TLS1_3_VERSION isn't defined.  I found this in
> /usr/include/openssl/tls1.h:
>
> #if defined(LIBRESSL_HAS_TLS1_3) || defined(LIBRESSL_INTERNAL)
> #define TLS1_3_VERSION                  0x0304
> #endif
>
> LIBRESSL_HAS_TLS1_3 is not defined anywhere; in
> /usr/include/openssl/opensslfeatures.h I find
>
> /*
> * Feature flags for LibreSSL... so you can actually tell when things
> * are enabled, rather than not being able to tell when things are
> * enabled (or possibly not yet not implemented, or removed!).
> */
> /* #define LIBRESSL_HAS_TLS1_3 */
>
> which is about the best example I've seen lately of crappy code
> falsifying the adjacent comment.

AFAICT from reading their (not too extensive) docs is that they consider 1.3
supporting starting with 3.4 which supports the OpenSSL 1.1.1 API.  Recent
reports [0] on their -portable Github repo are saying it still doesn't work.  I
haven't dug too far in to this yet, but will have a look.

Adding host=localhost to the connection string in the tests make all the tests
but two pass for me:

t/001_ssltests.pl .. 93/110
#   Failed test 'certificate authorization fails with revoked client cert: matches'
#   at t/001_ssltests.pl line 565.
#                   'psql: error: connection to server at "127.0.0.1", port 50547 failed: server closed the connection
unexpectedly
#     This probably means the server terminated abnormally
#     before or while processing the request.
# SSL SYSCALL error: Broken pipe'
#     doesn't match '(?^:SSL error: sslv3 alert certificate revoked)'

#   Failed test 'certificate authorization fails with revoked client cert with server-side CRL directory: matches'
#   at t/001_ssltests.pl line 618.
#                   'psql: error: connection to server at "127.0.0.1", port 50547 failed: server closed the connection
unexpectedly
#     This probably means the server terminated abnormally
#     before or while processing the request.
# SSL SYSCALL error: Broken pipe
# connection to server at "127.0.0.1", port 50547 failed: FATAL:  no pg_hba.conf entry for host "127.0.0.1", user
"ssltestuser",database "certdb", no encryption' 
#     doesn't match '(?^:SSL error: sslv3 alert certificate revoked)'
# Looks like you failed 2 tests of 110.
t/001_ssltests.pl .. Dubious, test returned 2 (wstat 512, 0x200)
Failed 2/110 subtests
t/002_scram.pl ..... ok
t/003_sslinfo.pl ... ok

The remaining tests are both CRL tests, but I haven't had time yet to dig into
why those are failing (the logs weren't terribly helpful on a quick glance).

--
Daniel Gustafsson        https://vmware.com/

[0] https://github.com/libressl-portable/portable/issues/228

Pouring over SSL test logs I was again red-herringed by the warning we get for
using hex() on a large input value, before I remembered that it's benign and
emerged from the rabbithole:

  Hexadecimal number > 0xffffffff non-portable at t/001_ssltests.pl line 508.

We could suppress it by turning off warnings for that line, since we know it
will work due to the 64-bit int test a few lines before:

@@ -505,6 +505,7 @@ if ($? == 0)
        {
                $serialno =~ s/^serial=//;
                $serialno =~ s/\s+//g;
+               local $SIG{'__WARN__'} = sub { };
                $serialno = hex($serialno);
        }
        else

Turning of warnings might be a bridge too far for some though? Thoughts?

--
Daniel Gustafsson        https://vmware.com/

Hi,

On February 3, 2022 7:48:40 AM PST, Daniel Gustafsson <daniel@yesql.se> wrote:
>Pouring over SSL test logs I was again red-herringed by the warning we get for
>using hex() on a large input value, before I remembered that it's benign and
>emerged from the rabbithole:
>
>  Hexadecimal number > 0xffffffff non-portable at t/001_ssltests.pl line 508.
>
>We could suppress it by turning off warnings for that line, since we know it
>will work due to the 64-bit int test a few lines before:
>
>@@ -505,6 +505,7 @@ if ($? == 0)
>        {
>                $serialno =~ s/^serial=//;
>                $serialno =~ s/\s+//g;
>+               local $SIG{'__WARN__'} = sub { };
>                $serialno = hex($serialno);
>        }
>        else
>
>Turning of warnings might be a bridge too far for some though? Thoughts?

Can't we just chop serialno into two 32bit numbers and call hex separately? Seems about as hard as adding a comment
explainingwhat the warn bit is about... 

Andres

--
Sent from my Android device with K-9 Mail. Please excuse my brevity.

> On 3 Feb 2022, at 16:55, Andres Freund <andres@anarazel.de> wrote:

> Can't we just chop serialno into two 32bit numbers and call hex separately?
> Seems about as hard as adding a comment explaining what the warn bit is
> about...


That doesn't not make sense.. I'll look at that instead. Thanks.

--
Daniel Gustafsson        https://vmware.com/

Daniel Gustafsson <daniel@yesql.se> writes:
> Adding host=localhost to the connection string in the tests make all the tests
> but two pass for me:

FWIW, I see no change from that on 6.8.

            regards, tom lane

> On 3 Feb 2022, at 17:47, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Daniel Gustafsson <daniel@yesql.se> writes:
>> Adding host=localhost to the connection string in the tests make all the tests
>> but two pass for me:
>
> FWIW, I see no change from that on 6.8.

Interesting.  I realize that I forgot to mention that this was on a fresh
install of 7 with LibreSSL 3.4.2.

--
Daniel Gustafsson        https://vmware.com/

> On 3 Feb 2022, at 15:25, Daniel Gustafsson <daniel@yesql.se> wrote:

> The remaining tests are both CRL tests, but I haven't had time yet to dig into
> why those are failing (the logs weren't terribly helpful on a quick glance).

Looking at these remaining failures today left me a bit confused.  It seems to
be some form of timing or synchronization issue as delaying shutdown with a
sleep(1) in the be_tls_open_server errorpath makes the tests pass.  With the
attached diff I get all tests passing on OpenBSD 7.  Following the bouncing
ball into differences between OpenSSL and LibreSSL in the revocation and
shutdown paths didn't lead to anything.

Does anyone have any ideas what this could be?

Thomas: Does the attached reproduce these results for you?

--
Daniel Gustafsson        https://vmware.com/

Hi,

On 2022-02-04 15:12:47 +0100, Daniel Gustafsson wrote:
> Looking at these remaining failures today left me a bit confused.  It seems to
> be some form of timing or synchronization issue as delaying shutdown with a
> sleep(1) in the be_tls_open_server errorpath makes the tests pass.  With the
> attached diff I get all tests passing on OpenBSD 7.  Following the bouncing
> ball into differences between OpenSSL and LibreSSL in the revocation and
> shutdown paths didn't lead to anything.

Have you checked whether openssl on openbsd doesn't have this problem? It
could be an OS issue, rather than libressl.


> Does anyone have any ideas what this could be?

I wonder if reverting 6051857fc and ed52c3707 makes a difference (like done in
the stable branches, due to windows issues)?

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> I wonder if reverting 6051857fc and ed52c3707 makes a difference (like done in
> the stable branches, due to windows issues)?

Sure hope not, because that code's inside #ifdef WIN32.

            regards, tom lane

On Sat, Feb 5, 2022 at 3:12 AM Daniel Gustafsson <daniel@yesql.se> wrote:
> Thomas: Does the attached reproduce these results for you?

-bash-5.1$ uname -a
OpenBSD openbsd6.localdomain 6.9 GENERIC.MP#473 amd64
-bash-5.1$ openssl version
LibreSSL 3.3.2
-bash-5.1$ git rev-parse HEAD
b31e3f561365136b48d63e8561f32b697df16d1d
-bash-5.1$ curl -s
https://www.postgresql.org/message-id/attachment/130677/kludge.diff |
patch -s -p1
-bash-5.1$ ./rebuild.sh
-bash-5.1$ gmake -s -C src/test/ssl check
t/001_ssltests.pl .. ok
t/002_scram.pl ..... ok
t/003_sslinfo.pl ... ok
All tests successful.
Files=3, Tests=134, 26 wallclock secs ( 0.18 usr  0.05 sys +  4.46
cusr  7.16 csys = 11.85 CPU)
Result: PASS

If I comment out your sleep(1), I get:

-bash-5.1$ gmake -s -C src/test/ssl check
t/001_ssltests.pl .. 80/110
#   Failed test 'certificate authorization fails with revoked client
cert: matches'
#   at t/001_ssltests.pl line 565.
#                   'psql: error: connection to server at "127.0.0.1",
port 61927 failed: server closed the connection unexpectedly
#     This probably means the server terminated abnormally
#     before or while processing the request.
# SSL SYSCALL error: Broken pipe'
#     doesn't match '(?^:SSL error: sslv3 alert certificate revoked)'
t/001_ssltests.pl .. 107/110
#   Failed test 'certificate authorization fails with revoked client
cert with server-side CRL directory: matches'
#   at t/001_ssltests.pl line 618.
#                   'psql: error: connection to server at "127.0.0.1",
port 61927 failed: server closed the connection unexpectedly
#     This probably means the server terminated abnormally
#     before or while processing the request.
# SSL SYSCALL error: Broken pipe
# connection to server at "127.0.0.1", port 61927 failed: FATAL:  no
pg_hba.conf entry for host "127.0.0.1", user "ssltestuser", database
"certdb", no encryption'
#     doesn't match '(?^:SSL error: sslv3 alert certificate revoked)'
# Looks like you failed 2 tests of 110.
t/001_ssltests.pl .. Dubious, test returned 2 (wstat 512, 0x200)
Failed 2/110 subtests
t/002_scram.pl ..... ok
t/003_sslinfo.pl ... ok

Test Summary Report
-------------------
t/001_ssltests.pl (Wstat: 512 Tests: 110 Failed: 2)
  Failed tests:  97, 110
  Non-zero exit status: 2
Files=3, Tests=134, 26 wallclock secs ( 0.07 usr  0.03 sys +  4.81
cusr  6.55 csys = 11.46 CPU)
Result: FAIL
gmake: *** [Makefile:32: check] Error 1

Hi,

On 2022-02-04 08:05:28 -0800, Andres Freund wrote:
> Have you checked whether openssl on openbsd doesn't have this problem? It
> could be an OS issue, rather than libressl.

FWIW, the ssl tests do pass with openssl, on openbsd 7.0, without any
patches. So it is a libressl related issue (although it can obviously be on
"our" side rather than "their" side).

Greetings,

Andres Freund

On Sat, Feb 5, 2022 at 3:12 AM Daniel Gustafsson <daniel@yesql.se> wrote:
> Looking at these remaining failures today left me a bit confused.  It seems to
> be some form of timing or synchronization issue as delaying shutdown with a
> sleep(1) in the be_tls_open_server errorpath makes the tests pass.  With the
> attached diff I get all tests passing on OpenBSD 7.  Following the bouncing
> ball into differences between OpenSSL and LibreSSL in the revocation and
> shutdown paths didn't lead to anything.
>
> Does anyone have any ideas what this could be?

usleep(1) is also enough, but usleep(0) isn't.  I wonder if something
could be disabling SO_LINGER on the socket, or somehow activating
similar data-dropping behaviour so the final ereport doesn't get
transferred.

Daniel Gustafsson <daniel@yesql.se> writes:
> Thomas: Does the attached reproduce these results for you?

FWIW, I've also reproduced these results, on a fresh OpenBSD 7.0 install
inside a qemu VM: adding "host=localhost" silences all but two failures,
and then the sleep fixes those.

HEAD:

Test Summary Report
-------------------
t/001_ssltests.pl (Wstat: 5632 Tests: 110 Failed: 22)
  Failed tests:  72-76, 79-83, 88-90, 94-95, 97, 99, 102
                104, 106, 108, 110
  Non-zero exit status: 22
t/002_scram.pl   (Wstat: 1792 Tests: 11 Failed: 7)
  Failed tests:  1, 4-5, 7, 9-11
  Non-zero exit status: 7
t/003_sslinfo.pl (Wstat: 7424 Tests: 1 Failed: 1)
  Failed test:  1
  Non-zero exit status: 29
  Parse errors: Bad plan.  You planned 13 tests but ran 1.
Files=3, Tests=122, 42 wallclock secs ( 0.12 usr  0.05 sys +  6.81 cusr  9.99 csys = 16.97 CPU)

Add "host=localhost" to tests:

Test Summary Report
-------------------
t/001_ssltests.pl (Wstat: 512 Tests: 110 Failed: 2)
  Failed tests:  97, 110
  Non-zero exit status: 2
Files=3, Tests=134, 48 wallclock secs ( 0.04 usr  0.06 sys +  8.31 cusr 12.49 csys = 20.90 CPU)

What's even more interesting:

* Adding the sleep alone fixes nothing.

* Sometimes, all the tests will pass without the sleep, just
the "host=localhost" hack.

That seems to confirm that there's a timing problem somewhere
in the CRL cases.

I don't have any theory about why "host=localhost" helps.

            regards, tom lane

I wrote:
> I don't have any theory about why "host=localhost" helps.

Hah: now I do.  The initial connection string set up by
Cluster.pm is something like

Connection string: port=65130 host=/tmp/ShNzQo5mRv

and we happily pass that bogus host name to SSL_set_tlsext_host_name.
Apparently, openssl takes such a bogus setting in stride, but libressl
not so much.  It's not entirely clear to me why this doesn't cause
*every* connection attempt to fail, but at any rate Daniel's hack
causes this to be overridden with "localhost", keeping
SSL_set_tlsext_host_name happy.  You can get the same results by
setting host='' instead (preventing SSL_set_tlsext_host_name
from being called at all).  I'd backed into this by diking out
the SSL_set_tlsext_host_name call altogether and finding that
that also makes the tests pass (after groveling through the libpq
source code and finding that that's basically the only way we
could be exposing the host setting to libressl).

I'd recommend using host='' in the tests, as that more or less
replicates what the test author probably expected to happen.

The seeming timing problem with the two CRL tests remains.

            regards, tom lane

I wrote:
> The seeming timing problem with the two CRL tests remains.

I spent some more time poking at this, and found that:

* There are three tests, not two, that intermittently fail.
They are at 001_ssltests.pl lines 565, 608, 618.  It's suspicious
that these are exactly the tests that expect to see "sslv3 alert"
or "tlsv1 alert" conditions rather than anything higher-level;
but I don't have any insight as to why that might be relevant.

* The failure occurs on the WRITE side, not the read side; the
'server closed the connection unexpectedly' message we see coming
back from libpq is from pqsecure_raw_write.  (I verified this by
changing the texts of the various instances of that message.)

* If I make my_sock_write ignore EPIPE/ECONNRESET, as per the
attached entirely-uncommitable patch, the errors go away.

I hypothesize that something about OpenBSD scheduling is allowing the
server to (sometimes) exit before the client-side openssl has flushed
all its buffers, and the client-side code doesn't handle that well.
It's not very clear why this wouldn't be affecting all users of
OpenSSL, but there you have it.

While the attached is surely no good as a general patch, could we
get away with ignoring EPIPE/ECONNRESET in writes during connection
startup?  We'd notice the failure soon enough on the read side if
it's not this problem.  (This seems a bit related to libpq's other
hacks that postpone recognition of write failures.)

By the by, today's fairywren failure [1] sure looks related:

#   Failed test 'intermediate client certificate is missing: matches'
#   at t/001_ssltests.pl line 608.
#                   'psql: error: connection to server at "127.0.0.1", port 50577 failed: could not receive data from
server:Software caused connection abort (0x00002745/10053) 
# SSL SYSCALL error: Software caused connection abort (0x00002745/10053)
# could not send startup packet: No error (0x00000000/0)'
#     doesn't match '(?^:SSL error: tlsv1 alert unknown ca)'

This is evidently on the read not write side, so it's not quite
the same thing, but ...

            regards, tom lane

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=fairywren&dt=2022-02-07%2021%3A04%3A53

diff --git a/src/interfaces/libpq/fe-secure-openssl.c b/src/interfaces/libpq/fe-secure-openssl.c
index 9f735ba437..11084a6a07 100644
--- a/src/interfaces/libpq/fe-secure-openssl.c
+++ b/src/interfaces/libpq/fe-secure-openssl.c
@@ -1697,6 +1697,10 @@ my_sock_write(BIO *h, const char *buf, int size)
                 BIO_set_retry_write(h);
                 break;

+            case EPIPE:
+            case ECONNRESET:
+                return size;
+
             default:
                 break;
         }

> On 6 Feb 2022, at 01:53, Tom Lane <tgl@sss.pgh.pa.us> wrote:

> ..we happily pass that bogus host name to SSL_set_tlsext_host_name.
> Apparently, openssl takes such a bogus setting in stride, but libressl
> not so much.

Looking at OpenSSL 1.1.1 (which is what LibreSSL claims API compatibility
with), the call ends up simply copying whatever came in without validation:

    case SSL_CTRL_SET_TLSEXT_HOSTNAME:
        /*
         * TODO(OpenSSL1.2)
         * This API is only used for a client to set what SNI it will request
         * from the server, but we currently allow it to be used on servers
         * as well, which is a programming error.  Currently we just clear
         * the field in SSL_do_handshake() for server SSLs, but when we can
         * make ABI-breaking changes, we may want to make use of this API
         * an error on server SSLs.
         */

In OpenSSL 3 they have removed the TODO marker, but still don't validate the
hostname, which explains why we don't see test errors here on the OpenSSL 3
animals (and likely wont going forward based on the comment).

In LibreSSL this is implemented with tlsext_sni_is_valid_hostname() which
checks for RFC 5890 compliance.

So, passing host='' seems the correct option.  It would be nice to be able to
run testcases which knows if we use LibreSSL or OpenSSL to test situations like
this where they do differ.

> I'd recommend using host='' in the tests, as that more or less
> replicates what the test author probably expected to happen.

Agreed. Are you taking care of that or should I?

--
Daniel Gustafsson        https://vmware.com/

> On 8 Feb 2022, at 01:30, Tom Lane <tgl@sss.pgh.pa.us> wrote:

> * If I make my_sock_write ignore EPIPE/ECONNRESET, as per the
> attached entirely-uncommitable patch, the errors go away.

I can confirm that I wasn't able to reproduce the errors with the attached (and
the sleep() removed) running the tests over and over in a loop on Linux and
OpenBSD.  Moreover, I was also unable to reproduce the error when only ignoring
EPIPE.  When only ignoring ECONNRESET it worked intermittently on OpenBSD (but
all the time on Linux as expected).

> ..could we get away with ignoring EPIPE/ECONNRESET in writes during connection
> startup?  We'd notice the failure soon enough on the read side if it's not this
> problem.  (This seems a bit related to libpq's other hacks that postpone
> recognition of write failures.)

Off the cuff I can't think of a case where it would lead to adverse effects
*during startup*.

--
Daniel Gustafsson        https://vmware.com/

Daniel Gustafsson <daniel@yesql.se> writes:
> On 6 Feb 2022, at 01:53, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> I'd recommend using host='' in the tests, as that more or less
>> replicates what the test author probably expected to happen.

On second thought, using 'localhost' as in your original patch
might be better, simply so that we do exercise the call to
SSL_set_tlsext_host_name.

> Agreed. Are you taking care of that or should I?

It's your patch, feel free.

            regards, tom lane

Daniel Gustafsson <daniel@yesql.se> writes:
> On 8 Feb 2022, at 01:30, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> ..could we get away with ignoring EPIPE/ECONNRESET in writes during connection
>> startup?  We'd notice the failure soon enough on the read side if it's not this
>> problem.  (This seems a bit related to libpq's other hacks that postpone
>> recognition of write failures.)

> Off the cuff I can't think of a case where it would lead to adverse effects
> *during startup*.

Just to note that I have a plan for fixing this part.  I've concluded
that it was a design error to implement the write_failed error
postponement mechanism in pqSendSome, and instead we should shove it
down a couple of abstraction layers into pqsecure_raw_write.  This'd
visibly have no effect on non-encrypted connections, because
pqSendSome is the only caller of pqsecure_write.  But in encrypted
connections, we'd be additionally allowing write-failure postponement
during OpenSSL's internal machinations, which seems to be exactly
what's wanted now that we have seen this failure mode.

There are some details to work through, but I hope to have a patch
soon.

            regards, tom lane

> On 8 Feb 2022, at 20:19, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Daniel Gustafsson <daniel@yesql.se> writes:
>> On 6 Feb 2022, at 01:53, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> 
> On second thought, using 'localhost' as in your original patch
> might be better, simply so that we do exercise the call to
> SSL_set_tlsext_host_name.
> 
>> Agreed. Are you taking care of that or should I?
> 
> It's your patch, feel free.

I've pushed this part to master and 14 now.

--
Daniel Gustafsson        https://vmware.com/

I wrote:
> Just to note that I have a plan for fixing this part.  I've concluded
> that it was a design error to implement the write_failed error
> postponement mechanism in pqSendSome, and instead we should shove it
> down a couple of abstraction layers into pqsecure_raw_write.  This'd
> visibly have no effect on non-encrypted connections, because
> pqSendSome is the only caller of pqsecure_write.  But in encrypted
> connections, we'd be additionally allowing write-failure postponement
> during OpenSSL's internal machinations, which seems to be exactly
> what's wanted now that we have seen this failure mode.

Here's a draft patch for that.  It seems to fix the OpenBSD problem
reliably.

I'd originally thought that everything under pqsecure_write needed to be
converted to use the write_failed mechanism, which would have required
rather invasive changes in fe-secure-openssl.c and fe-secure-gssapi.c.
But now I think we can leave those modules alone, as long as the
bottom-level physical I/O uses write_failed.  If we get some other
error out of the SSL/GSS layer, there's no harm in reporting it
right away instead of postponing it.  This reflects the fact that
it's not that easy to tell whether an OpenSSL error ought to be
classified as "read" or "write", since both I/O directions might be
going on under the hood.

BTW, this also changes what is looking to me like a thinko in
my_sock_write(): if we get a zero result from pqsecure_raw_write(),
we should not be consulting errno, because it wouldn't have
been set.  Am I missing something there?

Thoughts?

            regards, tom lane

diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 90a312bf2c..09c731729e 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -777,19 +777,19 @@ definitelyFailed:
  * (putting it in conn->inBuffer) in any situation where we can't send
  * all the specified data immediately.
  *
- * Upon write failure, conn->write_failed is set and the error message is
- * saved in conn->write_err_msg, but we clear the output buffer and return
- * zero anyway; this is because callers should soldier on until it's possible
- * to read from the server and check for an error message.  write_err_msg
- * should be reported only when we are unable to obtain a server error first.
- * (Thus, a -1 result is returned only for an internal *read* failure.)
+ * If a socket-level write failure occurs, conn->write_failed is set and the
+ * error message is saved in conn->write_err_msg, but we clear the output
+ * buffer and return zero anyway; this is because callers should soldier on
+ * until it's possible to read from the server and check for an error message.
+ * write_err_msg should be reported only when we are unable to obtain a server
+ * error first.  Much of that behavior is implemented at lower levels, but
+ * this function deals with some edge cases.
  */
 static int
 pqSendSome(PGconn *conn, int len)
 {
     char       *ptr = conn->outBuffer;
     int            remaining = conn->outCount;
-    int            oldmsglen = conn->errorMessage.len;
     int            result = 0;

     /*
@@ -817,7 +817,7 @@ pqSendSome(PGconn *conn, int len)
     if (conn->sock == PGINVALID_SOCKET)
     {
         conn->write_failed = true;
-        /* Insert error message into conn->write_err_msg, if possible */
+        /* Store error message in conn->write_err_msg, if possible */
         /* (strdup failure is OK, we'll cope later) */
         conn->write_err_msg = strdup(libpq_gettext("connection not open\n"));
         /* Discard queued data; no chance it'll ever be sent */
@@ -859,24 +859,6 @@ pqSendSome(PGconn *conn, int len)
                     continue;

                 default:
-                    /* pqsecure_write set the error message for us */
-                    conn->write_failed = true;
-
-                    /*
-                     * Transfer error message to conn->write_err_msg, if
-                     * possible (strdup failure is OK, we'll cope later).
-                     *
-                     * We only want to transfer whatever has been appended to
-                     * conn->errorMessage since we entered this routine.
-                     */
-                    if (!PQExpBufferBroken(&conn->errorMessage))
-                    {
-                        conn->write_err_msg = strdup(conn->errorMessage.data +
-                                                     oldmsglen);
-                        conn->errorMessage.len = oldmsglen;
-                        conn->errorMessage.data[oldmsglen] = '\0';
-                    }
-
                     /* Discard queued data; no chance it'll ever be sent */
                     conn->outCount = 0;

@@ -886,7 +868,18 @@ pqSendSome(PGconn *conn, int len)
                         if (pqReadData(conn) < 0)
                             return -1;
                     }
-                    return 0;
+
+                    /*
+                     * Lower-level code should already have filled
+                     * conn->write_err_msg (and set conn->write_failed) or
+                     * conn->errorMessage.  In the former case, we pretend
+                     * there's no problem; the write_failed condition will be
+                     * dealt with later.  Otherwise, report the error now.
+                     */
+                    if (conn->write_failed)
+                        return 0;
+                    else
+                        return -1;
             }
         }
         else
diff --git a/src/interfaces/libpq/fe-secure-openssl.c b/src/interfaces/libpq/fe-secure-openssl.c
index 9f735ba437..f6e563a2e5 100644
--- a/src/interfaces/libpq/fe-secure-openssl.c
+++ b/src/interfaces/libpq/fe-secure-openssl.c
@@ -1682,7 +1682,7 @@ my_sock_write(BIO *h, const char *buf, int size)

     res = pqsecure_raw_write((PGconn *) BIO_get_data(h), buf, size);
     BIO_clear_retry_flags(h);
-    if (res <= 0)
+    if (res < 0)
     {
         /* If we were interrupted, tell caller to retry */
         switch (SOCK_ERRNO)
diff --git a/src/interfaces/libpq/fe-secure.c b/src/interfaces/libpq/fe-secure.c
index 0b998e254d..a1dc7b796d 100644
--- a/src/interfaces/libpq/fe-secure.c
+++ b/src/interfaces/libpq/fe-secure.c
@@ -280,9 +280,22 @@ pqsecure_raw_read(PGconn *conn, void *ptr, size_t len)
 /*
  *    Write data to a secure connection.
  *
- * On failure, this function is responsible for appending a suitable message
- * to conn->errorMessage.  The caller must still inspect errno, but only
- * to determine whether to continue/retry after error.
+ * Returns the number of bytes written, or a negative value (with errno
+ * set) upon failure.  The write count could be less than requested.
+ *
+ * Note that socket-level hard failures are masked from the caller,
+ * instead setting conn->write_failed and storing an error message
+ * in conn->write_err_msg; see pqsecure_raw_write.  This allows us to
+ * postpone reporting of write failures until we're sure no error
+ * message is available from the server.
+ *
+ * However, errors detected in the SSL or GSS management level are reported
+ * via a negative result, with message appended to conn->errorMessage.
+ * It's frequently unclear whether such errors should be considered read or
+ * write errors, so we don't attempt to postpone reporting them.
+ *
+ * The caller must still inspect errno upon failure, but only to determine
+ * whether to continue/retry; a message has been saved someplace in any case.
  */
 ssize_t
 pqsecure_write(PGconn *conn, const void *ptr, size_t len)
@@ -310,16 +323,50 @@ pqsecure_write(PGconn *conn, const void *ptr, size_t len)
     return n;
 }

+/*
+ * Low-level implementation of pqsecure_write.
+ *
+ * This is used directly for an unencrypted connection.  For encrypted
+ * connections, this does the physical I/O on behalf of pgtls_write or
+ * pg_GSS_write.
+ *
+ * This function reports failure (i.e., returns a negative result) only
+ * for retryable errors such as EINTR.  Looping for such cases is to be
+ * handled at some outer level, maybe all the way up to the application.
+ * For hard failures, we set conn->write_failed and store an error message
+ * in conn->write_err_msg, but then claim to have written the data anyway.
+ * This is because we don't want to report write failures so long as there
+ * is a possibility of reading from the server and getting an error message
+ * that could explain why the connection dropped.  Many TCP stacks have
+ * race conditions such that a write failure may or may not be reported
+ * before all incoming data has been read.
+ *
+ * Note that this error behavior happens below the SSL management level when
+ * we are using SSL.  That's because at least some versions of OpenSSL are
+ * too quick to report a write failure when there's still a possibility to
+ * get a more useful error from the server.
+ */
 ssize_t
 pqsecure_raw_write(PGconn *conn, const void *ptr, size_t len)
 {
     ssize_t        n;
     int            flags = 0;
     int            result_errno = 0;
+    char        msgbuf[1024];
     char        sebuf[PG_STRERROR_R_BUFLEN];

     DECLARE_SIGPIPE_INFO(spinfo);

+    /*
+     * If we already had a write failure, we will never again try to send data
+     * on that connection.  Even if the kernel would let us, we've probably
+     * lost message boundary sync with the server.  conn->write_failed
+     * therefore persists until the connection is reset, and we just discard
+     * all data presented to be written.
+     */
+    if (conn->write_failed)
+        return len;
+
 #ifdef MSG_NOSIGNAL
     if (conn->sigpipe_flag)
         flags |= MSG_NOSIGNAL;
@@ -369,17 +416,29 @@ retry_masked:
                 /* FALL THRU */

             case ECONNRESET:
-                appendPQExpBufferStr(&conn->errorMessage,
-                                     libpq_gettext("server closed the connection unexpectedly\n"
-                                                   "\tThis probably means the server terminated abnormally\n"
-                                                   "\tbefore or while processing the request.\n"));
+                conn->write_failed = true;
+                /* Store error message in conn->write_err_msg, if possible */
+                /* (strdup failure is OK, we'll cope later) */
+                snprintf(msgbuf, sizeof(msgbuf),
+                         libpq_gettext("server closed the connection unexpectedly\n"
+                                       "\tThis probably means the server terminated abnormally\n"
+                                       "\tbefore or while processing the request.\n"));
+                conn->write_err_msg = strdup(msgbuf);
+                /* Now claim the write succeeded */
+                n = len;
                 break;

             default:
-                appendPQExpBuffer(&conn->errorMessage,
-                                  libpq_gettext("could not send data to server: %s\n"),
-                                  SOCK_STRERROR(result_errno,
-                                                sebuf, sizeof(sebuf)));
+                conn->write_failed = true;
+                /* Store error message in conn->write_err_msg, if possible */
+                /* (strdup failure is OK, we'll cope later) */
+                snprintf(msgbuf, sizeof(msgbuf),
+                         libpq_gettext("could not send data to server: %s\n"),
+                         SOCK_STRERROR(result_errno,
+                                       sebuf, sizeof(sebuf)));
+                conn->write_err_msg = strdup(msgbuf);
+                /* Now claim the write succeeded */
+                n = len;
                 break;
         }
     }

Hi,

On 2022-02-10 19:44:57 -0500, Tom Lane wrote:
> BTW, this also changes what is looking to me like a thinko in
> my_sock_write(): if we get a zero result from pqsecure_raw_write(),
> we should not be consulting errno, because it wouldn't have
> been set.  Am I missing something there?

It does look like an oversight. I think it's effectively harmless, because
pqsecure_raw_write() will always set up result_errno = 0, and it doesn't make
the same mistake of checking errno with a 0 result.


> + * If a socket-level write failure occurs, conn->write_failed is set and the
> + * error message is saved in conn->write_err_msg, but we clear the output
> + * buffer and return zero anyway; this is because callers should soldier on
> + * until it's possible to read from the server and check for an error message.
> + * write_err_msg should be reported only when we are unable to obtain a server
> + * error first.  Much of that behavior is implemented at lower levels, but
> + * this function deals with some edge cases.

The "soldier on until" bit seems to imply something stronger than how I
understand this to work. Makes it sound like we're going to busy loop or such
if necessary. Maybe something like "should soldier on until they have tried to
read from the server, so that server error messages can be processed"?


It's not in this change, but related. I don't really understand the
    /*
     * PQgetResult will return immediately in all states except BUSY, or if we
     * had a write failure.
     */
    return conn->asyncStatus == PGASYNC_BUSY || conn->write_failed;

business in PQisBusy(). Won't that potentially lead to clients waiting for
more network IO indefinitely, never getting around to calling PQgetResult()?

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> It's not in this change, but related. I don't really understand the

>     /*
>      * PQgetResult will return immediately in all states except BUSY, or if we
>      * had a write failure.
>      */
>     return conn->asyncStatus == PGASYNC_BUSY || conn->write_failed;

> business in PQisBusy(). Won't that potentially lead to clients waiting for
> more network IO indefinitely, never getting around to calling PQgetResult()?

I was staring at that for awhile too.  It's my own code (from 1f39a1c0641)
but it sure confuses me now; at the very least the code is not in sync
with the comment.  However, it's been that way for a couple years now and
we've not had complaints suggesting it's broken, so maybe it's the comment
that's wrong.

            regards, tom lane

Hi,

On 2022-02-10 20:25:28 -0500, Tom Lane wrote:
> I was staring at that for awhile too.  It's my own code (from 1f39a1c0641)
> but it sure confuses me now; at the very least the code is not in sync
> with the comment.  However, it's been that way for a couple years now and
> we've not had complaints suggesting it's broken, so maybe it's the comment
> that's wrong.

I wonder if it could be part of the whole "walreceiver on windows not noticing
connection death" business. Libpq internally gets a write failure, defers
reporting it, we end up in libpqrcv_PQgetResult(), which will call PQisBusy()
returning true due to write_failure, which then causes us to wait for incoming
socket IO. But WaitEventForMultipleObjects() will not be signalled again due
to the the edge triggered nature of FD_CLOSE.

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> On 2022-02-10 20:25:28 -0500, Tom Lane wrote:
>> I was staring at that for awhile too.  It's my own code (from 1f39a1c0641)
>> but it sure confuses me now; at the very least the code is not in sync
>> with the comment.  However, it's been that way for a couple years now and
>> we've not had complaints suggesting it's broken, so maybe it's the comment
>> that's wrong.

> I wonder if it could be part of the whole "walreceiver on windows not noticing
> connection death" business.

Hmm, maybe.  It sure *looks* like we need to do

-    return conn->asyncStatus == PGASYNC_BUSY || conn->write_failed;
+    return conn->asyncStatus == PGASYNC_BUSY && !conn->write_failed;

If anyone who can reproduce that Windows problem wants to try that ...

            regards, tom lane

I wrote:
> Andres Freund <andres@anarazel.de> writes:
>> I wonder if it could be part of the whole "walreceiver on windows not noticing
>> connection death" business.

> Hmm, maybe.  It sure *looks* like we need to do

> -    return conn->asyncStatus == PGASYNC_BUSY || conn->write_failed;
> +    return conn->asyncStatus == PGASYNC_BUSY && !conn->write_failed;

Dunno anything about the Windows angle, but after hacking together
a reproducer for this, I'm fairly convinced that this is indeed a bug.
The reasons we've not heard complaints are:

1. It's hard to get to.  Normally, if we hit a connection-close error
while writing, we'll come back to pqSendSome which will try to read
some data and will notice the closed connection from the read side,
thus immediately reporting an error.  Thus, usually the application
will see a failure from PQsendQuery and will never get to PQisBusy.

2. If you do manage to get into the state where PQisBusy falsely
returns true, the app is supposed to call PQconsumeInput, which
will definitely notice the closed connection from the read side
and report failure.  So there won't be anything as obvious as
an infinite loop --- but people probably don't realize that that's
not the way it's supposed to go.  You're supposed to be able to
get a PGresult from this situation, but you don't.

            regards, tom lane

I wrote:
>> Hmm, maybe.  It sure *looks* like we need to do

>> -    return conn->asyncStatus == PGASYNC_BUSY || conn->write_failed;
>> +    return conn->asyncStatus == PGASYNC_BUSY && !conn->write_failed;

> Dunno anything about the Windows angle, but after hacking together
> a reproducer for this, I'm fairly convinced that this is indeed a bug.

After further study, I now think that checking write_failed here is
the wrong thing entirely, because it's irrelevant to what we want to
do, which is keep reading until we've collected a server message or
seen read EOF.

What we do need to do though is check to see if we've closed the
socket.  That's because places like libpqwalreceiver.c assume
that if PQisBusy is true, then PQsocket() must be valid:

    while (PQisBusy(streamConn))
    {
        int            rc;

        rc = WaitLatchOrSocket(MyLatch,
                               WL_EXIT_ON_PM_DEATH | WL_SOCKET_READABLE |
                               WL_LATCH_SET,
                               PQsocket(streamConn),
                               0,
                               WAIT_EVENT_LIBPQWALRECEIVER_RECEIVE);

It seems like the existing coding in PQisBusy could allow that to fail.
I scraped the buildfarm for instances of the "cannot wait on socket
event without a socket" error that latch.c would emit if that happened,
but found none going back three months.  That's perhaps because of the
other behavior I noted that if the walsender crashes, we'll probably
report write failure immediately in PQsendQuery.  So maybe this is
mostly hypothetical in practice, but I think what we actually want
here is as attached.

In any case, I still don't see a way for this error to result in
an infinite loop, so it doesn't seem like an explanation for the
Windows problems.

            regards, tom lane

diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c
index 59121873d2..9afd4d88b4 100644
--- a/src/interfaces/libpq/fe-exec.c
+++ b/src/interfaces/libpq/fe-exec.c
@@ -1957,10 +1957,14 @@ PQisBusy(PGconn *conn)
     parseInput(conn);
 
     /*
-     * PQgetResult will return immediately in all states except BUSY, or if we
-     * had a write failure.
+     * PQgetResult will return immediately in all states except BUSY.  Also,
+     * if we've detected read EOF and dropped the connection, we can expect
+     * that PQgetResult will fail immediately.  Note that we do *not* check
+     * conn->write_failed here --- once that's become set, we know we have
+     * trouble, but we need to keep trying to read until we have a complete
+     * server message or detect read EOF.
      */
-    return conn->asyncStatus == PGASYNC_BUSY || conn->write_failed;
+    return conn->asyncStatus == PGASYNC_BUSY && conn->status != CONNECTION_BAD;
 }
 
 /*

I went ahead and pushed the patches-under-discussion (the larger
one only to HEAD, for now).  I've confirmed that the ssl tests
are solid now under OpenBSD 7.0, on bare metal as well as on the
VM I was using before.  They are still broken under OpenBSD 6.8,
which seems interesting but not so interesting that I want to
spend more time on it (seeing that 6.8 is EOL as far as
openbsd.org is concerned).  Does anyone want to recheck 6.9?

            regards, tom lane

On Sun, Feb 13, 2022 at 10:56 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> I went ahead and pushed the patches-under-discussion (the larger
> one only to HEAD, for now).  I've confirmed that the ssl tests
> are solid now under OpenBSD 7.0, on bare metal as well as on the
> VM I was using before.  They are still broken under OpenBSD 6.8,
> which seems interesting but not so interesting that I want to
> spend more time on it (seeing that 6.8 is EOL as far as
> openbsd.org is concerned).  Does anyone want to recheck 6.9?

Looks good:

t/001_ssltests.pl .. ok
t/002_scram.pl ..... ok
t/003_sslinfo.pl ... ok
All tests successful.
Files=3, Tests=134, 28 wallclock secs ( 0.04 usr  0.03 sys +  4.87
cusr  7.27 csys = 12.21 CPU)
Result: PASS
gmake: Leaving directory '/home/vagrant/postgres/src/test/ssl'
-bash-5.1$ uname -a
OpenBSD openbsd6.localdomain 6.9 GENERIC.MP#473 amd64

Thomas Munro <thomas.munro@gmail.com> writes:
> On Sun, Feb 13, 2022 at 10:56 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> I went ahead and pushed the patches-under-discussion (the larger
>> one only to HEAD, for now).  I've confirmed that the ssl tests
>> are solid now under OpenBSD 7.0, on bare metal as well as on the
>> VM I was using before.  They are still broken under OpenBSD 6.8,
>> which seems interesting but not so interesting that I want to
>> spend more time on it (seeing that 6.8 is EOL as far as
>> openbsd.org is concerned).  Does anyone want to recheck 6.9?

> Looks good:

Thanks for checking!

So I think the remaining question here is whether, and if so when,
to back-patch faa189c93.  I'm not sure that the benefit is worth
the risk of new problems (though maybe I'm just feeling particularly
pessimistic because of the regressions we've found in this week's
releases).  Leaving aside the behavior of the ssl tests, which
few people would run anyway, it seems like the benefit is just
to replace a not-very-helpful error message with a more-helpful
one.  That's worth something, but how much?

            regards, tom lane

Hi,

On 2022-02-12 20:06:24 -0500, Tom Lane wrote:
> So I think the remaining question here is whether, and if so when,
> to back-patch faa189c93.  I'm not sure that the benefit is worth
> the risk of new problems (though maybe I'm just feeling particularly
> pessimistic because of the regressions we've found in this week's
> releases).  Leaving aside the behavior of the ssl tests, which
> few people would run anyway, it seems like the benefit is just
> to replace a not-very-helpful error message with a more-helpful
> one.  That's worth something, but how much?

Yea, not sure either. Maybe slightly leaning towards not backpatching for now?
If people complain and we've gained a bit more confidence, we can still do so?

Greetings,

Andres Freund

Hi,

On 2022-02-12 16:56:38 -0500, Tom Lane wrote:
> I went ahead and pushed the patches-under-discussion (the larger
> one only to HEAD, for now).

I was just writing a test to verify that the slot / stats bug you just
encountered is / stays fixed. I ended up doing it in isolationtester, because
that was the easiest to get reliable. When terminating an isolationtester
connection, I see the FATAL twice in isolationtester output:

  step s2_init: SELECT 'init' FROM pg_create_logical_replication_slot('slot_create_error', 'test_decoding'); <waiting
...>
  step s1_terminate_s2:
      SELECT pg_terminate_backend(pid) FROM pg_stat_activity WHERE application_name = 'isolation/error/s2';

  pg_terminate_backend
  --------------------
  t
  (1 row)

  step s2_init: <... completed>
  FATAL:  terminating connection due to administrator command
  FATAL:  terminating connection due to administrator command
  server closed the connection unexpectedly
          This probably means the server terminated abnormally
          before or while processing the request.

I haven't yet tracked down whether that's related to these changes, but I
thought it was interesting enough to bring up...

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> I was just writing a test to verify that the slot / stats bug you just
> encountered is / stays fixed. I ended up doing it in isolationtester, because
> that was the easiest to get reliable. When terminating an isolationtester
> connection, I see the FATAL twice in isolationtester output:

Yeah, see

https://www.postgresql.org/message-id/flat/ab4288f8-be5c-57fb-2400-e3e857f53e46%40enterprisedb.com

I haven't thought of a way to get rid of that that I like.
(There's a cleanup proposal in that thread that I've not
yet implemented, but it won't do anything for connection-loss
cases, I think.)

            regards, tom lane

Hi,

On 2022-02-14 19:48:00 -0500, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > I was just writing a test to verify that the slot / stats bug you just
> > encountered is / stays fixed. I ended up doing it in isolationtester, because
> > that was the easiest to get reliable. When terminating an isolationtester
> > connection, I see the FATAL twice in isolationtester output:
> 
> Yeah, see
> 
> https://www.postgresql.org/message-id/flat/ab4288f8-be5c-57fb-2400-e3e857f53e46%40enterprisedb.com

Ah, thanks.

Is the generation of the duplicated error message reliable in case of a
pg_terminate_backend()? Kinda looks like it should be?

I guess I'll push the fix without a test for now...

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> Is the generation of the duplicated error message reliable in case of a
> pg_terminate_backend()? Kinda looks like it should be?

Yeah, I think it is.  libpq wouldn't notice EOF until after it
returns the backend's FATAL message.

> I guess I'll push the fix without a test for now...

Might as well push it with.  If that behavior isn't stable,
it'd be nice to know.

            regards, tom lane

Hi,

On 2022-02-14 20:22:34 -0500, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > Is the generation of the duplicated error message reliable in case of a
> > pg_terminate_backend()? Kinda looks like it should be?
> 
> Yeah, I think it is.  libpq wouldn't notice EOF until after it
> returns the backend's FATAL message.

Cool.

> > I guess I'll push the fix without a test for now...
> 
> Might as well push it with.  If that behavior isn't stable,
> it'd be nice to know.

Pushed the test now.

Greetings,

Andres Freund