Обсуждение: BUG #17391: While using --with-ssl=openssl and PG_TEST_EXTRA='ssl' options, SSL tests fail on OpenBSD 7.0
BUG #17391: While using --with-ssl=openssl and PG_TEST_EXTRA='ssl' options, SSL tests fail on OpenBSD 7.0
От
PG Bug reporting form
Дата:
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