On 05/12/2012 11:31 AM, Qing Chang wrote:
On 04/12/2012 3:11 PM, Jakub Hrozek wrote:
> On Tue, Dec 04, 2012 at 08:50:23PM +0100, Jakub Hrozek wrote:
>> On Tue, Dec 04, 2012 at 02:38:34PM -0500, Simo Sorce wrote:
>>> On Tue, 2012-12-04 at 14:31 -0500, Qing Chang wrote:
>>>> On 04/12/2012 2:19 PM, Simo Sorce wrote:
>>>>> On Tue, 2012-12-04 at 13:11 -0500, Dmitri Pal wrote:
>>>>>>> A "service sssd restart" "fix" the
problem...
>>>>>>>
>>>>>>> I am thinking of running a cron job of above every 10 minutes
to
>>>>>> work
>>>>>>> around
>>>>>>> the problem while it is being troubleshoot. Is it a bad
idea?
>>>>> Well every 10 min. seem a bit too much, but I guess it depends how
long
>>>>> your user is willing to wait when it breaks :-/
>>>>>> This thread reminded me of the following thread
>>>>>>
https://lists.fedorahosted.org/pipermail/sssd-devel/2011-September/007058...
>>>>> Yes Dmitri, this is very similar.
>>>>>
>>>>> Qing,
>>>>> do you happen to have the provider logs as well ?
>>>>>
>>>>> It seemed confined to the nss responder, but it may be an actual
>>>>> provider issue after all, seem like the provider is deleting the
user
>>>>> from the cache from time to time, and it shouldn't.
>>>>>
>> The provider has no means of deleting a user from cache, in the current
>> model, the responders are pure "readers" and only the back ends are
>> "writers".
> I'm sorry, I swapped the terms responder and provider myself..
>
> Simo was completely right, because the provider is the writer (at least
> I got that part right) and for some reason the provider removed the
> cached entry, then the nss responder could not read it from
> cache while offline and return it.
>
> Bottom line is, the domain logs Simo asked for would be welcome.
>
> Sorry for the confusion.
> _______________________________________________
> sssd-devel mailing list
> sssd-devel(a)lists.fedorahosted.org
>
https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
This is getting real frustrating, sssd seems to play hide and seek with me, it
would forget and remeber at will:
=====
First failed "getent passwd shassan" triggers:
(Wed Dec 5 10:45:05 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to
get
information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Wed Dec 5 10:45:05 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Got request
for [4097][1][name=shassan]
(Wed Dec 5 10:45:05 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Request
processed. Returned 1,11,Fast reply - offline
=====
Although not 100% sure, (should have run "date;...",) second failed
"getent passwd shassan" triggers:
(Wed Dec 5 10:45:47 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to
get
information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Got request
for [4097][1][name=shassan]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Request
processed. Returned 1,11,Fast reply - offline
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send]
(0x0100): Trying
to resolve service 'IPA'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_port_status] (0x1000): Port
status of
port 0 for server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]]
[fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000):
Saving
the first resolved server
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200):
Found
address for server ipa1.sri.utoronto.ca: TTL 10800
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sss_ldap_init_send] (0x0400):
Setting 6
seconds timeout for connecting
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_ldap_connect_callback_add]
(0x1000):
New LDAP connection to [ldap://ipa1.sri.utoronto.ca:389/??base] with fd
[46].
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400):
calling ldap_search_ext with [(objectclass=*)][].
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [*]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [altServer]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [namingContexts]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedControl]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedExtension]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedFeatures]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedLDAPVersion]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedSASLMechanisms]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [defaultNamingContext]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [lastUSN]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [highestCommittedUSN]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 1
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3e02c80], ldap[0x3fdb450]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3e02c80], ldap[0x3fdb450]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400):
Search result: Success(0), no errmsg set
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_kinit_send] (0x0400):
Attempting
kinit (default, host/dovecot2.sri.utoronto.ca, SRI.UTORONTO.CA, 86400)
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_kinit_next_kdc] (0x1000):
Resolving
next KDC for service IPA
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send]
(0x0100): Trying
to resolve service 'IPA'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_port_status] (0x1000): Port
status of
port 0 for server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]]
[fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000):
Saving
the first resolved server
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200):
Found
address for server ipa1.sri.utoronto.ca: TTL 10800
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_kinit_kdc_resolved]
(0x1000): KDC
resolved, attempting to get TGT...
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [create_tgt_req_send_buffer]
(0x1000):
buffer size: 60
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Setting up
signal handler up for pid [14590]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Signal
handler set up for pid [14590]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [set_tgt_child_timeout] (0x0400):
Setting 6
seconds timeout for tgt child
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [write_pipe_handler] (0x0400): All
data has
been sent!
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [read_pipe_handler] (0x0400): EOF
received,
client finished
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_tgt_recv] (0x0400):
Child
responded: 0 [FILE:/var/lib/sss/db/ccache_SRI.UTORONTO.CA], expired on [135480
8747]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sasl_bind_send] (0x0100):
Executing sasl
bind mech: GSSAPI, user: host/dovecot2.sri.utoronto.ca
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000):
Waiting for
child [14590].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0100):
child [14590]
finished successfully.
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sss_child_handler] (0x2000):
waitpid
failed [10]: No child processes
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [fo_set_port_status] (0x0100):
Marking port
0 of server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [set_server_common_status]
(0x0100):
Marking server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_id_op_connect_done]
(0x2000): Old
USN: 358742, New USN: 364519
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_users_next_base]
(0x0400):
Searching for users with base [cn=accounts,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400):
calling ldap_search_ext with [(&(uid=shassan)(objectclass=posixAccount))][cn
=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uid]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uidNumber]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gecos]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [homeDirectory]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginShell]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPrincipalName]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowLastChange]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMin]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMax]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowWarning]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowInactive]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowExpire]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowFlag]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbLastPwdChange]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPasswordExpiration]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [pwdAttribute]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [authorizedService]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [accountExpires]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userAccountControl]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsAccountLock]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [host]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginDisabled]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginExpirationTime]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginAllowedTimeMap]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSshPubKey]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 5
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [be_run_online_cb] (0x0080): Going
online.
Running callbacks.
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8af00], ldap[0x3fdb450]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8af00], ldap[0x3fdb450]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400):
Search result: Success(0), no errmsg set
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_users_process] (0x0400):
Search
for users, returned 1 results.
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original DN [uid=shassan,cn=users,cn=accounts,dc=sri,dc=utoronto,dc=ca
] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
original
memberOf attributes to [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original mod-Timestamp [20121205133521Z] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
user
principal [shassan(a)SRI.UTORONTO.CA] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowLastChange [11472] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowMin is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowMax [99999] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowWarning [7] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowInactive is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowExpire is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowFlag is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbLastPwdChange [20121029140040Z] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbPasswordExpiration [20150417140040Z] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
pwdAttribute is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedService is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adAccountExpires is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adUserAccountControl is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
nsAccountLock is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedHost is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginDisabled is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginExpirationTime is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginAllowedTimeMap is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
sshPublicKey is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing
info for
user shassan
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_name]
(0x0400): No
such entry
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_add_user] (0x0400): Error:
17 (File
exists)
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_store_user] (0x0080): A
user with
the same UID [54184] was removed from the cache
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_uid]
(0x0400): No
such entry
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]]
[delayed_online_authentication_callback]
(0x0200): Backend is online, starting delayed online authentication.
======
At no later than Wed Dec 5 10:46:10 EST 2012, it recalled the memory:
[root@dovecot2 sssd]# getent passwd shassan
shassan:*:54184:541:Shazia Hassan:/home4/shassan:/bin/tcsh
[root@dovecot2 sssd]# date
Wed Dec 5 10:46:10 EST 2012
Then a successful Thunderbird login triggers:
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Got request
for [3][1][name=shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_initgr_next_base]
(0x0400):
Searching for users with base [cn=accounts,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400):
calling ldap_search_ext with [(&(uid=shassan)(objectclass=posixAccount))][cn
=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uid]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uidNumber]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gecos]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [homeDirectory]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginShell]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPrincipalName]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowLastChange]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMin]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMax]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowWarning]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowInactive]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowExpire]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowFlag]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbLastPwdChange]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPasswordExpiration]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [pwdAttribute]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [authorizedService]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [accountExpires]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userAccountControl]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsAccountLock]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [host]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginDisabled]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginExpirationTime]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginAllowedTimeMap]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSshPubKey]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 154
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400):
Search result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original DN [uid=shassan,cn=users,cn=accounts,dc=sri,dc=utoronto,dc=ca
] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
original
memberOf attributes to [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original mod-Timestamp [20121205154656Z] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
user
principal [shassan(a)SRI.UTORONTO.CA] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowLastChange [11472] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowMin is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowMax [99999] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowWarning [7] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowInactive is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowExpire is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowFlag is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbLastPwdChange [20121029140040Z] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbPasswordExpiration [20150417140040Z] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
pwdAttribute is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedService is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adAccountExpires is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adUserAccountControl is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
nsAccountLock is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedHost is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginDisabled is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginExpirationTime is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginAllowedTimeMap is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
sshPublicKey is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing
info for
user shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [userPassword] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowMin] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowInactive] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowExpire] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowFlag] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [pwdAttribute] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [authorizedService] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [adAccountExpires] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [adUserAccountControl] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [nsAccountLock] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [authorizedHost] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginDisabled] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginExpirationTime] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginAllowedTimeMap] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [sshPublicKey] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_has_deref_support] (0x0400):
The
server supports deref method OpenLDAP
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400):
calling ldap_search_ext with [(&(objectclass=posixGroup)(cn=*))][cn=ipausers
,cn=groups,cn=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [member]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 155
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3efbd90], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3efbd90], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400):
Search result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_initgr_nested_search]
(0x0040):
Search for group cn=ipausers,cn=groups,cn=accounts,dc=sri,dc=utoronto,dc=ca,
returned 0 results. Skipping
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]]
[sdap_initgr_store_user_memberships]
(0x1000): The user shassan is a direct member of 0 LDAP groups
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_get_direct_parents]
(0x2000):
searching sysdb with filter [(&(objectClass=group)(member=name=shassan,cn=use
rs,cn=sri.utoronto.ca,cn=sysdb))]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_get_direct_parents]
(0x1000):
shassan is a member of 0 sysdb groups
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]]
[sdap_initgr_store_user_memberships]
(0x2000): Updating memberships for shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [acctinfo_callback] (0x0100):
Request
processed. Returned 0,0,Success
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
command:
PAM_AUTHENTICATE
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
service: dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 9
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv:
1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
cli_pid: 13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [check_for_valid_tgt] (0x1000):
TGT end
time [1354808817].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [check_for_valid_tgt] (0x0080):
TGT is valid.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send]
(0x0100): Trying
to resolve service 'IPA'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [get_port_status] (0x1000): Port
status of
port 0 for server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]]
[fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000):
Saving
the first resolved server
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200):
Found
address for server ipa1.sri.utoronto.ca: [142.76.29.27] TTL 10800
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_resolve_callback] (0x0400):
Constructed uri 'ldap://ipa1.sri.utoronto.ca'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Setting up
signal handler up for pid [14717]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Signal
handler set up for pid [14717]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [write_pipe_handler] (0x0400): All
data has
been sent!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [read_pipe_handler] (0x0400): EOF
received,
client finished
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [krb5_child_done] (0x1000): TGT
times are
[1354722435][1354722435][1354808835][0].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [fo_set_port_status] (0x0100):
Marking port
0 of server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [set_server_common_status]
(0x0100):
Marking server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [safe_remove_old_ccache_file]
(0x1000): New
and old ccache file are the same, no one will be deleted.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Backend
returned: (0, 0, <NULL>) [Success]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Sending
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Sent
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000):
Waiting for
child [14717].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0100):
child [14717]
finished successfully.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sss_child_handler] (0x2000):
waitpid
failed [10]: No child processes
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
command:
PAM_ACCT_MGMT
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
service: dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv:
1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
cli_pid: 13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_access_send] (0x0400):
Performing
access check for user [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_account_expired_rhds]
(0x0400):
Performing RHDS access check for user [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_retry] (0x0400): Performing
cached
HBAC evaluation
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_attrs_to_rule] (0x1000):
Processing
rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_user_attrs_to_rule]
(0x1000):
Processing users for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is
set to 'all'.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_service_attrs_to_rule]
(0x1000):
Processing PAM services for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is
set to 'all'.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_thost_attrs_to_rule]
(0x1000):
Processing target hosts for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is
set to 'all'.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule]
(0x0400):
Processing source hosts for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule]
(0x2000): Source
hosts disabled, setting ALL
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000):
[1]
groups for [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000):
Added
group [ipausers] for user [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_hbac_evaluate_rules]
(0x0080): Access
granted by HBAC rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Backend
returned: (0, 0, <NULL>) [Success]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Sending
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Sent
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
command:
PAM_OPEN_SESSION
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
service: dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv:
1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
cli_pid: 13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x0400):
Retrieving
SELinux user mapping
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x2000):
Connection
status is [online].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400):
calling ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=dovecot2.sri.utor
onto.ca))][cn=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 156
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f62e80], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f62e80], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400):
Search result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x1000): Total
count [0]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_selinux_get_maps_next]
(0x0400):
Trying to fetch SELinux maps with following parameters: [2][(null)][cn=selin
ux,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400):
calling ldap_search_ext with [(&(objectclass=ipaselinuxusermap)(ipaEnabledFl
ag=TRUE))][cn=selinux,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberUser]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberHost]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [seeAlso]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSELinuxUser]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaEnabledFlag]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userCategory]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [hostCategory]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaUniqueID]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 157
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8b800], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8b800], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400):
Search result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x1000): Total
count [0]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_selinux_get_maps_done]
(0x0400): No
SELinux user maps found!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Backend
returned: (0, 0, Success) [Success]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Sending
result [4][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback]
(0x0100): Sent
result [4][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
command:
PAM_CLOSE_SESSION
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
service: dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv:
1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
cli_pid: 13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Sending
result
[0][sri.utoronto.ca]
I hope this is enough info for you. I am going to put in the cron job now...
Thanks,
Qing
_______________________________________________
sssd-devel mailing list
sssd-devel(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-devel One more piece of info,
it lost the memory again. Now I am pretty sure that if it
does not get the memory back by itself somehow, nothing will trigger it to do so.
I did a few of this: date; getent passwd shassan, I also asked the user to
open her Thunderbird, both actions just trigger this:
(Wed Dec 5 11:43:52 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to
get
information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Wed Dec 5 11:43:52 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to
get
information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Wed Dec 5 11:43:52 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to
get
information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Wed Dec 5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got
request
for [4097][1][name=shassan]
(Wed Dec 5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Request
processed. Returned 1,11,Fast reply - offline
(Wed Dec 5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got
request
for [4097][1][name=shassan]
(Wed Dec 5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Request
processed. Returned 1,11,Fast reply - offline
(Wed Dec 5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got
request
for [4097][1][name=shassan]
(Wed Dec 5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Request
processed. Returned 1,11,Fast reply - offline
NOTHING else...
Sure enough, just before I hit send, it decided to get back the memory:
[root@dovecot2 sssd]# date; getent passwd shassan
Wed Dec 5 11:53:30 EST 2012
shassan:*:54184:541:Shazia Hassan:/home4/shassan:/bin/tcsh
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got
request
for [3][1][name=shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_initgr_next_base]
(0x0400):
Searching for users with base [cn=accounts,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(uid=shassan)(objectclass=posixAccount))][cn
=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uid]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uidNumber]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gecos]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [homeDirectory]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginShell]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPrincipalName]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowLastChange]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMin]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMax]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowWarning]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowInactive]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowExpire]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowFlag]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbLastPwdChange]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPasswordExpiration]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [pwdAttribute]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [authorizedService]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [accountExpires]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userAccountControl]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsAccountLock]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [host]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginDisabled]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginExpirationTime]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginAllowedTimeMap]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSshPubKey]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 267
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3c98c70], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3c98c70], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original DN [uid=shassan,cn=users,cn=accounts,dc=sri,dc=utoronto,dc=ca
] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
original
memberOf attributes to [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original mod-Timestamp [20121205164344Z] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
user
principal [shassan(a)SRI.UTORONTO.CA] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowLastChange [11472] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowMin is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowMax [99999] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowWarning [7] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowInactive is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowExpire is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowFlag is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbLastPwdChange [20121029140040Z] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbPasswordExpiration [20150417140040Z] to attributes of [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
pwdAttribute is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedService is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adAccountExpires is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adUserAccountControl is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
nsAccountLock is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedHost is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginDisabled is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginExpirationTime is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginAllowedTimeMap is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
sshPublicKey is not available for [shassan].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing
info for
user shassan
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [userPassword] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowMin] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowInactive] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowExpire] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowFlag] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [pwdAttribute] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [authorizedService] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [adAccountExpires] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [adUserAccountControl] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [nsAccountLock] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [authorizedHost] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginDisabled] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginExpirationTime] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginAllowedTimeMap] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [sshPublicKey] from [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_has_deref_support] (0x0400):
The server
supports deref method OpenLDAP
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(objectclass=posixGroup)(cn=*))][cn=ipausers
,cn=groups,cn=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [member]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 268
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3c2c400], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3c2c400], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_initgr_nested_search]
(0x0040): Search
for group cn=ipausers,cn=groups,cn=accounts,dc=sri,dc=utoronto,dc=ca,
returned 0 results. Skipping
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]]
[sdap_initgr_store_user_memberships]
(0x1000): The user shassan is a direct member of 0 LDAP groups
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_get_direct_parents]
(0x2000):
searching sysdb with filter [(&(objectClass=group)(member=name=shassan,cn=use
rs,cn=sri.utoronto.ca,cn=sysdb))]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_get_direct_parents]
(0x1000): shassan
is a member of 0 sysdb groups
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]]
[sdap_initgr_store_user_memberships]
(0x2000): Updating memberships for shassan
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [acctinfo_callback] (0x0100):
Request
processed. Returned 0,0,Success
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[(nil)], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_AUTHENTICATE
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 1
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 9
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
18178
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [krb5_auth_send] (0x0100): No
ccache file for
user [shassan] found.
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send] (0x0100):
Trying to
resolve service 'IPA'
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [get_port_status] (0x1000): Port
status of
port 0 for server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]]
[fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000):
Saving the
first resolved server
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200):
Found
address for server ipa1.sri.utoronto.ca: TTL 10800
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_resolve_callback] (0x0400):
Constructed
uri 'ldap://ipa1.sri.utoronto.ca'
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Setting up
signal handler up for pid [18421]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Signal
handler set up for pid [18421]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [write_pipe_handler] (0x0400): All
data has
been sent!
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [read_pipe_handler] (0x0400): EOF
received,
client finished
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [krb5_child_done] (0x1000): TGT
times are
[1354726413][1354726413][1354812813][0].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [fo_set_port_status] (0x0100):
Marking port 0
of server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [set_server_common_status]
(0x0100): Marking
server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Backend
returned: (0, 0, <NULL>) [Success]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sending
result [0][sri.utoronto.ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sent
result [0][sri.utoronto.ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000):
Waiting for
child [18421].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0100): child
[18421]
finished successfully.
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000):
Waiting for
child [16176].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0020):
waitpid failed
[10][No child processes].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sss_child_handler] (0x2000):
waitpid failed
[10]: No child processes
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_ACCT_MGMT
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
18178
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_access_send] (0x0400):
Performing
access check for user [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_account_expired_rhds]
(0x0400):
Performing RHDS access check for user [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_retry] (0x0400): Performing
cached HBAC
evaluation
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_attrs_to_rule] (0x1000):
Processing
rule [allow_all]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_user_attrs_to_rule] (0x1000):
Processing users for rule [allow_all]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is set
to 'all'.
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_service_attrs_to_rule]
(0x1000):
Processing PAM services for rule [allow_all]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is set
to 'all'.
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_thost_attrs_to_rule]
(0x1000):
Processing target hosts for rule [allow_all]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is set
to 'all'.
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule]
(0x0400):
Processing source hosts for rule [allow_all]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule]
(0x2000): Source
hosts disabled, setting ALL
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000):
[1] groups
for [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000):
Added
group [ipausers] for user [shassan]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_hbac_evaluate_rules] (0x0080):
Access
granted by HBAC rule [allow_all]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Backend
returned: (0, 0, <NULL>) [Success]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sending
result [0][sri.utoronto.ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sent
result [0][sri.utoronto.ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_OPEN_SESSION
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
18178
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x0400):
Retrieving
SELinux user mapping
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x2000):
Connection
status is [online].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=dovecot2.sri.utor
onto.ca))][cn=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 269
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3f65030], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3f65030], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x1000): Total
count [0]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_selinux_get_maps_next]
(0x0400): Trying
to fetch SELinux maps with following parameters: [2][(null)][cn=selin
ux,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(objectclass=ipaselinuxusermap)(ipaEnabledFl
ag=TRUE))][cn=selinux,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberUser]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberHost]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [seeAlso]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSELinuxUser]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaEnabledFlag]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userCategory]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [hostCategory]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaUniqueID]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 270
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3e05cd0], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[0x3e05cd0], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x1000): Total
count [0]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_selinux_get_maps_done]
(0x0400): No
SELinux user maps found!
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Backend
returned: (0, 0, Success) [Success]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sending
result [4][sri.utoronto.ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sent
result [4][sri.utoronto.ca]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ccd810], connected[1], ops[(nil)], ldap[0x3f95840]
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_CLOSE_SESSION
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
18178
(Wed Dec 5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Sending
result
[0][sri.utoronto.ca]
Thanks,
Qing