Thread: src/test/perl/TestLib.pm: check_pg_config needs/usr/include/postgresql/pg_config.h
src/test/perl/TestLib.pm: check_pg_config needs/usr/include/postgresql/pg_config.h
From
Christoph Berg
Date:
I believe check_pg_config as used by src/test/ssl/t/002_scram.pl
shouldn't rely on /usr/include/postgresql/pg_config.h but use the file
from the build tree instead:
src/test/perl/TestLib.pm:
Return the number of matches of the given regular expression
within the installation's C<pg_config.h>.
=cut
sub check_pg_config
{
my ($regexp) = @_;
my ($stdout, $stderr);
my $result = IPC::Run::run [ 'pg_config', '--includedir' ], '>',
\$stdout, '2>', \$stderr
or die "could not execute pg_config";
chomp($stdout);
$stdout =~ s/\r$//;
open my $pg_config_h, '<', "$stdout/pg_config.h" or die "$!"; <-- here
my $match = (grep { /^$regexp/ } <$pg_config_h>);
close $pg_config_h;
return $match;
}
src/test/ssl/README claims that it is possible to run the "ssl" extra
test from make check (as opposed to installcheck).
Christoph
Re: src/test/perl/TestLib.pm: check_pg_config needs /usr/include/postgresql/pg_config.h
From
Tom Lane
Date:
Christoph Berg <myon@debian.org> writes:
> I believe check_pg_config as used by src/test/ssl/t/002_scram.pl
> shouldn't rely on /usr/include/postgresql/pg_config.h but use the file
> from the build tree instead:
But during "make check", that should be executing pg_config from the
the temporary installation, so we should get the right answer no?
Conversely, in "make installcheck" scenarios, we definitely do want
the value from the installed file, or so I should think.
Do you have a concrete scenario where you're getting wrong behavior?
regards, tom lane
Re: src/test/perl/TestLib.pm: check_pg_config needs/usr/include/postgresql/pg_config.h
From
Christoph Berg
Date:
Re: Tom Lane > But during "make check", that should be executing pg_config from the > the temporary installation, so we should get the right answer no? > > Conversely, in "make installcheck" scenarios, we definitely do want > the value from the installed file, or so I should think. > > Do you have a concrete scenario where you're getting wrong behavior? I just added the extra tests to the postgresql-13 package and got this: $ cat build/src/test/ssl/tmp_check/log/regress_log_002_scram No such file or directory at /srv/projects/postgresql/pg/master/build/../src/test/perl/TestLib.pm line 595. But I just realized that the problem is caused by a Debian-specific patch that removes the find_my_exec logic from pg_config and replaces it with PGBINDIR. We need that patch because we install pg_config to both /usr/bin and /usr/lib/postgresql/<version>/bin and want the same output from both. I'll revisit that to see if we can come up with a different solution. Christoph
> I just added the extra tests to the postgresql-13 package and got
> this:
Some other problem emerged here in the ldap test:
17:28:58
17:28:58 # Failed test 'StartTLS'
17:28:58 # at t/001_auth.pl line 169.
17:28:58 # got: '2'
17:28:58 # expected: '0'
17:28:58
17:28:58 # Failed test 'LDAPS'
17:28:58 # at t/001_auth.pl line 169.
17:28:58 # got: '2'
17:28:58 # expected: '0'
17:28:59
17:28:59 # Failed test 'LDAPS with URL'
17:28:59 # at t/001_auth.pl line 169.
17:28:59 # got: '2'
17:28:59 # expected: '0'
17:28:59 # Looks like you failed 3 tests of 22.
17:28:59 t/001_auth.pl ..
...
17:28:59 # diagnostic message
17:28:59 ok 18 - any attempt fails due to bad search pattern
17:28:59 # TLS
17:28:59 not ok 19 - StartTLS
17:28:59 not ok 20 - LDAPS
17:28:59 not ok 21 - LDAPS with URL
17:28:59 ok 22 - bad combination of LDAPS and StartTLS
17:28:59 Dubious, test returned 3 (wstat 768, 0x300)
src/test/ldap/tmp_check/log/slapd.log is empty.
It consistently fails on the build server, but works on my notebook.
Maybe that simply means slapd is crashing, but there's no slapd
output. Would it be possible to start slapd with "-d 255", even if
that means it doesn't background itself?
That'd be in src/test/ldap/t/001_auth.pl:
system_or_bail $slapd, '-f', $slapd_conf, '-h', "$ldap_url $ldaps_url";
END
{
kill 'INT', `cat $slapd_pidfile` if -f $slapd_pidfile;
}
Server and test output below:
17:28:59 2020-05-13 15:28:58.136 UTC [31564] LOG: starting PostgreSQL 13devel (Debian
13~~devel~20200513.1505-1~801.git043e3e0.pgdg+1)on x86_64-pc-linux-gnu, compiled by gcc (Debian 9.3.0-12) 9.3.0,
64-bit
17:28:59 2020-05-13 15:28:58.136 UTC [31564] LOG: listening on Unix socket "/tmp/gM2rQtsMib/.s.PGSQL.53078"
17:28:59 2020-05-13 15:28:58.139 UTC [31565] LOG: database system was shut down at 2020-05-13 15:28:58 UTC
17:28:59 2020-05-13 15:28:58.142 UTC [31564] LOG: database system is ready to accept connections
17:28:59 2020-05-13 15:28:58.230 UTC [31573] [unknown] LOG: LDAP login failed for user "?uid=test1" on server
"localhost":Invalid DN syntax
17:28:59 2020-05-13 15:28:58.230 UTC [31573] [unknown] DETAIL: LDAP diagnostics: invalid DN
17:28:59 2020-05-13 15:28:58.230 UTC [31573] [unknown] FATAL: LDAP authentication failed for user "test1"
17:28:59 2020-05-13 15:28:58.230 UTC [31573] [unknown] DETAIL: Connection matched pg_hba.conf line 1: "local all all
ldapldapserver=localhost ldapport=53076 ldapprefix="?uid=" ldapsuffix="""
17:28:59 2020-05-13 15:28:58.264 UTC [31564] LOG: received fast shutdown request
17:28:59 2020-05-13 15:28:58.264 UTC [31564] LOG: aborting any active transactions
17:28:59 2020-05-13 15:28:58.266 UTC [31564] LOG: background worker "logical replication launcher" (PID 31571) exited
withexit code 1
17:28:59 2020-05-13 15:28:58.266 UTC [31566] LOG: shutting down
17:28:59 2020-05-13 15:28:58.271 UTC [31564] LOG: database system is shut down
17:28:59 2020-05-13 15:28:58.384 UTC [31575] LOG: starting PostgreSQL 13devel (Debian
13~~devel~20200513.1505-1~801.git043e3e0.pgdg+1)on x86_64-pc-linux-gnu, compiled by gcc (Debian 9.3.0-12) 9.3.0,
64-bit
17:28:59 2020-05-13 15:28:58.385 UTC [31575] LOG: listening on Unix socket "/tmp/gM2rQtsMib/.s.PGSQL.53078"
17:28:59 2020-05-13 15:28:58.387 UTC [31576] LOG: database system was shut down at 2020-05-13 15:28:58 UTC
17:28:59 2020-05-13 15:28:58.390 UTC [31575] LOG: database system is ready to accept connections
17:28:59 2020-05-13 15:28:58.479 UTC [31584] [unknown] LOG: could not start LDAP TLS session: Connect error
17:28:59 2020-05-13 15:28:58.479 UTC [31584] [unknown] FATAL: LDAP authentication failed for user "test1"
17:28:59 2020-05-13 15:28:58.479 UTC [31584] [unknown] DETAIL: Connection matched pg_hba.conf line 1: "local all all
ldapldapserver=localhost ldapport=53076 ldapbasedn="dc=example,dc=net" ldapsearchfilter="(uid=$username)" ldaptls=1"
17:28:59 2020-05-13 15:28:58.514 UTC [31575] LOG: received fast shutdown request
17:28:59 2020-05-13 15:28:58.514 UTC [31575] LOG: aborting any active transactions
17:28:59 2020-05-13 15:28:58.516 UTC [31575] LOG: background worker "logical replication launcher" (PID 31582) exited
withexit code 1
17:28:59 2020-05-13 15:28:58.516 UTC [31577] LOG: shutting down
17:28:59 2020-05-13 15:28:58.520 UTC [31575] LOG: database system is shut down
17:28:59 2020-05-13 15:28:58.634 UTC [31586] LOG: starting PostgreSQL 13devel (Debian
13~~devel~20200513.1505-1~801.git043e3e0.pgdg+1)on x86_64-pc-linux-gnu, compiled by gcc (Debian 9.3.0-12) 9.3.0,
64-bit
17:28:59 2020-05-13 15:28:58.634 UTC [31586] LOG: listening on Unix socket "/tmp/gM2rQtsMib/.s.PGSQL.53078"
17:28:59 2020-05-13 15:28:58.636 UTC [31587] LOG: database system was shut down at 2020-05-13 15:28:58 UTC
17:28:59 2020-05-13 15:28:58.639 UTC [31586] LOG: database system is ready to accept connections
17:28:59 2020-05-13 15:28:58.728 UTC [31595] [unknown] LOG: could not perform initial LDAP bind for ldapbinddn "" on
server"localhost": Can't contact LDAP server
17:28:59 2020-05-13 15:28:58.728 UTC [31595] [unknown] FATAL: LDAP authentication failed for user "test1"
17:28:59 2020-05-13 15:28:58.728 UTC [31595] [unknown] DETAIL: Connection matched pg_hba.conf line 1: "local all all
ldapldapserver=localhost ldapscheme=ldaps ldapport=53077 ldapbasedn="dc=example,dc=net"
ldapsearchfilter="(uid=$username)""
17:28:59 2020-05-13 15:28:58.763 UTC [31586] LOG: received fast shutdown request
17:28:59 2020-05-13 15:28:58.764 UTC [31586] LOG: aborting any active transactions
17:28:59 2020-05-13 15:28:58.766 UTC [31586] LOG: background worker "logical replication launcher" (PID 31593) exited
withexit code 1
17:28:59 2020-05-13 15:28:58.766 UTC [31588] LOG: shutting down
17:28:59 2020-05-13 15:28:58.772 UTC [31586] LOG: database system is shut down
17:28:59 2020-05-13 15:28:58.886 UTC [31597] LOG: starting PostgreSQL 13devel (Debian
13~~devel~20200513.1505-1~801.git043e3e0.pgdg+1)on x86_64-pc-linux-gnu, compiled by gcc (Debian 9.3.0-12) 9.3.0,
64-bit
17:28:59 2020-05-13 15:28:58.886 UTC [31597] LOG: listening on Unix socket "/tmp/gM2rQtsMib/.s.PGSQL.53078"
17:28:59 2020-05-13 15:28:58.888 UTC [31598] LOG: database system was shut down at 2020-05-13 15:28:58 UTC
17:28:59 2020-05-13 15:28:58.891 UTC [31597] LOG: database system is ready to accept connections
17:28:59 2020-05-13 15:28:58.977 UTC [31606] [unknown] LOG: could not perform initial LDAP bind for ldapbinddn "" on
server"localhost": Can't contact LDAP server
17:28:59 2020-05-13 15:28:58.977 UTC [31606] [unknown] FATAL: LDAP authentication failed for user "test1"
17:28:59 2020-05-13 15:28:58.977 UTC [31606] [unknown] DETAIL: Connection matched pg_hba.conf line 1: "local all all
ldapldapurl="ldaps://localhost:53077/dc=example,dc=net??sub?(uid=$username)""
17:28:59 2020-05-13 15:28:59.014 UTC [31597] LOG: received fast shutdown request
17:28:59 2020-05-13 15:28:59.014 UTC [31597] LOG: aborting any active transactions
17:28:59 2020-05-13 15:28:59.017 UTC [31597] LOG: background worker "logical replication launcher" (PID 31604) exited
withexit code 1
17:28:59 2020-05-13 15:28:59.019 UTC [31599] LOG: shutting down
17:28:59 2020-05-13 15:28:59.025 UTC [31597] LOG: database system is shut down
17:28:59 2020-05-13 15:28:59.135 UTC [31608] LOG: starting PostgreSQL 13devel (Debian
13~~devel~20200513.1505-1~801.git043e3e0.pgdg+1)on x86_64-pc-linux-gnu, compiled by gcc (Debian 9.3.0-12) 9.3.0,
64-bit
17:28:59 2020-05-13 15:28:59.135 UTC [31608] LOG: listening on Unix socket "/tmp/gM2rQtsMib/.s.PGSQL.53078"
17:28:59 2020-05-13 15:28:59.137 UTC [31609] LOG: database system was shut down at 2020-05-13 15:28:59 UTC
17:28:59 2020-05-13 15:28:59.140 UTC [31608] LOG: database system is ready to accept connections
17:28:59 2020-05-13 15:28:59.228 UTC [31617] [unknown] LOG: could not start LDAP TLS session: Can't contact LDAP
server
17:28:59 2020-05-13 15:28:59.228 UTC [31617] [unknown] FATAL: LDAP authentication failed for user "test1"
17:28:59 2020-05-13 15:28:59.228 UTC [31617] [unknown] DETAIL: Connection matched pg_hba.conf line 1: "local all all
ldapldapurl="ldaps://localhost:53077/dc=example,dc=net??sub?(uid=$username)" ldaptls=1"
17:28:59 2020-05-13 15:28:59.264 UTC [31608] LOG: received immediate shutdown request
17:28:59 2020-05-13 15:28:59.265 UTC [31613] WARNING: terminating connection because of crash of another server
process
17:28:59 2020-05-13 15:28:59.265 UTC [31613] DETAIL: The postmaster has commanded this server process to roll back the
currenttransaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
17:28:59 2020-05-13 15:28:59.265 UTC [31613] HINT: In a moment you should be able to reconnect to the database and
repeatyour command.
17:28:59 2020-05-13 15:28:59.268 UTC [31608] LOG: database system is shut down
17:28:59 ******** build/src/test/ldap/tmp_check/log/regress_log_001_auth ********
17:28:59 1..22
17:28:59 # Checking port 53076
17:28:59 # Found port 53076
17:28:59 # Checking port 53077
17:28:59 # Found port 53077
17:28:59 # setting up slapd
17:28:59 # Running: openssl req -new -nodes -keyout /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/ca.key
-x509-out /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/ca.crt -subj /CN=CA
17:28:59 Generating a RSA private key
17:28:59 ...........+++++
17:28:59 ...............+++++
17:28:59 writing new private key to '/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/ca.key'
17:28:59 -----
17:28:59 # Running: openssl req -new -nodes -keyout
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/server.key-out
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/server.csr-subj /CN=server
17:28:59 Generating a RSA private key
17:28:59 ..............+++++
17:28:59 .............+++++
17:28:59 writing new private key to '/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/server.key'
17:28:59 -----
17:28:59 # Running: openssl x509 -req -in /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/server.csr -CA
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/ca.crt-CAkey
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/ca.key-CAcreateserial -out
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd-certs/server.crt
17:28:59 Signature ok
17:28:59 subject=CN = server
17:28:59 Getting CA Private Key
17:28:59 # Running: /usr/sbin/slapd -f /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/slapd.conf -h
ldap://localhost:53076ldaps://localhost:53077
17:28:59 # Running: ldapsearch -h localhost -p 53076 -s base -b dc=example,dc=net -D cn=Manager,dc=example,dc=net -y
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/ldappassword-n 'objectclass=*'
17:28:59 # extended LDIF
17:28:59 #
17:28:59 # LDAPv3
17:28:59 # base <dc=example,dc=net> with scope baseObject
17:28:59 # filter: 'objectclass=*'
17:28:59 # requesting: ALL
17:28:59 #
17:28:59
17:28:59 # loading LDAP data
17:28:59 # Running: ldapadd -x -y /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/ldappassword -f authdata.ldif
17:28:59 adding new entry "dc=example,dc=net"
17:28:59
17:28:59 adding new entry "uid=test1,dc=example,dc=net"
17:28:59
17:28:59 adding new entry "uid=test2,dc=example,dc=net"
17:28:59
17:28:59 # Running: ldappasswd -x -y /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/ldappassword -s secret1
uid=test1,dc=example,dc=net
17:28:59 # Running: ldappasswd -x -y /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/ldappassword -s secret2
uid=test2,dc=example,dc=net
17:28:59 # setting up PostgreSQL instance
17:28:59 # Checking port 53078
17:28:59 # Found port 53078
17:28:59 Name: node
17:28:59 Data directory: /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata
17:28:59 Backup directory: /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/backup
17:28:59 Archive directory: /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/archives
17:28:59 Connection string: port=53078 host=/tmp/gM2rQtsMib
17:28:59 Log file: /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.log
17:28:59 # Running: initdb -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -A trust -N
17:28:59 The files belonging to this database system will be owned by user "buildd".
17:28:59 This user must also own the server process.
17:28:59
17:28:59 The database cluster will be initialized with locale "C".
17:28:59 The default database encoding has accordingly been set to "SQL_ASCII".
17:28:59 The default text search configuration will be set to "english".
17:28:59
17:28:59 Data page checksums are disabled.
17:28:59
17:28:59 creating directory /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata ... ok
17:28:59 creating subdirectories ... ok
17:28:59 selecting dynamic shared memory implementation ... posix
17:28:59 selecting default max_connections ... 100
17:28:59 selecting default shared_buffers ... 128MB
17:28:59 selecting default time zone ... Etc/UTC
17:28:59 creating configuration files ... ok
17:28:59 running bootstrap script ... ok
17:28:59 performing post-bootstrap initialization ... ok
17:28:59
17:28:59 Sync to disk skipped.
17:28:59 The data directory might become corrupt if the operating system crashes.
17:28:59
17:28:59 Success. You can now start the database server using:
17:28:59
17:28:59 pg_ctl -D '/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata' -l logfile start
17:28:59
17:28:59 # Running: /<<PKGBUILDDIR>>/build/src/test/ldap/../../../src/test/regress/pg_regress --config-auth
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata
17:28:59 ### Starting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.log-o --cluster-name=node start
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31451
17:28:59 # running tests
17:28:59 # simple bind
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31466
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test0"
17:28:59 ok 1 - simple bind authentication fails if user not found in LDAP
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 ok 2 - simple bind authentication fails with wrong password
17:28:59 1
17:28:59 ok 3 - simple bind authentication succeeds
17:28:59 # search+bind
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31481
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test0"
17:28:59 ok 4 - search+bind authentication fails if user not found in LDAP
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 ok 5 - search+bind authentication fails with wrong password
17:28:59 1
17:28:59 ok 6 - search+bind authentication succeeds
17:28:59 # multiple servers
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31496
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test0"
17:28:59 ok 7 - search+bind authentication fails if user not found in LDAP
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 ok 8 - search+bind authentication fails with wrong password
17:28:59 1
17:28:59 ok 9 - search+bind authentication succeeds
17:28:59 # LDAP URLs
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31511
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test0"
17:28:59 ok 10 - search+bind with LDAP URL authentication fails if user not found in LDAP
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 ok 11 - search+bind with LDAP URL authentication fails with wrong password
17:28:59 1
17:28:59 ok 12 - search+bind with LDAP URL authentication succeeds
17:28:59 # search filters
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31526
17:28:59 1
17:28:59 ok 13 - search filter finds by uid
17:28:59 1
17:28:59 ok 14 - search filter finds by mail
17:28:59 # search filters in LDAP URLs
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31539
17:28:59 1
17:28:59 ok 15 - search filter finds by uid
17:28:59 1
17:28:59 ok 16 - search filter finds by mail
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31552
17:28:59 1
17:28:59 ok 17 - combined LDAP URL and search filter
17:28:59 # diagnostic message
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31564
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 ok 18 - any attempt fails due to bad search pattern
17:28:59 # TLS
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31575
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 not ok 19 - StartTLS
17:28:59
17:28:59 # Failed test 'StartTLS'
17:28:59 # at t/001_auth.pl line 169.
17:28:59 # got: '2'
17:28:59 # expected: '0'
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31586
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 not ok 20 - LDAPS
17:28:59
17:28:59 # Failed test 'LDAPS'
17:28:59 # at t/001_auth.pl line 169.
17:28:59 # got: '2'
17:28:59 # expected: '0'
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31597
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 not ok 21 - LDAPS with URL
17:28:59
17:28:59 # Failed test 'LDAPS with URL'
17:28:59 # at t/001_auth.pl line 169.
17:28:59 # got: '2'
17:28:59 # expected: '0'
17:28:59 ### Restarting node "node"
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -l
/<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/log/001_auth_node.logrestart
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 waiting for server to start.... done
17:28:59 server started
17:28:59 # Postmaster PID for node "node" is 31608
17:28:59 psql: error: could not connect to server: FATAL: LDAP authentication failed for user "test1"
17:28:59 ok 22 - bad combination of LDAPS and StartTLS
17:28:59 ### Stopping node "node" using mode immediate
17:28:59 # Running: pg_ctl -D /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata -m immediate
stop
17:28:59 waiting for server to shut down.... done
17:28:59 server stopped
17:28:59 # No postmaster PID for node "node"
17:28:59 # Looks like you failed 3 tests of 22.
17:28:59 make[1]: *** [debian/rules:193: override_dh_auto_test-arch] Error 1
Christoph
On Thu, May 14, 2020 at 4:05 AM Christoph Berg <myon@debian.org> wrote:
> Some other problem emerged here in the ldap test:
Hi Christoph,
> 17:28:59 Data directory: /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata
I know nothing about Debian package building so I could be missing
something about how this works, but I wonder if our script variable
handling is hygienic enough for paths like that. Let's see... I get
an error due to that when I run "make -C src/test/ldap check" from a
source tree under "/<<PKGBUILDDIR>>/build":
sh: 1: cannot create /build/src/test/ldap/tmp_check/slapd.pid:
Directory nonexistent
That's fixable with:
- kill 'INT', `cat $slapd_pidfile` if -f $slapd_pidfile;
+ kill 'INT', `cat "$slapd_pidfile"` if -f "$slapd_pidfile";
That's a side issue, though.
> 17:28:59 # TLS
> 17:28:59 not ok 19 - StartTLS
> 17:28:59 not ok 20 - LDAPS
> 17:28:59 not ok 21 - LDAPS with URL
> It consistently fails on the build server, but works on my notebook.
> Maybe that simply means slapd is crashing, but there's no slapd
> output. Would it be possible to start slapd with "-d 255", even if
> that means it doesn't background itself?
That'd require more scripting to put it in the background...
> 17:28:59 2020-05-13 15:28:58.479 UTC [31584] [unknown] LOG: could not start LDAP TLS session: Connect error
> 17:28:59 2020-05-13 15:28:58.728 UTC [31595] [unknown] LOG: could not perform initial LDAP bind for ldapbinddn "" on
server"localhost": Can't contact LDAP server
Hmm, I get exactly the same errors as this if I comment out the
following part of the test script:
# don't bother to check the server's cert (though perhaps we should)
append_to_file(
$ldap_conf,
qq{TLS_REQCERT never
});
That's a file that we point to with the environment variable LDAPCONF.
The man page for ldap.conf says:
Thus the following files and variables are read, in order:
variable $LDAPNOINIT, and if that is not set:
system file /etc/ldap/ldap.conf,
user files $HOME/ldaprc, $HOME/.ldaprc, ./ldaprc,
system file $LDAPCONF,
user files $HOME/$LDAPRC, $HOME/.$LDAPRC, ./$LDAPRC,
variables $LDAP<uppercase option name>.
Settings late in the list override earlier ones.
This leads me to suspect that something in your build server's
environment that comes later in that list is overridding the
TLS_REQCERT setting. If that's the explanation, perhaps we should do
this, which seems to work OK on my system, since it comes last in the
list:
-$ENV{'LDAPCONF'} = $ldap_conf;
+$ENV{'LDAPTLS_REQCERT'} = "never";
Re: Thomas Munro > > 17:28:59 Data directory: /<<PKGBUILDDIR>>/build/src/test/ldap/tmp_check/t_001_auth_node_data/pgdata > > I know nothing about Debian package building so I could be missing > something about how this works, but I wonder if our script variable > handling is hygienic enough for paths like that. That's from the sbuild log filter, the special chars are not the problem: 17:06:41 I: NOTICE: Log filtering will replace 'build/postgresql-13-fdfISX/postgresql-13-13~~devel~20200513.1505' with '<<PKGBUILDDIR>>' 17:06:41 I: NOTICE: Log filtering will replace 'build/postgresql-13-fdfISX' with '<<BUILDDIR>>' > > It consistently fails on the build server, but works on my notebook. > > Maybe that simply means slapd is crashing, but there's no slapd > > output. Would it be possible to start slapd with "-d 255", even if > > that means it doesn't background itself? > > That'd require more scripting to put it in the background... Maybe adding "&" is enough, provided it still writes the pid file for shutting down... > This leads me to suspect that something in your build server's > environment that comes later in that list is overridding the > TLS_REQCERT setting. If that's the explanation, perhaps we should do > this, which seems to work OK on my system, since it comes last in the > list: It's not messing with environment variables in that area. I'll see if I can catch a shell in the environment where it fails. Christoph
> 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=localhostldapport=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
Christoph Berg <myon@debian.org> writes:
> The slapd debug log is mostly garbage to me, the error seems to be
> this:
> ldap_read: want=8 error=Resource temporarily unavailable
Hm, so EAGAIN (although that's a BSD-ish spelling of the strerror
string, which seems pretty odd in a Debian context). I don't think
that's actually an error, it's just the daemon's data collection
logic trying to read data that isn't there. It then goes on and
issues a response, so this must not indicate that the request is
incomplete --- it's just a useless speculative read.
Somebody should get out the LDAP RFCs and decode the packet contents
that this log helpfully provides, but I suspect that we're just looking
at an authentication failure; there's still not much clue as to why.
regards, tom lane
Re: Tom Lane > Somebody should get out the LDAP RFCs and decode the packet contents > that this log helpfully provides, but I suspect that we're just looking > at an authentication failure; there's still not much clue as to why. The non-TLS tests work, so it's not a plain auth failure... I'm attaching the full logs from that test, maybe someone with more insight can compare the non-TLS with the TLS bits. Would it help to re-run that with log_debug on the PG side? Christoph
Attachment
On Sat, May 16, 2020 at 2:25 AM Christoph Berg <myon@debian.org> wrote:
> > Somebody should get out the LDAP RFCs and decode the packet contents
> > that this log helpfully provides, but I suspect that we're just looking
> > at an authentication failure; there's still not much clue as to why.
>
> The non-TLS tests work, so it's not a plain auth failure...
>
> I'm attaching the full logs from that test, maybe someone with more
> insight can compare the non-TLS with the TLS bits.
>
> Would it help to re-run that with log_debug on the PG side?
In your transcript for test 20, it looks like the client (PostgreSQL)
is hanging up without even sending a TLS ClientHello:
tls_read: want=5, got=0
...
psql:TLS: can't accept: The TLS connection was non-properly terminated..
With 001_auth.tl hacked to enable debug as you suggested*, on a local
Debian 10 system I see:
tls_read: want=5, got=5
0000: 16 03 01 01 4c ....L
That's: 0x16 = handshake record, 0x03 0x01 = TLS 1.0, and then a
record length for the following ClientHello. You're not even getting
that far, so I guess libdap is setting up the connection but then the
GNU TLS library (what Debian links libldap against) is not happy, even
before any negotiations begin. I wonder how to figure out why... does
this tell you anything?
$ENV{'LDAPCONF'} = $ldap_conf;
+$ENV{"GNUTLS_DEBUG_LEVEL"} = '99';
* Like this:
-system_or_bail $slapd, '-f', $slapd_conf, '-h', "$ldap_url $ldaps_url";
+system("$slapd -d 255 -f $slapd_conf -h '$ldap_url $ldaps_url' &");
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