[Freeipa-users] Slow logins on one ipa client- due to SSS_PAM_ACCT_MGMT

Kilborn, Jim jim.kilborn at swri.org
Thu Mar 16 20:24:42 UTC 2017 

Greetings,

My first post to the forum.

We are running centos7 with freeipa. Syncing from AD, with one linux replica.
The ipa clients are getting installed by puppet. All the clients are performing fine, except one. I am getting slow ssh logins to one host, as well as slow 'id' and 'who', etc.

I turned up the sss-debuglevel to 6, and compared the slow client to another, and I am seeing a section in the logs that is unique to the slow system, basically its doing a SSS_PAM_ACCT_MGMT, and I don't have any clue why. Same user logging in to both clients, one client does the SSS_PAM_ACCT_MGMT, followed by the SSS_PAM_OPEN_SESSION. While the other client only does SSS_PAM_OPEN_SESSION, and is much faster. (1 second vs 2-8 seconds)
It seems the SSS_PAM_ACCT_MGMT is the slow culprit, and I don't know why its running.

Any idea what would cause this or where I should look?

Below are the log for a good fast client, followed by the log from the slow client.

Thanks!!

Good Client
[dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=nobody at ipa.mydomain.org]
[sysdb_get_real_name] (0x0040): Cannot find user [nobody at ipa.mydomain.org] in cache
[ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request
[dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_pam_handler] (0x0100): Got request with the following data
[pam_print_data] (0x0100): command: SSS_PAM_OPEN_SESSION
[pam_print_data] (0x0100): domain: ipa.mydomain.org
[pam_print_data] (0x0100): user: myusername at ipa.mydomain.org
[pam_print_data] (0x0100): service: sshd
[pam_print_data] (0x0100): tty: ssh
[pam_print_data] (0x0100): ruser:
[pam_print_data] (0x0100): rhost: myhost.mydomain.org
[pam_print_data] (0x0100): authtok type: 0
[pam_print_data] (0x0100): newauthtok type: 0
[pam_print_data] (0x0100): priv: 1
[pam_print_data] (0x0100): cli_pid: 26697
[pam_print_data] (0x0100): logon name: not set


Bad Client
[dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=nobody at ipa.mydomain.org]
[sysdb_get_real_name] (0x0040): Cannot find user [nobody at ipa.mydomain.org] in cache
[ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request
[dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_pam_handler] (0x0100): Got request with the following data
[pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT
[pam_print_data] (0x0100): domain: ipa.mydomain.org
[pam_print_data] (0x0100): user: myusername at ipa.mydomain.org
[pam_print_data] (0x0100): service: sshd
[pam_print_data] (0x0100): tty: ssh
[pam_print_data] (0x0100): ruser:
[pam_print_data] (0x0100): rhost: myhost at mydomain.org
[pam_print_data] (0x0100): authtok type: 0
[pam_print_data] (0x0100): newauthtok type: 0
[pam_print_data] (0x0100): priv: 1
[pam_print_data] (0x0100): cli_pid: 183633
[pam_print_data] (0x0100): logon name: not set
[ipa_hostgroup_info_done] (0x0200): Dereferenced host group: darkjedi
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[sysdb_delete_entry] (0x0080): sysdb_delete_ts_entry failed: 0
[hbac_get_category] (0x0200): Category is set to 'all'.
[get_ipa_groupname] (0x0020): Expected cn in RDN, got uid
[hbac_user_attrs_to_rule] (0x0020): [uid=slurm,cn=users,cn=accounts,dc=ipa,dc=mydomain,dc=org] does not map to either a user or group. Skipping
[hbac_get_category] (0x0200): Category is set to 'all'.
[hbac_get_category] (0x0200): Category is set to 'all'.
[get_ipa_groupname] (0x0020): Expected groups second component, got privileges
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got privileges
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected groups second component, got permissions
[get_ipa_groupname] (0x0020): Expected cn in RDN, got ipaUniqueID
[get_ipa_groupname] (0x0020): Expected cn in RDN, got ipaUniqueID
[hbac_evaluate] (0x0100): [< hbac_evaluate()
[hbac_evaluate] (0x0100): The rule [darkjedi-access] did not match.
[hbac_evaluate] (0x0100): ALLOWED by rule [Infrastructure].
[hbac_evaluate] (0x0100): hbac_evaluate() >]
[ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [Infrastructure]
[dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_pam_handler] (0x0100): Got request with the following data
[pam_print_data] (0x0100): command: SSS_PAM_OPEN_SESSION
[pam_print_data] (0x0100): domain: ipa.mydomain.org
[pam_print_data] (0x0100): user: myusername at ipa.mydomain.org
[pam_print_data] (0x0100): service: sshd
[pam_print_data] (0x0100): tty: ssh
[pam_print_data] (0x0100): ruser:
[pam_print_data] (0x0100): rhost: myhost at mydomain.org
[pam_print_data] (0x0100): authtok type: 0
[pam_print_data] (0x0100): newauthtok type: 0
[pam_print_data] (0x0100): priv: 1
[pam_print_data] (0x0100): cli_pid: 183633
[pam_print_data] (0x0100): logon name: not set
[dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=myusername at ipa.mydomain.org]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=users,cn=ipa.mydomain.org,cn=sysdb
[dp_get_account_info_handler] (0x0200): Got request for [0x2][BE_REQ_GROUP][1][idnumber=1051800710]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=groups,cn=ipa.mydomain.org,cn=sysdb
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait: No such object (32)]
[sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=myusername at ipa.mydomain.org,cn=groups,cn=ipa.mydomain.org,cn=sysdb




[cid:image002.png at 01D29E69.6E7C99E0]<http://www.swri.org/>

Jim Kilborn,  Principal Technical Specialist
Information Technology, Division 18
Southwest Research Institute
Office (210) 522-2739     jim.kilborn at swri.org


[cid:image004.png at 01D29D66.A9B19BE0]<https://www.linkedin.com/company/southwest-research-institute> [cid:image005.png at 01D29D66.A9B19BE0] <https://www.facebook.com/southwestresearch>  [cid:image006.png at 01D29D66.A9B19BE0] <https://www.youtube.com/user/SwRItv>  [cid:image007.png at 01D29D66.A9B19BE0] <https://twitter.com/swri>

Advanced science. Applied technology.




-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170316/92c6511b/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image004.png
Type: image/png
Size: 16036 bytes
Desc: image004.png
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170316/92c6511b/attachment.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image005.png
Type: image/png
Size: 15917 bytes
Desc: image005.png
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170316/92c6511b/attachment-0001.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image006.png
Type: image/png
Size: 16148 bytes
Desc: image006.png
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170316/92c6511b/attachment-0002.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image007.png
Type: image/png
Size: 16048 bytes
Desc: image007.png
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170316/92c6511b/attachment-0003.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image002.png
Type: image/png
Size: 7084 bytes
Desc: image002.png
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170316/92c6511b/attachment-0004.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image003.png
Type: image/png
Size: 176 bytes
Desc: image003.png
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170316/92c6511b/attachment-0005.png>

More information about the Freeipa-users mailing list