LDAP authentication fails with concurrent create extensions - Mailing list pgsql-bugs

We are using postgresql 10.3 on Centos 7.2 with LDAP authentication (samba4 with AD domain controller). We've recently moved to LDAP authentication and are now encountering a problem where some concurrent connections that create extensions in different databases at the same time are failing with a "Can't contact LDAP server" error. The postgres error log contains:

========================================================================================

Apr 10 16:55:27.988 kvmdevdb12 postgres[10901]: [9-1] db=db_test_022,user=fullaccess LOG:  00000: LDAP login failed for user "cn=dev_fullaccess,

OU=StandardUsers,OU=Postgres,OU=ZZ,DC=company,DC=com,DC=XX" on server "server1.ZZ.net server2.ZZ.net": Can't contact LDAP server

Apr 10 16:55:27.988 kvmdevdb12 postgres[10901]: [9-2] db=db_test_022,user=fullaccess LOCATION:  CheckLDAPAuth, auth.c:2593

Apr 10 16:55:27.988 kvmdevdb12 postgres[10901]: [10-1] db=db_test_022,user=fullaccess FATAL:  28000: LDAP authentication failed for user "fullaccess"

Apr 10 16:55:27.989 kvmdevdb12 postgres[10901]: [10-2] db=db_test_022,user=fullaccess DETAIL:  Connection matched pg_hba.conf line 12: "host       all

           +systemlogin 0.0.0.0/0               ldap ldapserver="server1.ZZ.net server2.ZZ.net" ldapprefix="cn=dev_" ldapsuffix=",OU=StandardUsers,OU=Postgres,OU=ZZ,DC=company,DC=com,DC=XX""

Apr 10 16:55:27.989 kvmdevdb12 postgres[10901]: [10-3] db=db_test_022,user=fullaccess LOCATION:  auth_failed, auth.c:328

========================================================================================

The postgres version is "PostgreSQL 10.3 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-16), 64-bit" although we get similar failures with Postgres 9.5.9.

The problem is reproducible with this bash script and assumes the user password is in .pgpass:

========================================================================================

#!/bin/bash

set -u

declare -r NUM_DATABASES=50

declare -r NUM_CREATE_EXTENSIONS=1

declare -r DBHOST=kvmdevdb12

declare -r PORT=5437

declare -r USER=fullaccess

declare -r EXTENSION_NAME="btree_gin"

#declare -r EXTENSION_NAME="pgcrypto"

#declare -r EXTENSION_NAME="pg_buffercache"

#declare -r EXTENSION_NAME="tablefunc"

declare -r LOG=/tmp/drop_create.log

declare -r SIGNAL_FILE=/tmp/start_drop_create.flg

declare -r ERROR_SIGNAL_FILE=/tmp/connect_error

function get_now()

{

    date +'%Y-%m-%d %H:%M:%S.%N'

}

function create_extension()

{

    local -r DBNAME=$1

    psql -qt -p $PORT -h $DBHOST -d $DBNAME -U $USER -c "DROP EXTENSION IF EXISTS $EXTENSION_NAME; CREATE EXTENSION $EXTENSION_NAME SCHEMA extensions"

    if [[ $? != 0 ]] ; then

        echo "$(get_now): *** Error: could not create extension \"$EXTENSION_NAME\" in database \"$DBNAME\" for user \"$USER\"." | tee -a $LOG

        touch $ERROR_SIGNAL_FILE

        exit 1

    fi

}

function drop_create_db()

{

    local -r DBNAME=$1

    psql -qt -p $PORT -h $DBHOST -d postgres -U $USER -c "DROP DATABASE IF EXISTS $DBNAME"

    psql -qt -p $PORT -h $DBHOST -d postgres -U $USER -c "CREATE DATABASE $DBNAME"

        if [[ $? != 0 ]] ; then

        echo "$(get_now): *** Error: could not create database \"$DBNAME\"." | tee -a $LOG

        touch $ERROR_SIGNAL_FILE

        exit 1

    fi

    psql -qt -p $PORT -h $DBHOST -d $DBNAME -U $USER -c "CREATE SCHEMA extensions"

    if [[ $? != 0 ]] ; then

        echo "$(get_now): *** Error: could not create schema for \"$DBNAME\"." | tee -a $LOG

        touch $ERROR_SIGNAL_FILE

        exit 1

    fi

    while [[ ! -f $SIGNAL_FILE ]]; do

        :

    done;

    for i in $(seq 1 $NUM_CREATE_EXTENSIONS); do

        create_extension $DBNAME

    done

}

echo "$(get_now): Postgres version: $(psql -qt -p $PORT -h $DBHOST -d postgres -U $USER -c 'SELECT VERSION()')"

echo

echo "$(get_now): Setting up $NUM_DATABASES background jobs..."

rm -f $SIGNAL_FILE

rm -f $ERROR_SIGNAL_FILE

declare DBNAME=""

declare NUM=1

while [[ 1 ]]; do

    echo "$(get_now): Creating \"$DBHOST:$PORT/$DBNAME\"..."  >> $LOG

    DBNAME=$(printf "db_test_%03d" $NUM)

    drop_create_db $DBNAME &

    if [[ $NUM -ge $NUM_DATABASES ]]; then

        break

    fi

    NUM=$(($NUM + 1))

    echo >> $LOG

done

echo "$(get_now): Signal the $NUM_DATABASES background jobs to start creating extensions..."

touch $SIGNAL_FILE

echo "$(get_now): Waiting for all the create extensions to finish..."

echo

wait

echo

if [[ -f $ERROR_SIGNAL_FILE ]]; then

    echo "$(get_now): THERE WERE ERRORS."

    echo

fi

echo "$(get_now): *** Finished." | tee -a $LOG

========================================================================================

I did some simple debugging into 'openldap' and could get this debug information about the failure:

========================================================================================

ldap_init: trying /var/lib/pgsql/ldap/etc/openldap/ldap.conf

ldap_init: HOME env is /var/lib/pgsql

ldap_init: trying /var/lib/pgsql/ldaprc

ldap_init: trying /var/lib/pgsql/.ldaprc

ldap_init: trying ldaprc

ldap_init: LDAPCONF env is NULL

ldap_init: LDAPRC env is NULL

ldap_create

ldap_simple_bind_s

ldap_sasl_bind_s

ldap_sasl_bind

ldap_send_initial_request

ldap_new_connection 1 1 0

ldap_int_open_connection

ldap_connect_to_host: TCP server1.om.net:389

ldap_new_socket: 6

ldap_prepare_socket: 6

ldap_connect_to_host: Trying 192.168.111.111:389

ldap_pvt_connect: fd: 6 tm: -1 async: 0

attempting to connect:

connect success

ldap_open_defconn: successful

ldap_send_server_request

ldap_result ld 0x1d76380 msgid 1

wait4msg ld 0x1d76380 msgid 1 (infinite timeout)

wait4msg continue ld 0x1d76380 msgid 1 all 1

** ld 0x1d76380 Connections:

* host: server1.om.net  port: 389  (default)

  refcnt: 2  status: Connected

  last used: Tue Apr 10 15:01:01 2018

** ld 0x1d76380 Outstanding Requests:

 * msgid 1,  origid 1, status InProgress

   outstanding referrals 0, parent count 0

  ld 0x1d76380 request count 1 (abandoned 0)

** ld 0x1d76380 Response Queue:

   Empty

  ld 0x1d76380 response count 0

ldap_chkResponseList ld 0x1d76380 msgid 1 all 1

ldap_chkResponseList returns ld 0x1d76380 NULL

ldap_int_select

ldap_int_select returned -1: errno 4                              <====================== ERROR HERE

ldap_unbind

ldap_free_request (origid 1, msgid 1)

ldap_free_connection 1 1

ldap_send_unbind

ldap_free_connection: actually freed

ldap_err2string

========================================================================================

errno 4 is EINTR and the function actually failing is 'poll' inside the os-ip.c function 'ldap_int_select'.