Re: ldap tls test fails in some environments

Re: Thomas Munro
> In your transcript for test 20, it looks like the client (PostgreSQL)
> is hanging up without even sending a TLS ClientHello:

Maybe tests 19 and 20 are failing because 18 was already bad. (But
probably not.)

> I wonder how to figure out why... does this tell you anything?
> 
>  $ENV{'LDAPCONF'}   = $ldap_conf;
> +$ENV{"GNUTLS_DEBUG_LEVEL"} = '99';

Sorry, I had not seen your message until now. Logs attached.

Even ldapsearch ... -ZZ is failing with that slapd config, so it's not
a PG problem.

$ GNUTLS_DEBUG_LEVEL=99 ldapsearch -h localhost -p 56118 -s base -b dc=example,dc=net -D cn=Manager,dc=example,dc=net
-y/home/myon/postgresql-13-13~~devel~20200515.0434/build/src/test/ldap/tmp_check/ldappassword -n 'objectclass=*' -ZZ
 
gnutls[2]: Enabled GnuTLS 3.6.13 logging...
gnutls[2]: getrandom random generator was detected
gnutls[2]: Intel SSSE3 was detected
gnutls[2]: Intel AES accelerator was detected
gnutls[2]: Intel GCM accelerator was detected
gnutls[2]: cfg: unable to access: /etc/gnutls/config: 2
5ec3ec38 daemon: activity on 1 descriptor
5ec3ec38 daemon: activity on:
5ec3ec38 slap_listener_activate(6):
5ec3ec38 daemon: epoll: listen=6 busy
5ec3ec38 daemon: epoll: listen=7 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=8 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=9 active_threads=0 tvp=NULL
5ec3ec38 >>> slap_listener(ldap://localhost:56118)
5ec3ec38 daemon: accept() = 10
5ec3ec38 daemon: listen=6, new connection on 10
5ec3ec38 daemon: activity on 1 descriptor
5ec3ec38 daemon: activity on:
5ec3ec38 daemon: epoll: listen=6 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=7 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=8 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=9 active_threads=0 tvp=NULL
5ec3ec38 daemon: added 10r (active) listener=(nil)
5ec3ec38 daemon: activity on 1 descriptor
5ec3ec38 daemon: activity on: 10r
5ec3ec38 daemon: read active on 10
5ec3ec38 daemon: epoll: listen=6 active_threads=0 tvp=NULL
5ec3ec38 connection_get(10)
5ec3ec38 daemon: epoll: listen=7 active_threads=0 tvp=NULL
5ec3ec38 connection_get(10): got connid=1000
5ec3ec38 connection_read(10): checking for input on id=1000
5ec3ec38 daemon: epoll: listen=8 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=9 active_threads=0 tvp=NULL
5ec3ec38 daemon: activity on 1 descriptor
ber_get_next
5ec3ec38 daemon: activity on:
ldap_read: want=8, got=8
  0000:  30 1d 02 01 01 77 18 80                            0....w..
5ec3ec38 daemon: epoll: listen=6 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=7 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=8 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=9 active_threads=0 tvp=NULL
ldap_read: want=23, got=23
  0000:  16 31 2e 33 2e 36 2e 31  2e 34 2e 31 2e 31 34 36   .1.3.6.1.4.1.146
  0010:  36 2e 32 30 30 33 37                               6.20037
ber_get_next: tag 0x30 len 29 contents:
ber_dump: buf=0x7f0c50000bc0 ptr=0x7f0c50000bc0 end=0x7f0c50000bdd len=29
  0000:  02 01 01 77 18 80 16 31  2e 33 2e 36 2e 31 2e 34   ...w...1.3.6.1.4
  0010:  2e 31 2e 31 34 36 36 2e  32 30 30 33 37            .1.1466.20037
5ec3ec38 op tag 0x77, time 1589898296
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
5ec3ec38 conn=1000 op=0 do_extended
5ec3ec38 daemon: activity on 1 descriptor
5ec3ec38 daemon: activity on:
ber_scanf fmt ({m) ber:
ber_dump: buf=0x7f0c50000bc0 ptr=0x7f0c50000bc3 end=0x7f0c50000bdd len=26
5ec3ec38 daemon: epoll: listen=6 active_threads=0 tvp=NULL
  0000:  77 18 80 16 31 2e 33 2e  36 2e 31 2e 34 2e 31 2e   w...1.3.6.1.4.1.
  0010:  31 34 36 36 2e 32 30 30  33 37                     1466.20037
5ec3ec38 daemon: epoll: listen=7 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=8 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=9 active_threads=0 tvp=NULL
5ec3ec38 do_extended: oid=1.3.6.1.4.1.1466.20037
5ec3ec38 send_ldap_extended: err=0 oid= len=0
5ec3ec38 send_ldap_response: msgid=1 tag=120 err=0
ber_flush2: 14 bytes to sd 10
  0000:  30 0c 02 01 01 78 07 0a  01 00 04 00 04 00         0....x........
ldap_write: want=14, written=14
  0000:  30 0c 02 01 01 78 07 0a  01 00 04 00 04 00         0....x........
gnutls[2]: added 6 protocols, 29 ciphersuites, 19 sig algos and 10 groups into priority list
gnutls[3]: ASSERT: ../../../lib/x509/verify-high2.c[gnutls_x509_trust_list_add_trust_file]:361
ldap_start_tls: Connect error (-11)
5ec3ec38 daemon: activity on 1 descriptor
5ec3ec38 daemon: activity on: 10r
5ec3ec38 daemon: read active on 10
5ec3ec38 daemon: epoll: listen=6 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=7 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=8 active_threads=0 tvp=NULL
5ec3ec38 connection_get(10)
5ec3ec38 connection_get(10): got connid=1000
5ec3ec38 daemon: epoll: listen=9 active_threads=0 tvp=NULL
5ec3ec38 connection_read(10): checking for input on id=1000
tls_read: want=5, got=5
  0000:  30 05 02 01 02                                     0....
TLS: can't accept: An unexpected TLS packet was received..
5ec3ec38 connection_read(10): TLS accept failure error=-1 id=1000, closing
5ec3ec38 connection_closing: readying conn=1000 sd=10 for close
5ec3ec38 connection_close: conn=1000 sd=10
5ec3ec38 daemon: activity on 1 descriptor
5ec3ec38 daemon: removing 10
5ec3ec38 daemon: activity on:
5ec3ec38 daemon: epoll: listen=6 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=7 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=8 active_threads=0 tvp=NULL
5ec3ec38 daemon: epoll: listen=9 active_threads=0 tvp=NULL

There is an assertion failure:

gnutls[3]: ASSERT: ../../../lib/x509/verify-high2.c[gnutls_x509_trust_list_add_trust_file]:361

https://sources.debian.org/src/gnutls28/3.6.13-2/lib/x509/verify-high2.c/#L361

... which doesn't make sense to me yet.

Christoph