LDAP with TLS is taking more time in Postgresql 11.5

On 2/24/20 11:50 AM, Mani Sankar wrote:

Hi All,

We have recently upgraded our postgres servers from 9.4 version to 11.5
version. Post upgrade we are see delay in authentication.

Issue is when we are using ldaptls=1 the authentication takes 1 second
or greater than that. But if I disable ldaptls it's getting
authenticated within milliseconds.

But in 9.4 even if I enable ldaptls it's getting authenticated within
milliseconds any idea why we are facing the issue?

This is going to need a good deal more information:

1) OS the server is running on and did the OS or OS version change with
the upgrade?

2) How was the server installed from packages(if so from where?) or from
source?

3) The configuration for LDAP in pg_hba.conf.

4) Pertinent information from the Postgres log.

5) Pertinent information from the system log.

Regards,
Mani.

--
Adrian Klaver
adrian.klaver@aklaver.com

On Tue, 2020-02-25 at 01:20 +0530, Mani Sankar wrote:

We have recently upgraded our postgres servers from 9.4 version to 11.5 version. Post upgrade we are see delay in authentication.

Issue is when we are using ldaptls=1 the authentication takes 1 second or greater than that. But if I disable ldaptls it's getting authenticated within milliseconds.

But in 9.4 even if I enable ldaptls it's getting authenticated within milliseconds any idea why we are facing the issue?

I would use a packet sniffer like Wireshark to examine the message flow and see where the time is spent.

Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com

On 2/24/20 9:07 PM, Mani Sankar wrote:
Please reply to list also.
Ccing list.

Hi Adrian,

Thanks for replying. Below are the requested details.

################ Configuration in 9.4 PG Version

local all all ldap ldapserver=XXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser xx.xx.xx.xx/32 ldap ldapserver=XXXXXXXXXXXXXXX
ldapport=3268 ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all all 0.0.0.0/0 <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\" ldapsuffix=""
ldaptls=1

host all all ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\" ldapsuffix=""
ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\" ldapsuffix=""
ldaptls=1

############ Configuration in 11.5 Version.

local all all ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser xx.xx.xx.xx/32 ldap ldapserver=XXXXXXXXXXXXXXX
ldapport=3268 ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all all 0.0.0.0/0 <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\" ldapsuffix=""
ldaptls=1

host all all ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\" ldapsuffix=""
ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\" ldapsuffix=""
ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\" ldapsuffix=""
ldaptls=1

host    replication     replicator  XXXXXXXXXXXXX/22        md5

host    replication     replicator  1XXXXXXXXXXXX/22        md5

Linux Version: Red Hat Enterprise Linux Server release 6.10 (Santiago)

Server Installation is Source code installation. Custom build for our
environment.

Authentication logs from PG 11.5:

2020-02-24 00:00:15 MST [25089]:
application=[unknown],host=xx.xx.xxx.xx(55742),user=[unknown],db=[unknown],state=00000
LOG:  connection received: host=xx.xx.xxx.xx port=55742

2020-02-24 00:00:16 MST [25090]:
application=[unknown],host=xx.xx.xxx.xx(55748),user=[unknown],db=[unknown],state=00000
LOG:  connection received: host=xx.xx.xxx.xx port=55748

2020-02-24 00:00:16 MST [25092]:
application=[unknown],host=xx.xx.xxx.xx(55765),user=[unknown],db=[unknown],state=00000
LOG:  connection received: host=xx.xx.xxx.xx port=55765

2020-02-24 00:00:16 MST [25093]:
application=[unknown],host=xx.xx.xxx.xx(55770),user=[unknown],db=[unknown],state=00000
LOG:  connection received: host=xx.xx.xxx.xx port=55770

2020-02-24 00:00:17 MST [25090]:
application=[unknown],host=xx.xx.xxx.xx(55748),user=Someuser,db=test_db,state=00000
LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 00:00:17 MST [25089]:
application=[unknown],host=xx.xx.xxx.xx(55742),user=Someuser,db=test_db,state=00000
LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 00:00:17 MST [25092]:
application=[unknown],host=xx.xx.xxx.xx(55765),user=Someuser,db=test_db,state=00000
LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 00:00:17 MST [25093]:
application=[unknown],host=xx.xx.xxx.xx(55770),user=Someuser,db=test_db,state=00000
LOG:  connection authorized: user=Someuser database=test_db

Authentication logs from PG 9.4:

2020-02-17 22:40:01 MST [127575]:
application=[unknown],host=xx.xx.xx.xx(39451),user=[unknown],db=[unknown] LOG:
connection received: host=xx.xx.xx.xx port=39451

2020-02-17 22:40:01 MST [127575]:
application=[unknown],host=xx.xx.xx.xx(39451),user=Someuser,db=test_db
LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 21:57:44 MST [117472]:
application=[unknown],host=xx.xx.xx.xx(58500),user=[unknown],db=[unknown] LOG:
connection received: host=xx.xx.xx.xx port=58500

2020-02-24 21:57:44 MST [117472]:
application=[unknown],host=xx.xx.xx.xx(58500),user=Someuser,db=test_db
LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 21:58:27 MST [117620]:
application=[unknown],host=xx.xx.xx.xx(58520),user=[unknown],db=[unknown] LOG:
connection received: host=xx.xx.xx.xx port=58520

2020-02-24 21:58:27 MST [117620]:
application=[unknown],host=xx.xx.xx.xx(58520),user=Someuser,db=test_db
LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 21:58:31 MST [117632]:
application=[unknown],host=xx.xx.xx.xx(58524),user=[unknown],db=[unknown] LOG:
connection received: host=xx.xx.xx.xx port=58524

2020-02-24 21:58:31 MST [117632]:
application=[unknown],host=xx.xx.xx.xx(58524),user=Someuser,db=test_db
LOG:  connection authorized: user=Someuser database=test_db

We also have a local .ldaprc file with below entry

TLS_REQCERT allow

On Tue, Feb 25, 2020 at 2:28 AM Adrian Klaver <adrian.klaver@aklaver.com
<mailto:adrian.klaver@aklaver.com>> wrote:

On 2/24/20 11:50 AM, Mani Sankar wrote:

Hi All,

We have recently upgraded our postgres servers from 9.4 version

to 11.5

version. Post upgrade we are see delay in authentication.

Issue is when we are using ldaptls=1 the authentication takes 1

second

or greater than that. But if I disable ldaptls it's getting
authenticated within milliseconds.

But in 9.4 even if I enable ldaptls it's getting authenticated

within

milliseconds any idea why we are facing the issue?

This is going to need a good deal more information:

1) OS the server is running on and did the OS or OS version change with
the upgrade?

2) How was the server installed from packages(if so from where?) or
from
source?

3) The configuration for LDAP in pg_hba.conf.

4) Pertinent information from the Postgres log.

5) Pertinent information from the system log.

Regards,
Mani.

--
Adrian Klaver
adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>

--
Adrian Klaver
adrian.klaver@aklaver.com

Hi Adrian,

Should I want to try this configuration?

Regards,
Mani.

On Tue, 25 Feb, 2020, 9:24 pm Adrian Klaver, <adrian.klaver@aklaver.com>
wrote:

On 2/25/20 10:08 AM, Mani Sankar wrote:

Hi Adrian,

Should I want to try this configuration?

I thought you where already using this configuration?

Are the 9.4 and 11.5 instances are on the same machine and/or network?

In other words is ldapserver=XXXXXXXXXXXXXXX pointing at the same thing?

Regards,
Mani.

On Tue, 25 Feb, 2020, 9:24 pm Adrian Klaver, <adrian.klaver@aklaver.com
<mailto:adrian.klaver@aklaver.com>> wrote:

On 2/24/20 9:07 PM, Mani Sankar wrote:
Please reply to list also.
Ccing list.

Hi Adrian,

Thanks for replying. Below are the requested details.

################ Configuration in 9.4 PG Version

local all all ldap ldapserver=XXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser xx.xx.xx.xx/32 ldap ldapserver=XXXXXXXXXXXXXXX
ldapport=3268 ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX

ldapport=3268

ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all all 0.0.0.0/0 <http://0.0.0.0/0&gt; <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\"

ldapsuffix=""

ldaptls=1

host all all ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt;

<http://0.0.0.0/0&gt; ldap

ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\"

ldapsuffix=""

ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt;

<http://0.0.0.0/0&gt; ldap

ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\"

ldapsuffix=""

ldaptls=1

############ Configuration in 11.5 Version.

local all all ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser xx.xx.xx.xx/32 ldap ldapserver=XXXXXXXXXXXXXXX
ldapport=3268 ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all someuser ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX

ldapport=3268

ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host all all 0.0.0.0/0 <http://0.0.0.0/0&gt; <http://0.0.0.0/0&gt; ldap
ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\"

ldapsuffix=""

ldaptls=1

host all all ::1/128 ldap ldapserver=XXXXXXXXXXXXXXX ldapport=3268
ldapprefix="ADS\" ldapsuffix="" ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt;

<http://0.0.0.0/0&gt; ldap

ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\"

ldapsuffix=""

ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt;

<http://0.0.0.0/0&gt; ldap

ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\"

ldapsuffix=""

ldaptls=1

host replication someuser 0.0.0.0/0 <http://0.0.0.0/0&gt;

<http://0.0.0.0/0&gt; ldap

ldapserver=XXXXXXXXXXXXXXX ldapport=3268 ldapprefix="ADS\"

ldapsuffix=""

ldaptls=1

host    replication     replicator  XXXXXXXXXXXXX/22        md5

host    replication     replicator  1XXXXXXXXXXXX/22        md5

Linux Version: Red Hat Enterprise Linux Server release 6.10

(Santiago)

Server Installation is Source code installation. Custom build for

our

environment.

Authentication logs from PG 11.5:

2020-02-24 00:00:15 MST [25089]:

application=[unknown],host=xx.xx.xxx.xx(55742),user=[unknown],db=[unknown],state=00000

LOG:  connection received: host=xx.xx.xxx.xx port=55742

2020-02-24 00:00:16 MST [25090]:

application=[unknown],host=xx.xx.xxx.xx(55748),user=[unknown],db=[unknown],state=00000

LOG:  connection received: host=xx.xx.xxx.xx port=55748

2020-02-24 00:00:16 MST [25092]:

application=[unknown],host=xx.xx.xxx.xx(55765),user=[unknown],db=[unknown],state=00000

LOG:  connection received: host=xx.xx.xxx.xx port=55765

2020-02-24 00:00:16 MST [25093]:

application=[unknown],host=xx.xx.xxx.xx(55770),user=[unknown],db=[unknown],state=00000

LOG:  connection received: host=xx.xx.xxx.xx port=55770

2020-02-24 00:00:17 MST [25090]:

application=[unknown],host=xx.xx.xxx.xx(55748),user=Someuser,db=test_db,state=00000

LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 00:00:17 MST [25089]:

application=[unknown],host=xx.xx.xxx.xx(55742),user=Someuser,db=test_db,state=00000

LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 00:00:17 MST [25092]:

application=[unknown],host=xx.xx.xxx.xx(55765),user=Someuser,db=test_db,state=00000

LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 00:00:17 MST [25093]:

application=[unknown],host=xx.xx.xxx.xx(55770),user=Someuser,db=test_db,state=00000

LOG:  connection authorized: user=Someuser database=test_db

Authentication logs from PG 9.4:

2020-02-17 22:40:01 MST [127575]:

application=[unknown],host=xx.xx.xx.xx(39451),user=[unknown],db=[unknown]
LOG:

connection received: host=xx.xx.xx.xx port=39451

2020-02-17 22:40:01 MST [127575]:

application=[unknown],host=xx.xx.xx.xx(39451),user=Someuser,db=test_db

LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 21:57:44 MST [117472]:

application=[unknown],host=xx.xx.xx.xx(58500),user=[unknown],db=[unknown]
LOG:

connection received: host=xx.xx.xx.xx port=58500

2020-02-24 21:57:44 MST [117472]:

application=[unknown],host=xx.xx.xx.xx(58500),user=Someuser,db=test_db

LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 21:58:27 MST [117620]:

application=[unknown],host=xx.xx.xx.xx(58520),user=[unknown],db=[unknown]
LOG:

connection received: host=xx.xx.xx.xx port=58520

2020-02-24 21:58:27 MST [117620]:

application=[unknown],host=xx.xx.xx.xx(58520),user=Someuser,db=test_db

LOG:  connection authorized: user=Someuser database=test_db

2020-02-24 21:58:31 MST [117632]:

application=[unknown],host=xx.xx.xx.xx(58524),user=[unknown],db=[unknown]
LOG:

connection received: host=xx.xx.xx.xx port=58524

2020-02-24 21:58:31 MST [117632]:

application=[unknown],host=xx.xx.xx.xx(58524),user=Someuser,db=test_db

LOG:  connection authorized: user=Someuser database=test_db

We also have a local .ldaprc file with below entry

TLS_REQCERT allow

On Tue, Feb 25, 2020 at 2:28 AM Adrian Klaver

<adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>

<mailto:adrian.klaver@aklaver.com

<mailto:adrian.klaver@aklaver.com>>> wrote:

     On 2/24/20 11:50 AM, Mani Sankar wrote:
      > Hi All,
      >
      > We have recently upgraded our postgres servers from 9.4

version

     to 11.5
      > version. Post upgrade we are see delay in authentication.
      >
      > Issue is when we are using ldaptls=1 the authentication

takes 1

     second
      > or greater than that. But if I disable ldaptls it's getting
      > authenticated within milliseconds.
      >
      > But in 9.4 even if I enable ldaptls it's getting authenticated
     within
      > milliseconds any idea why we are facing the issue?

     This is going to need a good deal more information:

     1) OS the server is running on and did the OS or OS version

change with

     the upgrade?

     2) How was the server installed from packages(if so from

where?) or

     from
     source?

     3) The configuration for LDAP in pg_hba.conf.

     4) Pertinent information from the Postgres log.

     5) Pertinent information from the system log.

      >
      > Regards,
      > Mani.
      >

     --
     Adrian Klaver
adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>

<mailto:adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>>

--
Adrian Klaver
adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>

--
Adrian Klaver
adrian.klaver@aklaver.com

Hi Adrian,

Both the machines are in same network and both are pointing towards the
same LDAP server

Regards,
Mani.

On Tue, 25 Feb, 2020, 11:48 pm Adrian Klaver, <adrian.klaver@aklaver.com>
wrote:

On 2/25/20 10:23 AM, Mani Sankar wrote:

Hi Adrian,

Both the machines are in same network and both are pointing towards the
same LDAP server

I don't see any errors in the Postgres logs.

You probably should take a look at the LDAP server logs to see if there
is anything there.

You could also turn up the logging detail in Postgres to see if it
reveals anything.

Regards,
Mani.

--
Adrian Klaver
adrian.klaver@aklaver.com

On Wed, Feb 26, 2020 at 7:37 AM Adrian Klaver <adrian.klaver@aklaver.com> wrote:

On 2/25/20 10:23 AM, Mani Sankar wrote:

Hi Adrian,

Both the machines are in same network and both are pointing towards the
same LDAP server

I don't see any errors in the Postgres logs.

You probably should take a look at the LDAP server logs to see if there
is anything there.

You could also turn up the logging detail in Postgres to see if it
reveals anything.

A couple more ideas:

If you take PostgreSQL out of the picture and run the equivalent LDAP
queries with the ldapsearch command line tool, do you see the same
difference in response time? If so, I'd trace that with strace etc
with timings to see where the time is spent -- for example, is it
simply waiting for a response from the LDAP (AD?) server? If not,
I'd try tracing the PostgreSQL process and looking at the system calls
(strace -tt -T for high res times and elapsed times), perhaps using
PostgreSQL's pre_auth_delay setting to get time to attach strace.

A wild stab in the dark: if it's slow from one computer and not from
another, perhaps the problem has something to do with a variation in
reverse DNS lookup speed on the LDAP server side when it's verifying
the certificate. Or something like that.