Attachment 671512 Details for Bug 890062 – Requested SSSD logs

Requested SSSD logs

sssd.logs (text/plain), 55.70 KB, created by Gordon Messmer on 2013-01-02 15:58:34 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Gordon Messmer

Created: 2013-01-02 15:58:34 UTC

Size: 55.70 KB

patch

obsolete

>
>
>
>
>==> /var/log/sssd/sssd_default.log <==
>(Wed Jan  2 07:50:39 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 7FD554FF9520
>(Wed Jan  2 07:50:39 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Wed Jan  2 07:50:39 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>(Wed Jan  2 07:50:41 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 7FD555007B90
>(Wed Jan  2 07:50:41 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Wed Jan  2 07:50:41 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [getDomains]
>(Wed Jan  2 07:50:41 2013) [sssd[be[default]]] [be_get_subdomains] (0x2000): Undefined backend target.
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 7FD55500D850
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [be_get_account_info] (0x0100): Got request for [3][1][name=gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550144e0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd555014600
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd555014600 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550144e0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550138a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd555015650
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd555019170
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd555019220
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd555015650 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550138a0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550192d0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd555019630
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd555019220 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd555019170 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd555019630 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550192d0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): beginning to connect
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'directory.private.dragonsdawn.net' is 'name not resolved'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 389 for server 'directory.private.dragonsdawn.net' is 'neutral'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'directory.private.dragonsdawn.net' is 'name not resolved'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_is_address] (0x4000): [directory.private.dragonsdawn.net] does not look like an IP address
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'directory.private.dragonsdawn.net' in files
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'directory.private.dragonsdawn.net' as 'resolving name'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_step] (0x2000): Querying files
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'directory.private.dragonsdawn.net' in files
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_step] (0x2000): Querying DNS
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'directory.private.dragonsdawn.net' in DNS
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 5 seconds
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [request_watch_destructor] (0x0400): Deleting request watch
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'directory.private.dragonsdawn.net' as 'name resolved'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [be_resolve_server_process] (0x0200): Found address for server directory.private.dragonsdawn.net: [192.168.89.1] TTL 3600
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldap://directory.private.dragonsdawn.net/'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x4000): Using file descriptor [24] for LDAP connection.
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://directory.private.dragonsdawn.net:389/??base] with fd [24].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd55501a0f0], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [vendorName]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [vendorVersion]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [dataversion]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [netscapemdsuffix]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd55501a0f0], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_rootdse_done] (0x2000): Got rootdse
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [get_naming_context] (0x0200): Using value from [namingContexts] as naming context.
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_set_search_base] (0x0100): Setting option [ldap_sudo_search_base] to [dc=private,dc=dragonsdawn,dc=net].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [common_parse_search_base] (0x0100): Search base added: [SUDO][dc=private,dc=dragonsdawn,dc=net][SUBTREE][]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is supported by this server!
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_server_opts_from_rootdse] (0x0200): Will use modification timestamp as usn!
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1357142745
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_cli_auth_step] (0x1000): No authentication requested or SASL auth forced off
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'directory.private.dragonsdawn.net' as 'working'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'directory.private.dragonsdawn.net' as 'working'
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=private,dc=dragonsdawn,dc=net]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=gordon)(objectclass=posixAccount))][dc=private,dc=dragonsdawn,dc=net].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 2
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [be_run_online_cb] (0x0080): Going online. Running callbacks.
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd555013910], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd555013910], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=gordon,ou=People,dc=private,dc=dragonsdawn,dc=net].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [uid]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [uidNumber]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [homeDirectory]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [loginShell]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [shadowLastChange]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd555013910], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Storing the user
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_save_user] (0x4000): Save user
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_save_user] (0x2000): Adding originalDN [uid=gordon,ou=People,dc=private,dc=dragonsdawn,dc=net] to attributes of [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original memberOf is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20120103020316Z] to attributes of [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original USN value is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): User principal is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowLastChange [15210] to attributes of [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [gordon].
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for user gordon
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd55502c530
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c650
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c650 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd55502c530 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd55502bf60
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c410 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd55502bf60 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502f8a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502f8a0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd55502c410 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPrincipalName] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd5550389b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd5550389b0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd55502c410 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowMin] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c410 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowMax] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502f8a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502f8a0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowWarning] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd5550389b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd5550389b0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowInactive] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c410 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowExpire] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502f8a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502f8a0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowFlag] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd5550389b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd5550389b0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbLastPwdChange] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c410 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbPasswordExpiration] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502f8a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502f8a0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [pwdAttribute] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd5550389b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd5550389b0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedService] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c410 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502f8a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502f8a0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adUserAccountControl] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd5550389b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd5550389b0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [nsAccountLock] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c410 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedHost] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502f8a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502f8a0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginDisabled] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd5550389b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd5550389b0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginExpirationTime] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502c410
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502c410 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginAllowedTimeMap] from [gordon]
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd5550355b0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502f8a0
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502f8a0 "ltdb_timeout"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd5550355b0 "ltdb_callback"
>
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Commit change
>(Wed Jan  2 07:50:45 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd55502ca00
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd55502cb20
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd55502cb20 "ltdb_timeout"
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd55502ca00 "ltdb_callback"
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Process user's groups
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_initgr_rfc2307_next_base] (0x0400): Searching for groups with base [dc=private,dc=dragonsdawn,dc=net]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(memberuid=gordon)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=private,dc=dragonsdawn,dc=net].
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 3
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd555019600], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [delayed_online_authentication_callback] (0x0200): Backend is online, starting delayed online authentication.
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd555019600], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=ispd,ou=Groups,dc=private,dc=dragonsdawn,dc=net].
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd555019600], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=smbadmins,ou=Groups,dc=private,dc=dragonsdawn,dc=net].
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[0x7fd555019600], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x1000): Total count [0]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd55502c550
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd555022670
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd555022670 "ltdb_timeout"
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd55502c550 "ltdb_callback"
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_initgr_common_store] (0x2000): Updating memberships for gordon
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_get_initgr_done] (0x4000): Initgroups done
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_id_op_done] (0x4000): releasing operation connection
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sbus_add_timeout] (0x2000): 0x7fd555017e90
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x7fd555019790], connected[1], ops[(nil)], ldap[0x7fd554fe0480]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sbus_remove_timeout] (0x2000): 0x7fd555017e90
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 7FD555007B90
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 7FD55500D850
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_pam_handler] (0x0100): Got request with the following data
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): domain: default
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): user: gordon
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): service: sshd
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): tty: ssh
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): ruser: 
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): rhost: ascension.private.dragonsdawn.net
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok type: 1
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok size: 9
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok type: 0
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok size: 0
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): priv: 1
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [pam_print_data] (0x0100): cli_pid: 14282
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [krb5_pam_handler] (0x1000): Wait queue of user [gordon] is empty, running request immediately.
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fd555016330
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fd555017840
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x7fd555017840 "ltdb_timeout"
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x7fd555016330 "ltdb_callback"
>
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [krb5_get_simple_upn] (0x4000): Using simple UPN [gordon@PRIVATE.DRAGONSDAWN.NET].
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [cc_residual_is_used] (0x1000): User [1002] is still active, reusing ccache [/run/user/1002/krb5cc].
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [cc_dir_check_existing] (0x0400): ccache DIR::/run/user/1002/krb5cc/tktuNNNlC is missing or empty
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [krb5_auth_send] (0x4000): Ccache_file is [DIR::/run/user/1002/krb5cc/tktuNNNlC] and is  active and TGT is not valid.
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'KERBEROS'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'directory.private.dragonsdawn.net' is 'working'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 0 for server 'directory.private.dragonsdawn.net' is 'neutral'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'directory.private.dragonsdawn.net' is 'working'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_resolve_server_process] (0x0200): Found address for server directory.private.dragonsdawn.net: [192.168.89.1] TTL 3600
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'KPASSWD'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'directory.private.dragonsdawn.net' is 'working'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 0 for server 'directory.private.dragonsdawn.net' is 'neutral'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'directory.private.dragonsdawn.net' is 'working'
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_resolve_server_process] (0x0200): Found address for server directory.private.dragonsdawn.net: [192.168.89.1] TTL 3600
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [krb5_find_ccache_step] (0x0080): Saved ccache DIR::/run/user/1002/krb5cc/tktuNNNlC if of different type than ccache in configuration file, reusing the old ccache
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [14284]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [child_handler_setup] (0x2000): Signal handler set up for pid [14284]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [write_pipe_handler] (0x0400): All data has been sent!
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [become_user] (0x0200): Trying to become user [1002][1002].
>
>==> /var/log/sssd/krb5_child.log <==
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [main] (0x0400): krb5_child started.
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [unpack_buffer] (0x1000): total buffer size: [135]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [unpack_buffer] (0x0100): cmd [241] uid [1002] gid [1002] validate [false] offline [false] UPN [gordon@PRIVATE.DRAGONSDAWN.NET]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [unpack_buffer] (0x0100): ccname: [DIR::/run/user/1002/krb5cc/tktuNNNlC] keytab: [/etc/krb5.keytab]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [krb5_child_setup] (0x0400): Will perform online auth
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [krb5_child_setup] (0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [krb5_child_setup] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment.
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [krb5_set_canonicalize] (0x0100): SSSD_KRB5_CANONICALIZE is set to [false]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [krb5_child_setup] (0x0100): Not using FAST.
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [PRIVATE.DRAGONSDAWN.NET]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.46642: Getting initial credentials for gordon@PRIVATE.DRAGONSDAWN.NET
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.47116: Sending request (203 bytes) to PRIVATE.DRAGONSDAWN.NET
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.47898: Sending initial UDP request to dgram 192.168.89.1:88
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.50888: Received answer from dgram 192.168.89.1:88
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.51169: Response was from master KDC
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.51530: Processing preauth types: 19
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.51789: Selected etype info: etype aes256-cts, salt "(null)", params ""
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.51876: Produced preauth for next request: (empty)
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.52236: Salt derived from principal: PRIVATE.DRAGONSDAWN.NETgordon
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.52534: Getting AS key, salt "PRIVATE.DRAGONSDAWN.NETgordon", params ""
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.71616: AS key obtained from gak_fct: aes256-cts/4076
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.71707: Decrypted AS reply; session key is: aes256-cts/7B9D
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sss_child_krb5_trace_cb] (0x4000): [14284] 1357141846.71736: FAST negotiation: available
>
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [get_and_save_tgt] (0x0100): TGT validation is disabled.
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [create_ccache_in_dir] (0x0200): Creating ccache at [DIR::/run/user/1002/krb5cc/tktuNNNlC]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [become_user] (0x0200): Trying to become user [1002][1002].
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [create_ccache_in_dir] (0x0040): 495: [-1765328189][Credential cache directory /run/user/1002/krb5cc does not exist]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [get_and_save_tgt] (0x0020): 1008: [-1765328189][Credential cache directory /run/user/1002/krb5cc does not exist]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [kerr_handle_error] (0x0020): 1030: [-1765328189][Credential cache directory /run/user/1002/krb5cc does not exist]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [prepare_response_message] (0x0400): Building response for result [-1765328189]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [pack_response_packet] (0x2000): response packet size: [76]
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [sendresponse] (0x4000): Response sent.
>(Wed Jan  2 07:50:46 2013) [[sssd[krb5_child[14284]]]] [main] (0x0400): krb5_child completed successfully
>
>==> /var/log/sssd/sssd_default.log <==
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [child_sig_handler] (0x1000): Waiting for child [14284].
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [child_sig_handler] (0x0100): child [14284] finished successfully.
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [sss_child_handler] (0x2000): waitpid failed [10]: No child processes
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [read_pipe_handler] (0x0400): EOF received, client finished
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [parse_krb5_child_response] (0x1000): child response [4][1][64].
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [check_wait_queue] (0x1000): Wait queue for user [gordon] is empty.
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 4, <NULL>) [Success]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sending result [4][default]
>(Wed Jan  2 07:50:46 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sent result [4][default]
>(Wed Jan  2 07:50:49 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 7FD554FF9520
>(Wed Jan  2 07:50:49 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>(Wed Jan  2 07:50:49 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>

Actions: View

Attachments on bug 890062: 671511 | 671512