Thread: TLS session tickets disabled?
I recently updated one of my PostgreSQL databases to 16.4. Since updating, I am unable to refresh Power BI reports that rely on the database. The error message in my PostgreSQL server's log file is "could not accept SSL connection: session id context uninitialized". I looked up the error message and found my issue in another mailing list: https://www.postgresql.org/message-id/CADT4RqBU8N-csyZuzaook-c795dt22Zcwg1aHWB6tfVdAkodZA%40mail.gmail.com.
After reading the old thread, it looks like the resolution was to make the PostgreSQL server pass SSL_OP_NO_TICKET to SSL_CTX_set_options. I believe the 16.4 update has resurrected this issue. In the 16.4 release notes, I found a bullet point that says:
"Disable creation of stateful TLS session tickets by OpenSSL.
This avoids possible failures with clients that think receipt of a session ticket means that TLS session resumption is supported."
Would it be possible to get this change reverted in the next update?
Thank you,
Cameron Vogt
Don’t forget to RSVP for our annual Customer Appreciation Day!
September 20th, 2024, from 11am-3pm
Cameron Vogt | Software Developer
Direct:314-756-2302 | Cell: 636-388-2050
cvogt@automaticcontrols.net
Attachment
Cameron Vogt <cvogt@automaticcontrols.net> writes: > I recently updated one of my PostgreSQL databases to 16.4. Since updating, I am unable to refresh Power BI reports thatrely on the database. The error message in my PostgreSQL server's log file is "could not accept SSL connection: sessionid context uninitialized". I looked up the error message and found my issue in another mailing list: https://www.postgresql.org/message-id/CADT4RqBU8N-csyZuzaook-c795dt22Zcwg1aHWB6tfVdAkodZA%40mail.gmail.com. > After reading the old thread, it looks like the resolution was to make the PostgreSQL server pass SSL_OP_NO_TICKET to SSL_CTX_set_options.I believe the 16.4 update has resurrected this issue. In the 16.4 release notes, I found a bullet pointthat says: > "Disable creation of stateful TLS session tickets by OpenSSL. > This avoids possible failures with clients that think receipt of a session ticket means that TLS session resumption issupported." > Would it be possible to get this change reverted in the next update? What is your argument that it's not the client that is broken? AFAIK, it should not be requiring a session ticket to exist. regards, tom lane
Update: I found an old NpgSQL thread at https://github.com/npgsql/npgsql/issues/576 that discusses this issue in more detail. This thread suggests adding "UseSslStream=false" to the connection string. I tested this, and now NpgSQL 4.0.10 works with PostgreSQL 16.4. Unfortunately, I cannot control the connection string Power BI uses to connect to my PostgreSQL database, but I suppose recompiling NpgSQL 4.0.10 with that option disabled by default would work. I've read in a couple places that this issue only occurs when ssl_ca_file is set, and I can confirm that my PostgreSQL server has this. So configuring ssl_ca_file may be important for anyone wishing to reproduce the issue.
I don't know enough about TLS handshakes and session tickets to know where the bug truly lies (PostgreSQL/OpenSSL vs .NET's SslStream).
Cameron Vogt | Software Developer
Direct: 314-756-2302 | Cell: 636-388-2050
1585 Fencorp Drive | Fenton, MO 63026
Automatic Controls Equipment Systems, Inc.
On Thu, Aug 15, 2024 at 10:36 AM Cameron Vogt <cvogt@automaticcontrols.net> wrote: > I don't know enough about TLS handshakes and session tickets to know where the bug truly lies (PostgreSQL/OpenSSL vs .NET'sSslStream). I'm getting the feeling that this is our bug, and that we should be using both SSL_OP_NO_TICKET (for TLSv1.2) and SSL_CTX_set_num_tickets (for TLSv1.3). I don't see any indication in the docs or source that the latter does anything for 1.2. (cc'ing Daniel) --Jacob
> On 15 Aug 2024, at 19:52, Jacob Champion <jacob.champion@enterprisedb.com> wrote: > > On Thu, Aug 15, 2024 at 10:36 AM Cameron Vogt > <cvogt@automaticcontrols.net> wrote: >> I don't know enough about TLS handshakes and session tickets to know where the bug truly lies (PostgreSQL/OpenSSL vs .NET'sSslStream). > > I'm getting the feeling that this is our bug, and that we should be > using both SSL_OP_NO_TICKET (for TLSv1.2) and SSL_CTX_set_num_tickets > (for TLSv1.3). I don't see any indication in the docs or source that > the latter does anything for 1.2. Thanks for copying me, I have been on vacation and had missed this thread. It does indeed have the smell of me messing up when reading the OpenSSL docs =( -- Daniel Gustafsson
> I recently updated one of my PostgreSQL databases to 16.4. Since updating, (...) The error message in my PostgreSQL server's log file is "could not accept SSL connection: session id context uninitialized".
I also updated my server from 16.3 > 16.4, nothing else changed and got exactly the same error. I'm also using SSL, as well as Npgsql in its current version v8.0.3 with VerifyFull including a CA file on server side.
Something is broken in PostgreSQL 16.4.
The debug5 log shows for me that the first connection is established successful, the second fails, hope it is okay to post this whole output here, perhaps it helps to fix it soon:
2024-08-15 13:24:33.298 CEST [1] DEBUG: forked new backend, pid=37 socket=11
2024-08-15 13:24:33.299 CEST [37] LOG: connection received: host=192.168.0.24 port=40653
2024-08-15 13:24:33.305 CEST [37] DEBUG: SSL: handshake start: "before SSL initialization"
2024-08-15 13:24:33.305 CEST [37] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.305 CEST [37] DEBUG: SSL: accept exit (-1): "before SSL initialization"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read client hello"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write server hello"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write certificate"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write key exchange"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write certificate request"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write server done"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept exit (-1): "SSLv3/TLS write server done"
2024-08-15 13:24:33.419 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write server done"
2024-08-15 13:24:33.420 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read client certificate"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read client key exchange"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read certificate verify"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read change cipher spec"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read finished"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write session ticket"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write change cipher spec"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write finished"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL: handshake done: "SSL negotiation finished successfully"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL: accept exit (1): "SSL negotiation finished successfully"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL connection from DN:"CN=rw_user" CN:"rw_user"
2024-08-15 13:24:33.432 CEST [37] DEBUG: InitPostgres
2024-08-15 13:24:33.432 CEST [37] DEBUG: my backend ID is 3
2024-08-15 13:24:33.433 CEST [37] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.433 CEST [37] LOG: connection authenticated: identity="CN=rw_user" method=cert (/etc/postgresql/config/pg_hba.test.conf:130)
2024-08-15 13:24:33.433 CEST [37] LOG: connection authorized: user=rw_user database=somedb SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256)
2024-08-15 13:24:33.434 CEST [37] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.457 CEST [37] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.467 CEST [37] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.479 CEST [37] DEBUG: shmem_exit(0): 4 before_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: shmem_exit(0): 6 on_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: proc_exit(0): 3 callbacks to make
2024-08-15 13:24:33.480 CEST [37] LOG: disconnection: session time: 0:00:00.180 user=rw_user database=somedb host=192.168.0.24 port=40653
2024-08-15 13:24:33.480 CEST [37] DEBUG: SSL: write alert (0x0100): "SSL negotiation finished successfully"
2024-08-15 13:24:33.480 CEST [37] DEBUG: exit(0)
2024-08-15 13:24:33.480 CEST [37] DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: proc_exit(-1): 0 callbacks to make
2024-08-15 13:24:33.483 CEST [1] DEBUG: reaping dead processes
2024-08-15 13:24:33.483 CEST [1] DEBUG: server process (PID 37) exited with exit code 0
2024-08-15 13:24:33.495 CEST [1] DEBUG: forked new backend, pid=38 socket=11
2024-08-15 13:24:33.496 CEST [38] LOG: connection received: host=192.168.0.24 port=40654
2024-08-15 13:24:33.496 CEST [38] DEBUG: SSL: handshake start: "before SSL initialization"
2024-08-15 13:24:33.496 CEST [38] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.496 CEST [38] DEBUG: SSL: accept exit (-1): "before SSL initialization"
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL: write alert (0x0250): "error"
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL: accept exit (-1): "error"
2024-08-15 13:24:33.543 CEST [38] LOG: could not accept SSL connection: session id context uninitialized
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL connection from DN:"(anonymous)" CN:"(anonymous)"
2024-08-15 13:24:33.543 CEST [38] DEBUG: shmem_exit(0): 0 before_shmem_exit callbacks to make
2024-08-15 13:24:33.543 CEST [38] DEBUG: shmem_exit(0): 0 on_shmem_exit callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: proc_exit(0): 1 callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: exit(0)
2024-08-15 13:24:33.544 CEST [38] DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: proc_exit(-1): 0 callbacks to make
2024-08-15 13:24:33.546 CEST [1] DEBUG: reaping dead processes
2024-08-15 13:24:33.546 CEST [1] DEBUG: server process (PID 38) exited with exit code 0
2024-08-15 13:24:33.299 CEST [37] LOG: connection received: host=192.168.0.24 port=40653
2024-08-15 13:24:33.305 CEST [37] DEBUG: SSL: handshake start: "before SSL initialization"
2024-08-15 13:24:33.305 CEST [37] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.305 CEST [37] DEBUG: SSL: accept exit (-1): "before SSL initialization"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read client hello"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write server hello"
2024-08-15 13:24:33.393 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write certificate"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write key exchange"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write certificate request"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write server done"
2024-08-15 13:24:33.395 CEST [37] DEBUG: SSL: accept exit (-1): "SSLv3/TLS write server done"
2024-08-15 13:24:33.419 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write server done"
2024-08-15 13:24:33.420 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read client certificate"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read client key exchange"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read certificate verify"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read change cipher spec"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS read finished"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write session ticket"
2024-08-15 13:24:33.421 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write change cipher spec"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL: accept loop: "SSLv3/TLS write finished"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL: handshake done: "SSL negotiation finished successfully"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL: accept exit (1): "SSL negotiation finished successfully"
2024-08-15 13:24:33.422 CEST [37] DEBUG: SSL connection from DN:"CN=rw_user" CN:"rw_user"
2024-08-15 13:24:33.432 CEST [37] DEBUG: InitPostgres
2024-08-15 13:24:33.432 CEST [37] DEBUG: my backend ID is 3
2024-08-15 13:24:33.433 CEST [37] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.433 CEST [37] LOG: connection authenticated: identity="CN=rw_user" method=cert (/etc/postgresql/config/pg_hba.test.conf:130)
2024-08-15 13:24:33.433 CEST [37] LOG: connection authorized: user=rw_user database=somedb SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256)
2024-08-15 13:24:33.434 CEST [37] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.457 CEST [37] DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.467 CEST [37] DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-08-15 13:24:33.479 CEST [37] DEBUG: shmem_exit(0): 4 before_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: shmem_exit(0): 6 on_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: proc_exit(0): 3 callbacks to make
2024-08-15 13:24:33.480 CEST [37] LOG: disconnection: session time: 0:00:00.180 user=rw_user database=somedb host=192.168.0.24 port=40653
2024-08-15 13:24:33.480 CEST [37] DEBUG: SSL: write alert (0x0100): "SSL negotiation finished successfully"
2024-08-15 13:24:33.480 CEST [37] DEBUG: exit(0)
2024-08-15 13:24:33.480 CEST [37] DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make
2024-08-15 13:24:33.480 CEST [37] DEBUG: proc_exit(-1): 0 callbacks to make
2024-08-15 13:24:33.483 CEST [1] DEBUG: reaping dead processes
2024-08-15 13:24:33.483 CEST [1] DEBUG: server process (PID 37) exited with exit code 0
2024-08-15 13:24:33.495 CEST [1] DEBUG: forked new backend, pid=38 socket=11
2024-08-15 13:24:33.496 CEST [38] LOG: connection received: host=192.168.0.24 port=40654
2024-08-15 13:24:33.496 CEST [38] DEBUG: SSL: handshake start: "before SSL initialization"
2024-08-15 13:24:33.496 CEST [38] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.496 CEST [38] DEBUG: SSL: accept exit (-1): "before SSL initialization"
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL: accept loop: "before SSL initialization"
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL: write alert (0x0250): "error"
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL: accept exit (-1): "error"
2024-08-15 13:24:33.543 CEST [38] LOG: could not accept SSL connection: session id context uninitialized
2024-08-15 13:24:33.543 CEST [38] DEBUG: SSL connection from DN:"(anonymous)" CN:"(anonymous)"
2024-08-15 13:24:33.543 CEST [38] DEBUG: shmem_exit(0): 0 before_shmem_exit callbacks to make
2024-08-15 13:24:33.543 CEST [38] DEBUG: shmem_exit(0): 0 on_shmem_exit callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: proc_exit(0): 1 callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: exit(0)
2024-08-15 13:24:33.544 CEST [38] DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make
2024-08-15 13:24:33.544 CEST [38] DEBUG: proc_exit(-1): 0 callbacks to make
2024-08-15 13:24:33.546 CEST [1] DEBUG: reaping dead processes
2024-08-15 13:24:33.546 CEST [1] DEBUG: server process (PID 38) exited with exit code 0
Daniel Gustafsson <daniel@yesql.se> writes: > On 15 Aug 2024, at 19:52, Jacob Champion <jacob.champion@enterprisedb.com> wrote: >>> I'm getting the feeling that this is our bug, and that we should be >>> using both SSL_OP_NO_TICKET (for TLSv1.2) and SSL_CTX_set_num_tickets >>> (for TLSv1.3). I don't see any indication in the docs or source that >>> the latter does anything for 1.2. > The attached, backpatched all the way, should be the correct fix. Sorry for > the mess =( Can we verify that this fixes the originally-reported problem? regards, tom lane
I can confirm the .diff patch Daniel sent over solves my issue. Here are the steps I took to verify:
I downloaded PostrgeSQL 16.4's source code and figured out how to compile it using the official documentation. I configured a new testing PostgreSQL server (built from the source) to mimic the configuration of my original database. Before implementing the patch, I verified that I still get the same issue when connecting via NpgSQL 4.0.10 to the source-built testing server. Then I implemented the patch, recompiled everything, and I verified that the issue is now gone when connecting via NpgSQL 4.0.10.
Thank you!
Cameron Vogt | Software Developer
Direct: 314-756-2302 | Cell: 636-388-2050
1585 Fencorp Drive | Fenton, MO 63026
Automatic Controls Equipment Systems, Inc.
On Fri, Aug 16, 2024 at 12:12 PM Cameron Vogt <cvogt@automaticcontrols.net> wrote: > > I can confirm the .diff patch Daniel sent over solves my issue. I also tested against a Python stack that's session-aware and was producing the same error message, and the patch fixes it. Thanks! --Jacob
> On 17 Aug 2024, at 01:00, Jacob Champion <jacob.champion@enterprisedb.com> wrote: > > On Fri, Aug 16, 2024 at 12:12 PM Cameron Vogt > <cvogt@automaticcontrols.net> wrote: >> >> I can confirm the .diff patch Daniel sent over solves my issue. > > I also tested against a Python stack that's session-aware and was > producing the same error message, and the patch fixes it. Thanks for confirming, once I have better access to my laptop (should be tomorrow Sunday or Monday at the latest) I'll get this committed and backpatched. -- Daniel Gustafsson
> On 17 Aug 2024, at 23:27, Daniel Gustafsson <daniel@yesql.se> wrote: > >> On 17 Aug 2024, at 01:00, Jacob Champion <jacob.champion@enterprisedb.com> wrote: >> >> On Fri, Aug 16, 2024 at 12:12 PM Cameron Vogt >> <cvogt@automaticcontrols.net> wrote: >>> >>> I can confirm the .diff patch Daniel sent over solves my issue. >> >> I also tested against a Python stack that's session-aware and was >> producing the same error message, and the patch fixes it. > > Thanks for confirming, once I have better access to my laptop (should be > tomorrow Sunday or Monday at the latest) I'll get this committed and > backpatched. This has now been done. -- Daniel Gustafsson