search

389ds / 389-ds-base

The enterprise-class Open Source LDAP server for Linux
https://www.port389.org/
Other
211 stars 92 forks source link

Freeipa user authentication slow using 389 1.3.2.9-1 #993

Closed 389-ds-bot closed 4 years ago

389-ds-bot commented 4 years ago

Cloned from Pagure issue: https://pagure.io/389-ds-base/issue/47656

After setting up freeipa on FC20 i noticed that logins were slow. I then installed FC19 and did the exact same setup as on FC20 and there the logins were fast.

I now have installed the FC19 389 packages on FC20 and the problem is also solved.

So the problem is probably related to 389 version 1.3.2.9-1 but what kind of logging should i provide?

It looks like the kerberos server cannot answer in time (query 389 server). The client then sents a second reuqest using tcp.

Attached is some logging for fc19 389 packages and fc20

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-02 16:46:42

error log fc19 packages fc19-packages.error.log

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-02 16:47:07

access log fc19 packages fc19-packages.log

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-02 16:47:27

error log fc20 packages fc20-packages.error.log

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-02 16:47:48

access log fc20 packages fc20-packages.log

389-ds-bot commented 4 years ago

Comment from lkrispen (@elkris) at 2014-01-14 18:34:30

I looked into the logs and all operations seem to be fast, all etimes are 0. What could indicate a slow response is that there are some gaps between conscutive operations, like here op=31 and op=32:

[02/Jan/2014:05:21:38 -0500] conn=7 op=31 SRCH base="idnsName=_tcp,idnsname=domain12.nl,cn=dns,dc=domain12,dc=nl" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL [02/Jan/2014:05:21:38 -0500] conn=7 op=31 RESULT err=32 tag=101 nentries=0 etime=0 [02/Jan/2014:05:21:41 -0500] conn=7 op=32 SRCH base="idnsName=_udp,idnsname=domain12.nl,cn=dns,dc=domain12,dc=nl" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL [02/Jan/2014:05:21:41 -0500] conn=7 op=32 RESULT err=32 tag=101 nentries=0 etime=0

But looking into the error logs, where connection activity is logged, we see: [02/Jan/2014:05:21:38 -0500] - activity on 67r [02/Jan/2014:05:21:38 -0500] - read activity on 67 [02/Jan/2014:05:21:41 -0500] - activity on 67r [02/Jan/2014:05:21:41 -0500] - read activity on 67

so op=32 only is received at 05:21:41, so the problem seems to be on the client side. If you switch between F19 and F20, is there also a difference in the version of IPA ?

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-16 01:16:24

Well i have installed freeipa on fedora 19 and 20 and only the latter seems to be slow. When i install the 389 version from fedora 19 on fedora 20 (using the rpms from 19) then the problem goes away.

The client fc 20 and ubuntu both work ok when using with the f19 freeipa server install and f20 install using the 389 rpms from fc19.

389-ds-bot commented 4 years ago

Comment from lkrispen (@elkris) at 2014-01-17 13:59:27

So this looks like 389 is the reason for a performance drop, but from the logs you provided I cannot see where the response of 389 would be slow. What do you measure whne you say it is slow ? Do we nned a specific client load, could you give the steps to reproduce the problem ?

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-17 14:43:16

To reproduce you should do a clean FreeIPA install on FC19 and 20.

The after configuration (do i need to provide those steps also?) install a client and connect it with freeipa-client-install to the freeipa server. The a simple kinit takes about 1 sec on FC19 Freeipa server and 4 to 5 secs on FC20 FreeIPA server. KRB5_TRACE=/dev/stdout kinit admin

You can notice a delay using the above command that the client tries udp first and always succeed on FC19 server but fails on FC20 server so a second call using tcp is requested.

That behaviour is gone when downgrading the 389 packages to the rpms from fc19.

William

389-ds-bot commented 4 years ago

Comment from lkrispen (@elkris) at 2014-01-17 14:50:14

Thanks, I will investigate. I'm just not yet familiar with IPA, I do see the world only from 389

389-ds-bot commented 4 years ago

Comment from pspacek at 2014-01-17 19:49:07

Replying to [comment:5 cobradevil]:

KRB5_TRACE=/dev/stdout kinit admin Please redirect KRB5_TRACE to a file and provide logs from Fedora 19 and 20 so we see what is happening. We are unable to reproduce this problem in our lab so we need more information.

Thank you!

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-17 20:48:25

This is logging with a fedora 20 client against FC19 freeipa install and FC20 freeipa install.

I'm also on irc now..

This is on FC20 KRB5_TRACE=/dev/stdout kinit admin [23977] 1389969758.101454: Getting initial credentials for admin@DOMAIN12.NL [23977] 1389969758.102046: Sending request (181 bytes) to DOMAIN12.NL [23977] 1389969758.190436: Resolving hostname test2.domain12.nl. [23977] 1389969758.191304: Sending initial UDP request to dgram 10.0.0.254:88 [23977] 1389969759.191583: Resolving hostname test2.domain12.nl. [23977] 1389969759.193152: Initiating TCP connection to stream 10.0.0.254:88 [23977] 1389969759.193566: Sending TCP request to stream 10.0.0.254:88 [23977] 1389969759.483094: Received answer from stream 10.0.0.254:88 [23977] 1389969759.573815: Response was from master KDC [23977] 1389969759.573853: Received error from KDC: -1765328359/Additional pre-authentication required [23977] 1389969759.573900: Processing preauth types: 136, 19, 2, 142, 133 [23977] 1389969759.573914: Selected etype info: etype aes256-cts, salt "/9MR-vmlC`67#=P", params "" [23977] 1389969759.573920: Received cookie: MIT Password for admin@DOMAIN12.NL: [23977] 1389969764.776075: AS key obtained for encrypted timestamp: aes256-cts/D585 [23977] 1389969764.776136: Encrypted timestamp (for 1389969764.776092): plain 301AA011180F32303134303131373134343234345AA10502030BD79C, encrypted 3E21EA6622F5E2BA7AB127B77EEB317EA9150E8426ABEC80C18D5B01B22890F2C6071619D5968590E20614F0075A894209D3CAE3119ACDC2 [23977] 1389969764.776161: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success [23977] 1389969764.776183: Produced preauth for next request: 133, 2 [23977] 1389969764.776210: Sending request (276 bytes) to DOMAIN12.NL (master) [23977] 1389969764.856587: Resolving hostname test2.domain12.nl. [23977] 1389969764.857153: Sending initial UDP request to dgram 10.0.0.254:88 [23977] 1389969765.858225: Resolving hostname test2.domain12.nl. [23977] 1389969765.859721: Initiating TCP connection to stream 10.0.0.254:88 [23977] 1389969765.860206: Sending TCP request to stream 10.0.0.254:88 [23977] 1389969767.372787: Received answer from dgram 10.0.0.254:88 [23977] 1389969767.373019: Processing preauth types: 19 [23977] 1389969767.373056: Selected etype info: etype aes256-cts, salt "/9MR-vmlC`67#=P", params "" [23977] 1389969767.373080: Produced preauth for next request: (empty) [23977] 1389969767.373116: AS key determined by preauth: aes256-cts/D585 [23977] 1389969767.373306: Decrypted AS reply; session key is: aes256-cts/A803 [23977] 1389969767.373392: FAST negotiation: available [23977] 1389969767.373470: Initializing FILE:/tmp/krb5cc_0 with default princ admin@DOMAIN12.NL [23977] 1389969767.373896: Removing admin@DOMAIN12.NL -> krbtgt/DOMAIN12.NL@DOMAIN12.NL from FILE:/tmp/krb5cc_0 [23977] 1389969767.373934: Storing admin@DOMAIN12.NL -> krbtgt/DOMAIN12.NL@DOMAIN12.NL in FILE:/tmp/krb5cc_0 [23977] 1389969767.374231: Storing config in FILE:/tmp/krb5cc_0 for krbtgt/DOMAIN12.NL@DOMAIN12.NL: fast_avail: yes [23977] 1389969767.374315: Removing admin@DOMAIN12.NL -> krb5_ccache_conf_data/fast_avail/krbtgt\/DOMAIN12.NL\@DOMAIN12.NL@X-CACHECONF: from FILE:/tmp/krb5cc_0 [23977] 1389969767.374343: Storing admin@DOMAIN12.NL -> krb5_ccache_conf_data/fast_avail/krbtgt\/DOMAIN12.NL\@DOMAIN12.NL@X-CACHECONF: in FILE:/tmp/krb5cc_0

FC19 KRB5_TRACE=/dev/stdout kinit admin [24352] 1389969986.697390: Getting initial credentials for admin@DOMAIN12.NL [24352] 1389969986.698090: Sending request (181 bytes) to DOMAIN12.NL [24352] 1389969986.703137: Resolving hostname test.domain12.nl. [24352] 1389969986.708677: Sending initial UDP request to dgram 10.0.0.1:88 [24352] 1389969986.718054: Received answer from dgram 10.0.0.1:88 [24352] 1389969986.720902: Response was from master KDC [24352] 1389969986.721012: Received error from KDC: -1765328359/Additional pre-authentication required [24352] 1389969986.721157: Processing preauth types: 136, 19, 2, 142, 133 [24352] 1389969986.721213: Selected etype info: etype aes256-cts, salt "DOMAIN12.NLadmin", params "" [24352] 1389969986.721238: Received cookie: MIT Password for admin@DOMAIN12.NL: [24352] 1389969989.881271: AS key obtained for encrypted timestamp: aes256-cts/704A [24352] 1389969989.881332: Encrypted timestamp (for 1389969989.881288): plain 301AA011180F32303134303131373134343632395AA10502030D7288, encrypted 1D1B8AB057464D924F6EA15D572C7EFE93AA43A5AD417C3E5A067E6B92FD8FD4B86E06D0D584A027ED590E801DC5F96B663EE859CD8DEA68 [24352] 1389969989.881372: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success [24352] 1389969989.881384: Produced preauth for next request: 133, 2 [24352] 1389969989.881405: Sending request (276 bytes) to DOMAIN12.NL (master) [24352] 1389969989.885886: Resolving hostname test.domain12.nl. [24352] 1389969989.886967: Sending initial UDP request to dgram 10.0.0.1:88 [24352] 1389969989.901653: Received answer from dgram 10.0.0.1:88 [24352] 1389969989.901707: Processing preauth types: 19 [24352] 1389969989.901717: Selected etype info: etype aes256-cts, salt "DOMAIN12.NLadmin", params "" [24352] 1389969989.901723: Produced preauth for next request: (empty) [24352] 1389969989.901734: AS key determined by preauth: aes256-cts/704A [24352] 1389969989.901858: Decrypted AS reply; session key is: aes256-cts/0CE0 [24352] 1389969989.901920: FAST negotiation: available [24352] 1389969989.901977: Initializing FILE:/tmp/krb5cc_0 with default princ admin@DOMAIN12.NL [24352] 1389969989.902254: Removing admin@DOMAIN12.NL -> krbtgt/DOMAIN12.NL@DOMAIN12.NL from FILE:/tmp/krb5cc_0 [24352] 1389969989.902281: Storing admin@DOMAIN12.NL -> krbtgt/DOMAIN12.NL@DOMAIN12.NL in FILE:/tmp/krb5cc_0 [24352] 1389969989.902515: Storing config in FILE:/tmp/krb5cc_0 for krbtgt/DOMAIN12.NL@DOMAIN12.NL: fast_avail: yes [24352] 1389969989.902578: Removing admin@DOMAIN12.NL -> krb5_ccache_conf_data/fast_avail/krbtgt\/DOMAIN12.NL\@DOMAIN12.NL@X-CACHECONF: from FILE:/tmp/krb5cc_0 [24352] 1389969989.902604: Storing admin@DOMAIN12.NL -> krb5_ccache_conf_data/fast_avail/krbtgt\/DOMAIN12.NL\@DOMAIN12.NL@X-CACHECONF: in FILE:/tmp/krb5cc_0

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-17 21:22:26

BTW you even do not need a client.

Just after the freeipa install issue the kinit command for the admin user and notice the difference.

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-17 21:57:15

A simple test to see the difference would be to get a ticket for the admin user and then do in a loop the renew request

1- kinit -r 1000 admin 2- while true ; do kinit -R ; done

When counting the reuests for a time i can see that with FC20 i can do about 10 renewals while i can do more then 600 renewals for FC19 server.

William

389-ds-bot commented 4 years ago

Comment from lkrispen (@elkris) at 2014-01-20 20:08:27

Petr has set up two pairs of IPA client/servers with f19 and f20. But I couldn't see any performance difference. I did run a loop of 1000 kinit -R for several times, on f19 the total time for 1000 renewals was 14.7 secs, on f20 it was 15.3 - so this seems not to be significant.

Do you have some special congig optipns for your DS ? Could you upload the dse.ldif ?

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-01-20 20:19:59

Nothing special.

Just installed fc19 and 20 installed freeipa then run the server install script.

After that i just run kinit admin from cli and on fc20 it gives me a delay for about 4 secs.

Will run a test again and then upload my dse.ldif

389-ds-bot commented 4 years ago

Comment from lkrispen (@elkris) at 2014-01-20 20:24:07

Petr, maybe we have not yet the same setup as william, I did run a kinit with krb trace and got ... [26332] 1390227350.650040: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success [26332] 1390227350.650045: Produced preauth for next request: 133, 2 [26332] 1390227350.650080: Sending request (257 bytes) to IPA.EXAMPLE [26332] 1390227350.650284: Sending initial UDP request to dgram 10.34.47.239:88 [26332] 1390227350.725790: Received answer from dgram 10.34.47.239:88 [26332] 1390227350.725880: Response was from master KDC [26332] 1390227350.725927: Processing preauth types: 19 [26332] 1390227350.725937: Selected etype info: etype aes256-cts, salt "|QO]<e-bTUrZgDB#", params "" [26332] 1390227350.725944: Produced preauth for next request: (empty) [26332] 1390227350.725954: AS key determined by preauth: aes256-cts/0C41 [26332] 1390227350.726033: Decrypted AS reply; session key is: aes256-cts/FB02 [26332] 1390227350.726053: FAST negotiation: available .... the difference is that in the trace from william we have: Sending request (276 bytes) to DOMAIN12.NL (master) [23977] 1389969764.856587: Resolving hostname test2.domain12.nl

whih is not in the trace from our lab, an ddidn't see the Response was from master KDC

in William's trace

389-ds-bot commented 4 years ago

Comment from simo (@simo5) at 2014-01-20 20:52:10

Ok William's kinit shows the KDC fails to respond within the 1s timeout and kinit retries multiple times. This means the KDC is being slow, might be due to LDAP being slow or something else. IS the server memory starved for example ? Can you post the output of top for the server while doing a slow kinit ?

389-ds-bot commented 4 years ago

Comment from lkrispen (@elkris) at 2014-01-28 15:20:01

back to work, unfortunately id did not get resolved by itself :-( since we cannot reproduce in our lab, we maybe need to start an other round of data collecting in teh customer environment.

To start with I would liek to get both the dse.ldif from f19 and f20 to comapre with our installation. Next could you post the full access and error log fro server start until the slow and the normal kinit was processed.

Simo asked for top of teh server(s) when processing the slow kinit. If possible could we get a sequence of pstacks of the DS process, wondering if we can see if any thread is "hanging"

389-ds-bot commented 4 years ago

Comment from nkinder (@nkinder) at 2014-02-24 21:02:34

Is there any update on this ticket? I didn't see any of the information provided that was requested in comment16. We need this information to continue troubleshooting, as we haven't been able to reproduce this issue.

389-ds-bot commented 4 years ago

Comment from cobradevil at 2014-03-13 18:02:26

Hello all,

sorry for the delay but i was occupied with other work.

I have retested in my old lab (which had issues) and the problem remained.

After reinstalling multiple times on my laptop the issue looks gone. There have been a lot of updates so i cannot tell which one did the trick.

After upgrading the old lab the problem also went away on that system.

So this report can be closed.

Thanks for the support.

William

389-ds-bot commented 4 years ago

Comment from pspacek at 2017-02-11 22:57:08

Metadata Update from @pspacek: