Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1jZZG3-00046F-0K for pgsql-hackers@arkaria.postgresql.org; Fri, 15 May 2020 12:16:07 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1jZZG1-0006qR-9i for pgsql-hackers@arkaria.postgresql.org; Fri, 15 May 2020 12:16:05 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1jZZG1-0006qK-15 for pgsql-hackers@lists.postgresql.org; Fri, 15 May 2020 12:16:05 +0000 Received: from feynman.df7cb.de ([195.49.152.168]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1jZZFx-0003q7-7A for pgsql-hackers@postgresql.org; Fri, 15 May 2020 12:16:04 +0000 Received: from msg.df7cb.de (unknown [IPv6:2a02:908:1474:3de0:76e5:bff:fef3:7e00]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange ECDHE (P-256) server-signature RSA-PSS (4096 bits) server-digest SHA256) (Client did not present a certificate) by feynman.df7cb.de (Postfix) with ESMTPSA id 49NnSH5TLvz3Dwk; Fri, 15 May 2020 14:15:59 +0200 (CEST) Date: Fri, 15 May 2020 14:15:59 +0200 From: Christoph Berg To: Thomas Munro , PostgreSQL Hackers Subject: Re: ldap tls test fails in some environments Message-ID: <20200515121559.GA2691@msg.df7cb.de> Mail-Followup-To: Christoph Berg , Thomas Munro , PostgreSQL Hackers References: <20200508191644.GA165095@msg.df7cb.de> <11682.1588966471@sss.pgh.pa.us> <20200508194533.GB165095@msg.df7cb.de> <20200513160544.GC373033@msg.df7cb.de> <20200514111047.GA445283@msg.df7cb.de> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20200514111047.GA445283@msg.df7cb.de> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk > I'll see if I can catch a shell in the environment where it fails. It failed right away when I tried on the buildd machine: The slapd debug log is mostly garbage to me, the error seems to be this: ldap_read: want=8 error=Resource temporarily unavailable src/test/ldap/t/001_auth.pl: system_or_bail "sh", "-c", "$slapd -f $slapd_conf -h '$ldap_url $ldaps_url' -d 255 &"; END { kill 'INT', `cat $slapd_pidfile` if -f $slapd_pidfile; } tmp_check/log/001_auth_node.log: 2020-05-15 14:06:18.915 CEST [30486] [unknown] LOG: could not start LDAP TLS session: Connect error 2020-05-15 14:06:18.916 CEST [30486] [unknown] FATAL: LDAP authentication failed for user "test1" 2020-05-15 14:06:18.916 CEST [30486] [unknown] DETAIL: Connection matched pg_hba.conf line 1: "local all all ldap ldapserver=localhost ldapport=65510 ldapbasedn="dc=example,dc=net" ldapsearchfilter="(uid=$username)" ldaptls=1" tmp_check/log/regress_log_001_auth: # TLS ### Restarting node "node" # Running: pg_ctl -D /home/myon/postgresql-13-13~~devel~20200515.0434/build/src/test/ldap/tmp_ch eck/t_001_auth_node_data/pgdata -l /home/myon/postgresql-13-13~~devel~20200515.0434/build/src/te st/ldap/tmp_check/log/001_auth_node.log restart waiting for server to shut down.... done server stopped waiting for server to start.... done server started # Postmaster PID for node "node" is 30477 5ebe85ba daemon: activity on 1 descriptor 5ebe85ba daemon: activity on: 5ebe85ba slap_listener_activate(6): 5ebe85ba daemon: epoll: listen=6 busy 5ebe85ba daemon: epoll: listen=7 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=8 active_threads=0 tvp=NULL 5ebe85ba >>> slap_listener(ldap://localhost:65510) 5ebe85ba daemon: epoll: listen=9 active_threads=0 tvp=NULL 5ebe85ba daemon: accept() = 10 5ebe85ba daemon: listen=6, new connection on 10 5ebe85ba daemon: activity on 1 descriptor 5ebe85ba daemon: activity on: 5ebe85ba daemon: epoll: listen=6 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=7 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=8 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=9 active_threads=0 tvp=NULL 5ebe85ba daemon: added 10r (active) listener=(nil) 5ebe85ba daemon: activity on 1 descriptor 5ebe85ba daemon: activity on: 10r 5ebe85ba daemon: read active on 10 5ebe85ba daemon: epoll: listen=6 active_threads=0 tvp=NULL 5ebe85ba connection_get(10) 5ebe85ba connection_get(10): got connid=1033 5ebe85ba daemon: epoll: listen=7 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=8 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=9 active_threads=0 tvp=NULL 5ebe85ba daemon: activity on 1 descriptor 5ebe85ba connection_read(10): checking for input on id=1033 ber_get_next 5ebe85ba daemon: activity on: 5ebe85ba daemon: epoll: listen=6 active_threads=0 tvp=NULL ldap_read: want=8, got=8 0000: 30 1d 02 01 01 77 18 80 0....w.. ldap_read: want=23, got=23 5ebe85ba daemon: epoll: listen=7 active_threads=0 tvp=NULL 0000: 16 31 2e 33 2e 36 2e 31 2e 34 2e 31 2e 31 34 36 .1.3.6.1.4.1.146 5ebe85ba daemon: epoll: listen=8 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=9 active_threads=0 tvp=NULL 0010: 36 2e 32 30 30 33 37 6.20037 ber_get_next: tag 0x30 len 29 contents: ber_dump: buf=0x7fa8ec107910 ptr=0x7fa8ec107910 end=0x7fa8ec10792d 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 5ebe85ba op tag 0x77, time 1589544378 ber_get_next ldap_read: want=8 error=Resource temporarily unavailable 5ebe85ba conn=1033 op=0 do_extended ber_scanf fmt ({m) ber: 5ebe85ba daemon: activity on 1 descriptor 5ebe85ba daemon: activity on:ber_dump: buf=0x7fa8ec107910 ptr=0x7fa8ec107913 end=0x7fa8ec10792d len=26 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 5ebe85ba daemon: epoll: listen=6 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=7 active_threads=0 tvp=NULL 5ebe85ba do_extended: oid=1.3.6.1.4.1.1466.20037 5ebe85ba daemon: epoll: listen=8 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=9 active_threads=0 tvp=NULL 5ebe85ba send_ldap_extended: err=0 oid= len=0 5ebe85ba 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........ 5ebe85ba daemon: activity on 1 descriptor 5ebe85ba daemon: activity on: 10r 5ebe85ba daemon: read active on 10 5ebe85ba daemon: epoll: listen=6 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=7 active_threads=0 tvp=NULL psql:5ebe85ba connection_get(10) error: could not connect to server: FATAL: LDAP authentication failed for user "test1" 5ebe85ba daemon: epoll: listen=8 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=9 active_threads=0 tvp=NULL 5ebe85ba connection_get(10): got connid=1033 5ebe85ba connection_read(10): checking for input on id=1033 tls_read: want=5, got=5 0000: 30 05 02 01 02 0.... TLS: can't accept: An unexpected TLS packet was received.. 5ebe85ba connection_read(10): TLS accept failure error=-1 id=1033, closing 5ebe85ba connection_closing: readying conn=1033 sd=10 for close 5ebe85ba connection_close: conn=1033 sd=10 5ebe85ba daemon: removing 10 5ebe85ba daemon: activity on 1 descriptor 5ebe85ba daemon: activity on: 5ebe85ba daemon: epoll: listen=6 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=7 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=8 active_threads=0 tvp=NULL 5ebe85ba daemon: epoll: listen=9 active_threads=0 tvp=NULL not ok 19 - StartTLS # Failed test 'StartTLS' # at t/001_auth.pl line 169. # got: '2' # expected: '0' ### Restarting node "node" Christoph