pg.ddx.io pgsql-hackers@postgresql.org mailing list archive help / color / mirror / Atom feed From: Christoph Berg <myon@debian.org>
To: Thomas Munro <thomas.munro@gmail.com>
To: PostgreSQL Hackers <pgsql-hackers@postgresql.org>
Subject: Re: ldap tls test fails in some environments
Date: Fri, 15 May 2020 14:15:59 +0200
Message-ID: <20200515121559.GA2691@msg.df7cb.de> (raw )
In-Reply-To: <20200514111047.GA445283@msg.df7cb.de >
References: <20200508191644.GA165095@msg.df7cb.de >
<11682.1588966471@sss.pgh.pa.us >
<20200508194533.GB165095@msg.df7cb.de >
<20200513160544.GC373033@msg.df7cb.de >
<CA+hUKG+_n-zt1EAZaZfojjXh9StROu+880pRrXVvtQTWEC_UMg@mail.gmail.com >
<20200514111047.GA445283@msg.df7cb.de >
> 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
view thread (8+ messages) latest in thread
Message-ID: <20200515121559.GA2691@msg.df7cb.de>
Permalink: ../20200515121559.GA2691@msg.df7cb.de/
Also on: postgresql.org/message-id/20200515121559.GA2691@msg.df7cb.de
copy link · copy postgr.es
reply Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: myon@debian.org, thomas.munro@gmail.com
Subject: Re: ldap tls test fails in some environments
In-Reply-To: <20200515121559.GA2691@msg.df7cb.de>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox