#47656 Freeipa user authentication slow using 389 1.3.2.9-1
Closed: wontfix None Opened 10 years ago by cobradevil.

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


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 ?

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.

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 ?

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

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

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!

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-v*mlC67#=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-v*mlC67#=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

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.

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

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 ?

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

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

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 ?

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"

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

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

Metadata Update from @pspacek:
- Issue set to the milestone: N/A

7 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/993

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Invalid)

3 years ago

Login to comment on this ticket.

Metadata