Hello sssd list. My problem is that a with sssd configured ubuntu 12.04 client cannot change a password that has to be set a new for IPA. As I've learned from the IPA list there are indications that sssd might be the problem in this case.

With logging=10 in sssd.conf I see the following logs by sssd:

When a user password expires the users are requested to change their password (in the login screen). They'll type their old password and then repeat it as part of the change process. Nevertheless - although the password matches - they are not issued to input their new password but get the error message that this action could not be performed (Password change failed. Server message..).

The sssd logs show the following. (Mon Nov 19 10:33:18 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:33:18 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:18 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8ED0A0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_get_account_info] (0x0100): Got request for [3][1][name=tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=cl,dc=atix] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=tuser)(objectclass=posixAccount))][cn=accounts,dc=cl,dc=atix]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 8 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: sh[0x997840], connected[1], ops[0x9a7480], ldap[0x9a48d0] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=tuser,cn=users,cn=accounts,dc=cl,dc=atix]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: sh[0x997840], connected[1], ops[0x9a7480], ldap[0x9a48d0] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Storing the user (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x4000): Save user (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [uid=tuser,cn=users,cn=accounts,dc=cl,dc=atix] to attributes of [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x1000): Original memberOf is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20121119092148Z] to attributes of [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x1000): Adding user principal [tuser@CL.ATIX] to attributes of [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbLastPwdChange [20121119091442Z] to attributes of [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbPasswordExpiration [20121119091442Z] to attributes of [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [tuser]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x0400): Storing info for user tuser (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 1) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 2) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9a8300 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 2) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 2) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowLastChange] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowMin] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowMax] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowWarning] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowInactive] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowExpire] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowFlag] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [pwdAttribute] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedService] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adUserAccountControl] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [nsAccountLock] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedHost] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginDisabled] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginExpirationTime] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginAllowedTimeMap] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9a8300

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9a8300 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [sshPublicKey] from [tuser] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b6e0

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b800

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b800 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b6e0 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 2) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 1) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Commit change (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d8720

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d8840

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d8840 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d8720 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Process user's groups (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_initgr_nested_send] (0x0100): User entry lacks original memberof ? (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_done] (0x4000): Initgroups done (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_id_op_done] (0x4000): releasing operation connection (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: sh[0x997840], connected[1], ops[(nil)], ldap[0x9a48d0] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8ED0A0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler] (0x0100): Got request with the following data (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): domain: gallien.atix (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): user: tuser (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): service: lightdm (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): tty: :0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): ruser: (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): rhost: (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok type: 1 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok size: 7 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok size: 0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): priv: 1 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): cli_pid: 19892 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0710

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9b6400

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9b6400 "ltdb_timeout"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0710 "ltdb_callback"

(Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [krb5_auth_send] (0x0100): No ccache file for user [tuser] found. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [krb5_auth_send] (0x4000): Ccache_file is [not set] and is not active and TGT is not valid. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [get_server_status] (0x1000): Status of server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [get_port_status] (0x1000): Port status of port 0 for server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [get_server_status] (0x1000): Status of server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_resolve_server_done] (0x0200): Found address for server axinfra02-1.cl.atix: [192.168.3.4] TTL 1200 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://axinfra02-1.cl.atix' (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [krb5_find_ccache_step] (0x4000): Recreating ccache file. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [19941] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [child_handler_setup] (0x2000): Signal handler set up for pid [19941] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [write_pipe_handler] (0x0400): All data has been sent!

==> /var/log/sssd/krb5_child.log <== (Mon Nov 19 10:33:27 2012) [[sssd[krb5_child[19941]]]] [main] (0x0400): krb5_child started. (Mon Nov 19 10:33:27 2012) [[sssd[krb5_child[19941]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment. (Mon Nov 19 10:33:27 2012) [[sssd[krb5_child[19941]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_LIFETIME] from environment. (Mon Nov 19 10:33:27 2012) [[sssd[krb5_child[19941]]]] [krb5_child_setup] (0x4000): Not using FAST. (Mon Nov 19 10:33:27 2012) [[sssd[krb5_child[19941]]]] [get_and_save_tgt] (0x0020): 660: [-1765328361][Password has expired] (Mon Nov 19 10:33:27 2012) [[sssd[krb5_child[19941]]]] [tgt_req_child] (0x0020): 919: [-1765328361][Password has expired]

==> /var/log/sssd/sssd_gallien.atix.log <== (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [read_pipe_handler] (0x0400): EOF received, client finished (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [krb5_child_done] (0x4000): child response [12][1][21]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 12, <NULL>) [Success] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sending result [12][gallien.atix] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sent result [12][gallien.atix] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8ED0A0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler] (0x0100): Got request with the following data (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): domain: gallien.atix (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): user: tuser (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): service: lightdm (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): tty: :0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): ruser: (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): rhost: (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok type: 0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok size: 0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok size: 0 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): priv: 1 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): cli_pid: 19892 (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_target_access_permit] (0x4000): be_target_access_permit called, returning PAM_SUCCESS. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sending result [0][gallien.atix] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sent result [0][gallien.atix] (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x1000): Waiting for child [19941]. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x0100): child [19941] finished successfully. (Mon Nov 19 10:33:27 2012) [sssd[be[gallien.atix]]] [sss_child_handler] (0x2000): waitpid failed [10]: No child processes (Mon Nov 19 10:33:28 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:33:28 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:28 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8ED0A0 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [be_get_account_info] (0x0100): Got request for [3][1][name=tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=cl,dc=atix] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=tuser)(objectclass=posixAccount))][cn=accounts,dc=cl,dc=atix]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: sh[0x997840], connected[1], ops[0x9a7480], ldap[0x9a48d0] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=tuser,cn=users,cn=accounts,dc=cl,dc=atix]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: sh[0x997840], connected[1], ops[0x9a7480], ldap[0x9a48d0] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Storing the user (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x4000): Save user (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [uid=tuser,cn=users,cn=accounts,dc=cl,dc=atix] to attributes of [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x1000): Original memberOf is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20121119093326Z] to attributes of [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x1000): Adding user principal [tuser@CL.ATIX] to attributes of [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbLastPwdChange [20121119091442Z] to attributes of [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbPasswordExpiration [20121119091442Z] to attributes of [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [tuser]. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_save_user] (0x0400): Storing info for user tuser (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 1) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9b6300

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d48d0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d48d0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9b6300 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 2) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0600

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0600 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 2) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 2) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xa319d0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0xa319d0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowLastChange] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowMin] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowMax] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowWarning] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowInactive] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowExpire] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowFlag] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [pwdAttribute] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedService] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adUserAccountControl] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [nsAccountLock] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedHost] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginDisabled] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginExpirationTime] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginAllowedTimeMap] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d08b0 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d0720 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sysdb_remove_attrs] (0x2000): Removing attribute [sshPublicKey] from [tuser] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d08b0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d0720

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d0720 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d08b0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 2) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 1) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Commit change (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x99b840

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x99b960

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x99b960 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x99b840 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_user] (0x4000): Process user's groups (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_initgr_nested_send] (0x0100): User entry lacks original memberof ? (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_get_initgr_done] (0x4000): Initgroups done (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_id_op_done] (0x4000): releasing operation connection (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: sh[0x997840], connected[1], ops[(nil)], ldap[0x9a48d0] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8ED0A0 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [be_pam_handler] (0x0100): Got request with the following data (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): command: PAM_CHAUTHTOK_PRELIM (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): domain: gallien.atix (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): user: tuser (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): service: lightdm (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): tty: :0 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): ruser: (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): rhost: (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok type: 1 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok size: 7 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok type: 0 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok size: 0 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): priv: 1 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): cli_pid: 19892 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9cfdf0

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d8b50

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d8b50 "ltdb_timeout"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9cfdf0 "ltdb_callback"

(Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [krb5_auth_send] (0x0100): No ccache file for user [tuser] found. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [krb5_auth_send] (0x4000): Ccache_file is [not set] and is not active and TGT is not valid. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [get_server_status] (0x1000): Status of server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [get_port_status] (0x1000): Port status of port 0 for server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [get_server_status] (0x1000): Status of server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [be_resolve_server_done] (0x0200): Found address for server axinfra02-1.cl.atix: [192.168.3.4] TTL 1200 (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [krb5_find_ccache_step] (0x4000): Recreating ccache file. (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [19942] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [child_handler_setup] (0x2000): Signal handler set up for pid [19942] (Mon Nov 19 10:33:32 2012) [sssd[be[gallien.atix]]] [write_pipe_handler] (0x0400): All data has been sent!

==> /var/log/sssd/krb5_child.log <== (Mon Nov 19 10:33:32 2012) [[sssd[krb5_child[19942]]]] [main] (0x0400): krb5_child started. (Mon Nov 19 10:33:32 2012) [[sssd[krb5_child[19942]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment. (Mon Nov 19 10:33:32 2012) [[sssd[krb5_child[19942]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_LIFETIME] from environment. (Mon Nov 19 10:33:32 2012) [[sssd[krb5_child[19942]]]] [krb5_child_setup] (0x4000): Not using FAST. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19942]]]] [changepw_child] (0x4000): Initial authentication for change password operation successfull.

==> /var/log/sssd/sssd_gallien.atix.log <== (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [read_pipe_handler] (0x0400): EOF received, client finished (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sending result [0][gallien.atix] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sent result [0][gallien.atix] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8ED0A0 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_pam_handler] (0x0100): Got request with the following data (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): command: PAM_CHAUTHTOK (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): domain: gallien.atix (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): user: tuser (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): service: lightdm (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): tty: :0 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): ruser: (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): rhost: (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok type: 1 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): authtok size: 7 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok type: 1 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): newauthtok size: 0 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): priv: 1 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [pam_print_data] (0x0100): cli_pid: 19892 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x9d8720

(Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x9d9090

(Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Destroying timer event 0x9d9090 "ltdb_timeout"

(Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [ldb] (0x4000): tevent: Ending timer event 0x9d8720 "ltdb_callback"

(Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [krb5_auth_send] (0x0100): No ccache file for user [tuser] found. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [krb5_auth_send] (0x4000): Ccache_file is [not set] and is not active and TGT is not valid. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [get_server_status] (0x1000): Status of server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [get_port_status] (0x1000): Port status of port 0 for server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [get_server_status] (0x1000): Status of server 'axinfra02-1.cl.atix' is 'working' (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_resolve_server_done] (0x0200): Found address for server axinfra02-1.cl.atix: [192.168.3.4] TTL 1200 (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [krb5_find_ccache_step] (0x4000): Recreating ccache file. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [19943] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_handler_setup] (0x2000): Signal handler set up for pid [19943] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [write_pipe_handler] (0x0400): All data has been sent! (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x1000): Waiting for child [19943]. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x0020): waitpid did not found a child with changed status. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x1000): Waiting for child [19942]. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x0100): child [19942] finished successfully.

==> /var/log/sssd/krb5_child.log <== (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [main] (0x0400): krb5_child started. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_LIFETIME] from environment. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [krb5_child_setup] (0x4000): Not using FAST. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [changepw_child] (0x0020): krb5_change_password failed [2][Server error]. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [changepw_child] (0x0020): krb5_change_password failed [2][Password not changed.].

==> /var/log/sssd/sssd_gallien.atix.log <== (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [read_pipe_handler] (0x0400): EOF received, client finished (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [krb5_child_done] (0x4000): child response [20][1][27]. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [krb5_child_done] (0x4000): child response [20][6][29]. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 20, <NULL>) [Success] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sending result [20][gallien.atix] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [be_pam_handler_callback] (0x0100): Sent result [20][gallien.atix] (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x1000): Waiting for child [19943]. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [child_sig_handler] (0x0100): child [19943] finished successfully. (Mon Nov 19 10:33:33 2012) [sssd[be[gallien.atix]]] [sss_child_handler] (0x2000): waitpid failed [10]: No child processes (Mon Nov 19 10:33:38 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:33:38 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:38 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Mon Nov 19 10:33:48 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:33:48 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:48 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Mon Nov 19 10:33:58 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:33:58 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:33:58 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Mon Nov 19 10:34:08 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:34:08 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:34:08 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Mon Nov 19 10:34:18 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:34:18 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:34:18 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping] (Mon Nov 19 10:34:28 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): dbus conn: 8C8E50 (Mon Nov 19 10:34:28 2012) [sssd[be[gallien.atix]]] [sbus_dispatch] (0x4000): Dispatching. (Mon Nov 19 10:34:28 2012) [sssd[be[gallien.atix]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]

Any ideas?

If you need more information or have a special trace let me know.

Regards Marc. Am 19.11.2012 18:12, schrieb Dmitri Pal:

On 11/19/2012 11:31 AM, Marc Grimme wrote:

...

This is what the kerberos (kadmin.log) shows on the relevant IPA server. Nov 19 17:29:54 axinfra02-1.cl.atix kadmind[18851](Error): password quality module empty rejected password for tuser@CL.ATIX: Empty passwords are not allowed Nov 19 17:29:54 axinfra02-1.cl.atix kadmind[18851](Notice): chpw request from 192.168.3.231 for tuser@CL.ATIX: Password is too short

I could only enter the old password the new one was never queried. Any idea?

Please cross post to the sssd-users. It seems that the server receives an empty password. I do not know if one can enable a trace that would show what password is actually sent. You might need to have a special build of SSSD to see what SSSD is actually sending. Anyways ask on SSSD list, you might get some good hints.

Thanks Dmitri

...

Thanks Marc.

Am 19.11.2012 16:57, schrieb Dmitri Pal:

...

On 11/19/2012 04:37 AM, Marc Grimme wrote:

...

(Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [krb5_child_setup] (0x4000): Not using FAST. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [changepw_child] (0x0020): krb5_change_password failed [2][Server error]. (Mon Nov 19 10:33:33 2012) [[sssd[krb5_child[19943]]]] [changepw_child] (0x0020): krb5_change_password failed [2][Password not changed.].

Have you looked at the server Kerberos log? Do you see an attempt there? If not there might be a problem accessing kadmin process on the server. Might be a firewall issue then. But let us start with the server side.