Attachment 707123 Details for Bug 905619 – sssd_default.log

sssd_default.log

sssd_default.log (text/plain), 91.30 KB, created by Orion Poplawski on 2013-03-08 16:47:20 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Orion Poplawski

Created: 2013-03-08 16:47:20 UTC

Size: 91.30 KB

patch

obsolete

>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: CA1460
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [be_get_account_info] (0x0100): Got request for [3][1][name=schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=nwra,dc=com]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=schuck)(objectclass=posixAccount))][dc=nwra,dc=com].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 18
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xfd4a40], ldap[0xd64d70]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=schuck,ou=People,dc=nwra,dc=com].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xfd4a40], ldap[0xd64d70]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Storing the user
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_save_user] (0x4000): Save user
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [uid=schuck,ou=People,dc=nwra,dc=com] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original memberOf is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20130204172928Z] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original USN value is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): User principal is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowLastChange [15741] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMin [5] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMax [365] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowWarning [14] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowInactive [21] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowFlag [-1] to attributes of [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for user schuck
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd42ac0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd42be0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd42be0 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd42ac0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xe6d700
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xe6d820
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xe6d820 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xe6d700 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPrincipalName] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowExpire] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbLastPwdChange] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbPasswordExpiration] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [pwdAttribute] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedService] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adUserAccountControl] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [nsAccountLock] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedHost] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginDisabled] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd28b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd28b0 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginExpirationTime] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd5a510
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xdb1320
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xdb1320 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd5a510 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginAllowedTimeMap] from [schuck]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfecf00
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xdb1320
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xdb1320 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfecf00 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Commit change
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd47d50
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfd34b0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfd34b0 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd47d50 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Process user's groups
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_initgr_rfc2307_next_base] (0x0400): Searching for groups with base [dc=nwra,dc=com]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(memberuid=schuck)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=nwra,dc=com].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberuid]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 19
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xd40410], ldap[0xd64d70]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xd40410], ldap[0xd64d70]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x1000): Total count [0]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd2840
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfd28f0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfd28f0 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd2840 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_initgr_common_store] (0x2000): Updating memberships for schuck
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_get_initgr_done] (0x4000): Initgroups done
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[(nil)], ldap[0xd64d70]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: CA1460
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [be_pam_handler] (0x0100): Got request with the following data
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): command: PAM_CHAUTHTOK_PRELIM
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): domain: default
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): user: schuck
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): service: passwd
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): tty: pts/2
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): ruser: 
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): rhost: 
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok type: 1
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok size: 10
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok type: 0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok size: 0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): priv: 0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [pam_print_data] (0x0100): cli_pid: 6475
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_pam_chpass_handler] (0x0040): starting password change request for user [schuck].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap2.cora.nwra.com' is 'working'
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 389 for server 'ldap2.cora.nwra.com' is 'working'
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap2.cora.nwra.com' is 'working'
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [be_resolve_server_done] (0x1000): Saving the first resolved server
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [be_resolve_server_done] (0x0200): Found address for server ldap2.cora.nwra.com: [10.10.11.4] TTL 21600
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldap://ldap2.cora.nwra.com/'
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x4000): Using file descriptor [33] for LDAP connection.
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://ldap2.cora.nwra.com:389/??base] with fd [33].
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_sys_connect_done] (0x0100): Executing START TLS
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xf86d10], connected[1], ops[0x102f4b0], ldap[0xd59a00]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_EXTENDED]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_connect_done] (0x0080): START TLS result: Success(0), Start TLS request accepted.Server willing to negotiate SSL.
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'ldap2.cora.nwra.com' as 'working'
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'ldap2.cora.nwra.com' as 'working'
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfbdc20
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd642e0
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd642e0 "ltdb_timeout"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfbdc20 "ltdb_callback"
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [find_password_expiration_attributes] (0x4000): No password policy requested.
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [simple_bind_send] (0x0100): Executing simple bind as: uid=schuck,ou=People,dc=nwra,dc=com
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [simple_bind_send] (0x2000): ldap simple bind sent, msgid = 2
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xf86d10], connected[1], ops[0xdb62d0], ldap[0xd59a00]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xf86d10], connected[1], ops[0xdb62d0], ldap[0xd59a00]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_BIND]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [simple_bind_done] (0x0200): Server returned no controls.
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [simple_bind_done] (0x0080): Bind result: Success(0), no errmsg set
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_auth4chpass_done] (0x4000): Initial authentication for change password operation successful.
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sending result [0][default]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sent result [0][default]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [sdap_handle_release] (0x2000): Trace: sh[0xf86d10], connected[1], ops[(nil)], ldap[0xd59a00], destructor_lock[0], release_memory[0]
>(Fri Mar  8 09:40:11 2013) [sssd[be[default]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>(Fri Mar  8 09:40:15 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: C95B30
>(Fri Mar  8 09:40:15 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:15 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: CA1460
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [be_get_account_info] (0x0100): Got request for [3][1][name=schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=nwra,dc=com]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=schuck)(objectclass=posixAccount))][dc=nwra,dc=com].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 20
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xca7150], ldap[0xd64d70]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=schuck,ou=People,dc=nwra,dc=com].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xca7150], ldap[0xd64d70]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Storing the user
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_save_user] (0x4000): Save user
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [uid=schuck,ou=People,dc=nwra,dc=com] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original memberOf is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20130204172928Z] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original USN value is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): User principal is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowLastChange [15741] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMin [5] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMax [365] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowWarning [14] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowInactive [21] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowFlag [-1] to attributes of [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for user schuck
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xca8870
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfedb30
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfedb30 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xca8870 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xe6d850
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xe6d970
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xe6d970 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xe6d850 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPrincipalName] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfe4fd0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfe4fd0 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfe4c70 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowExpire] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xe6d7b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xe6d7b0 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfe4c70 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbLastPwdChange] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfecf00
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfe4c70 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfecf00 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbPasswordExpiration] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xe6d7b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xe6d7b0 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [pwdAttribute] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xe6d7b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xe6d7b0 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfe4c70 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedService] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfecf00
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfe4c70 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfecf00 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xe6d7b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xe6d7b0 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adUserAccountControl] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xe6d7b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xe6d7b0 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfe4c70 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [nsAccountLock] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfecf00
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfe4c70 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfecf00 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedHost] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xe6d7b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xe6d7b0 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginDisabled] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xe6d970
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfe4c70 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xe6d970 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginExpirationTime] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xe6d7b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfecf00
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfecf00 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xe6d7b0 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginAllowedTimeMap] from [schuck]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xcb0280
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfe4c70
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfe4c70 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xcb0280 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Commit change
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd36b0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfd37d0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfd37d0 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd36b0 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Process user's groups
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_initgr_rfc2307_next_base] (0x0400): Searching for groups with base [dc=nwra,dc=com]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(memberuid=schuck)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=nwra,dc=com].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberuid]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 21
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xfedba0], ldap[0xd64d70]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xfedba0], ldap[0xd64d70]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x1000): Total count [0]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd2720
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfd27d0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfd27d0 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd2720 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_initgr_common_store] (0x2000): Updating memberships for schuck
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_get_initgr_done] (0x4000): Initgroups done
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[(nil)], ldap[0xd64d70]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: CA1460
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [be_pam_handler] (0x0100): Got request with the following data
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): command: PAM_CHAUTHTOK
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): domain: default
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): user: schuck
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): service: passwd
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): tty: pts/2
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): ruser: 
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): rhost: 
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok type: 1
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok size: 10
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok type: 1
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok size: 10
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): priv: 0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [pam_print_data] (0x0100): cli_pid: 6475
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_pam_chpass_handler] (0x0040): starting password change request for user [schuck].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap2.cora.nwra.com' is 'working'
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 389 for server 'ldap2.cora.nwra.com' is 'working'
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap2.cora.nwra.com' is 'working'
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [be_resolve_server_done] (0x1000): Saving the first resolved server
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [be_resolve_server_done] (0x0200): Found address for server ldap2.cora.nwra.com: [10.10.11.4] TTL 21600
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldap://ldap2.cora.nwra.com/'
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x4000): Using file descriptor [33] for LDAP connection.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://ldap2.cora.nwra.com:389/??base] with fd [33].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_sys_connect_done] (0x0100): Executing START TLS
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xfd4320], connected[1], ops[0xfd44f0], ldap[0xfedb50]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_EXTENDED]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_connect_done] (0x0080): START TLS result: Success(0), Start TLS request accepted.Server willing to negotiate SSL.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'ldap2.cora.nwra.com' as 'working'
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'ldap2.cora.nwra.com' as 'working'
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd59af0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd59ba0
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd59ba0 "ltdb_timeout"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd59af0 "ltdb_callback"
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [find_password_expiration_attributes] (0x4000): No password policy requested.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [simple_bind_send] (0x0100): Executing simple bind as: uid=schuck,ou=People,dc=nwra,dc=com
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [simple_bind_send] (0x2000): ldap simple bind sent, msgid = 2
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xfd4320], connected[1], ops[0xfd4a40], ldap[0xfedb50]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xfd4320], connected[1], ops[0xfd4a40], ldap[0xfedb50]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_BIND]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [simple_bind_done] (0x0200): Server returned no controls.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [simple_bind_done] (0x0080): Bind result: Success(0), no errmsg set
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_auth4chpass_done] (0x1000): user [uid=schuck,ou=People,dc=nwra,dc=com] successfully authenticated.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_control_create] (0x0080): Server does not support the requested control [1.3.6.1.4.1.42.2.27.8.5.1].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_exop_modify_passwd_send] (0x0100): Executing extended operation
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_exop_modify_passwd_send] (0x2000): ldap_extended_operation sent, msgid = 3
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xfd4320], connected[1], ops[0xfd44f0], ldap[0xfedb50]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xfd4320], connected[1], ops[0xfd44f0], ldap[0xfedb50]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ldap.cora.nwra.com] with fd [34].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [synchronous_tls_setup] (0x0100): Executing START TLS
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [synchronous_tls_setup] (0x0080): START TLS result: Operations error(1), SSL connection already established.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [synchronous_tls_setup] (0x4000): SSL/TLS handler already in place.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_rebind_proc] (0x1000): Successfully bind to [ldaps://ldap.cora.nwra.com/].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xfd4320], connected[1], ops[0xfd44f0], ldap[0xfedb50]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_ldap_connect_callback_del] (0x4000): Closing LDAP connection with fd [34].
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_EXTENDED]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_exop_modify_passwd_done] (0x0200): Server returned no controls.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_exop_modify_passwd_done] (0x0080): ldap_extended_operation result: Insufficient access(50), Anonymous Binds are not allowed.
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Backend returned: (3, 20, <NULL>) [Internal Error (Authentication token manipulation error)]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sending result [20][default]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sent result [20][default]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [sdap_handle_release] (0x2000): Trace: sh[0xfd4320], connected[1], ops[(nil)], ldap[0xfedb50], destructor_lock[0], release_memory[0]
>(Fri Mar  8 09:40:20 2013) [sssd[be[default]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>(Fri Mar  8 09:40:25 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: C95B30
>(Fri Mar  8 09:40:25 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:25 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: CA1460
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [be_get_account_info] (0x0100): Got request for [3][1][name=schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=nwra,dc=com]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=schuck)(objectclass=posixAccount))][dc=nwra,dc=com].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 22
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xdb61b0], ldap[0xd64d70]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=schuck,ou=People,dc=nwra,dc=com].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xdb61b0], ldap[0xd64d70]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Storing the user
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_save_user] (0x4000): Save user
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [uid=schuck,ou=People,dc=nwra,dc=com] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original memberOf is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20130204172928Z] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original USN value is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): User principal is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowLastChange [15741] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMin [5] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMax [365] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowWarning [14] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowInactive [21] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowFlag [-1] to attributes of [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [schuck].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for user schuck
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd47c20
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd47d40
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd47d40 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd47c20 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd614f0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd61610 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd614f0 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPrincipalName] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowExpire] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbLastPwdChange] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbPasswordExpiration] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [pwdAttribute] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedService] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adUserAccountControl] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [nsAccountLock] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedHost] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xf9b390
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xf9b390 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginDisabled] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd879a0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd61610 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd879a0 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginExpirationTime] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd89310
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd89310 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd61610 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginAllowedTimeMap] from [schuck]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xd89310
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd61610
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd61610 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xd89310 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Commit change
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfd34b0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xfd35d0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xfd35d0 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfd34b0 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Process user's groups
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_initgr_rfc2307_next_base] (0x0400): Searching for groups with base [dc=nwra,dc=com]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(memberuid=schuck)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=nwra,dc=com].
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberuid]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 23
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xd89ca0], ldap[0xd64d70]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[0xd89ca0], ldap[0xd64d70]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x1000): Total count [0]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0xfedb60
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0xd63140
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Destroying timer event 0xd63140 "ltdb_timeout"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): tevent: Ending timer event 0xfedb60 "ltdb_callback"
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_initgr_common_store] (0x2000): Updating memberships for schuck
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_get_initgr_done] (0x4000): Initgroups done
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0xc92160], connected[1], ops[(nil)], ldap[0xd64d70]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: CA1460
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler]
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [be_pam_handler] (0x0100): Got request with the following data
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): command: PAM_CLOSE_SESSION
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): domain: default
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): user: schuck
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): service: su-l
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): tty: pts/2
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): ruser: root
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): rhost: 
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok type: 0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok size: 0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok type: 0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok size: 0
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): priv: 1
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): cli_pid: 6438
>(Fri Mar  8 09:40:26 2013) [sssd[be[default]]] [be_pam_handler] (0x0100): Sending result [0][default]

Actions: View

Attachments on bug 905619: 707123