sssd-log
sssd-nss-client-disconnect.txt

Fields changed

description: After using sssd for a while, group information is lost. In this case the computer was connected to internet but no access to ldap server which is behind firewall in internal network.

When starting terminal:
id: cannot find name for group ID 105

I may have catched this "on tape", see the log but not sure if this is excactly from the time when group info was lost. At least it is close. Same thing has happened on 1.1.0 and IIRC with previous versions also. This system is rhel 5. The same thing happens on rhel 6 beta 2 refresh also.

(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_last_change has value shadowLastChange
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_min has value shadowMin
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_max has value shadowMax
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_warning has value shadowWarning
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_inactive has value shadowInactive
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_expire has value shadowExpire
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_flag has value shadowFlag
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_krb_last_pwd_change has value krbLastPwdChange
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_krb_password_expiration has value krbPasswordExpiration
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_pwd_attribute has value pwdAttribute
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_object_class has value posixGroup
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_name has value cn
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_pwd has value userPassword
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_gid_number has value gidNumber
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_member has value memberuid
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_uuid has value (null)
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_modify_timestamp has value modifyTimestamp
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sssm_ldap_auth_init] (7): Service name for discovery set to ldap
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [be_fo_add_service] (6): Failover service already initialized!
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_service_init] (6): Added URI ldaps://server.domain.com
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [fo_add_server] (3): Adding new server 'server.domain.com', to service 'LDAP'
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [main] (1): Backend provider (LDAP) started!
(Sun Sep 12 10:03:10 2010) [sssd] [client_registration] (4): Received ID registration: (%BE_LDAP,1)
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (5): Marking LDAP as started.
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (4): Now starting services!
(Sun Sep 12 10:03:10 2010) [sssd] [start_service] (4): Queueing service nss for startup
(Sun Sep 12 10:03:10 2010) [sssd] [start_service] (4): Queueing service pam for startup
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [ldb] (6): server_sort:Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [server_setup] (3): CONFDB: /var/lib/sss/db/config.ldb
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [confdb_get_domain_internal] (1): No enumeration for [LDAP]!
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sbus_init_connection] (5): Adding connection 15C55170
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [monitor_common_send_id] (4): Sending ID: (nss,1)
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sbus_init_connection] (5): Adding connection 15C56BB0
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [dp_common_send_id] (4): Sending ID to DP: (1,NSS)
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sysdb_domain_init_internal] (5): DB File for LDAP: /var/lib/sss/db/cache_LDAP.ldb
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [ldb] (6): asq: Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Adding connection 0x174c8980.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_init_connection] (5): Adding connection 174C8980
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd] [monitor_service_init] (3): Initializing D-BUS Service
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [id_callback] (4): Got id ack and version (1) from Monitor
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Adding connection 0x53a4e00.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_init_connection] (5): Adding connection 53A4E00
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [be_client_init] (4): Set-up Backend ID timeout [0x53a5920]
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sss_process_init] (1): Responder Initialization complete
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [nss_process_init] (1): NSS Initialization complete
(Sun Sep 12 10:03:10 2010) [sssd] [client_registration] (4): Received ID registration: (nss,1)
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (5): Marking nss as started.
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [id_callback] (4): Got id ack and version (1) from Monitor
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [ldb] (6): server_sort:Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [server_setup] (3): CONFDB: /var/lib/sss/db/config.ldb
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [confdb_get_domain_internal] (1): No enumeration for [LDAP]!
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Adding connection 0x174ca370.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_init_connection] (5): Adding connection 174CA370
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd] [monitor_service_init] (3): Initializing D-BUS Service
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sbus_init_connection] (5): Adding connection 37C3CB0
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [monitor_common_send_id] (4): Sending ID: (pam,1)
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sbus_init_connection] (5): Adding connection 37C56F0
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [dp_common_send_id] (4): Sending ID to DP: (1,PAM)
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sysdb_domain_init_internal] (5): DB File for LDAP: /var/lib/sss/db/cache_LDAP.ldb
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [ldb] (6): asq: Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sss_process_init] (1): Responder Initialization complete
(Sun Sep 12 10:03:10 2010) [sssd] [client_registration] (4): Received ID registration: (pam,1)
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (5): Marking pam as started.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Cancel DP ID timeout [0x53a5920]
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Added Frontend client [NSS]
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [dp_id_callback] (4): Got id ack and version (1) from DP
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Adding connection 0x53a76d0.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_init_connection] (5): Adding connection 53A76D0
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [be_client_init] (4): Set-up Backend ID timeout [0x53a7f30]
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [id_callback] (4): Got id ack and version (1) from Monitor
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Cancel DP ID timeout [0x53a7f30]
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Added Frontend client [PAM]
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [dp_id_callback] (4): Got id ack and version (1) from DP
(Sun Sep 12 10:03:15 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:15 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:15 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:15 2010) [sssd] [services_startup_timeout] (6): Handling timeout
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [sss_cmd_get_version] (5): Received client version [1].
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [nss_cmd_getpwuid] (4): Requesting info for [999@LDAP]
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4097][1][idnumber=999]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][idnumber=999]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name not resolved'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'neutral'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name not resolved'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [resolv_gethostbyname_send] (4): Trying to resolve A record of 'server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [set_server_common_status] (4): Marking server 'server.domain.com' as 'resolving name'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [set_server_common_status] (4): Marking server 'server.domain.com' as 'name resolved'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [be_resolve_server_done] (4): Found address for server server.domain.com: [193.166.1.229]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=)][].
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: []
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [altServer]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [namingContexts]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedControl]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedExtension]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedFeatures]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedLDAPVersion]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Sun Sep 12 10:03:20 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:20 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:20 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:20 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:20 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:20 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:20 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:20 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): ldap_search_ext failed: Can't contact LDAP server
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): Connection error: (null)
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'neutral'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [be_resolve_server_done] (4): Found address for server server.domain.com: [193.166.1.229]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=)][].
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: []
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [altServer]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [namingContexts]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedControl]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedExtension]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedFeatures]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedLDAPVersion]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): ldap_search_ext failed: Can't contact LDAP server
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): Connection error: (null)
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'neutral'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [be_resolve_server_done] (4): Found address for server server.domain.com: [193.166.1.229]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=)][].
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: []
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [altServer]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [namingContexts]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedControl]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedExtension]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedFeatures]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedLDAPVersion]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): ldap_search_ext failed: Can't contact LDAP server
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): Connection error: (null)
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (1): No available servers for service 'LDAP'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_run_offline_cb] (3): Going offline. Running callbacks.
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 5, User lookup failed) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 5, User lookup failed
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_callback] (6): Returning info for user [999]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [acctinfo_callback] (4): Request processed. Returned 1,5,User lookup failed
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_timer] (4): Backend is marked offline, retry later!
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_set_timer] (6): Scheduling next cleanup at 1284285804.1694442
(Sun Sep 12 10:03:24 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid] (4): Requesting info for [105@LDAP]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 11, Fast reply - offline) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_callback] (6): Returning info for group [105]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_cmd_get_version] (5): Received client version [1].
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid] (4): Requesting info for [999@LDAP]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4097][1][idnumber=999]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][idnumber=999]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 11, Fast reply - offline) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_callback] (6): Returning info for user [999]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid] (4): Requesting info for [105@LDAP]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 11, Fast reply - offline) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_callback] (6): Returning info for group [105]
(Sun Sep 12 10:03:25 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:25 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:25 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:30 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:30 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:30 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:30 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:30 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:30 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:30 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:30 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:30 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:35 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:35 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:35 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:39 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:39 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:39 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:39 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:39 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:39 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:39 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:39 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:39 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:45 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:45 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:45 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:50 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:50 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:50 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:50 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:50 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:50 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:50 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:50 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:50 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:55 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:55 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:55 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:55 2010) [sssd[nss]] [client_recv] (5): Client disconnected!
(Sun Sep 12 10:04:00 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:04:00 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:04:00 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:04:00 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:04:00 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:04:00 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:04:00 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:04:00 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:04:00 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:04:05 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:04:05 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:04:05 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:04:10 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:04:10 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:04:10 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:04:10 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:04:10 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:04:10 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:04:10 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:04:10 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:04:10 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:04:12 2010) [sssd] [monitor_quit] (0): Interrupt: killing children

Here are the package versions:
sssd x86_64 1.2.1-27.el5 epel 1.9 M
sssd-client x86_64 1.2.1-27.el5 epel
sssd-client i386 1.2.1-27.el5 epel 44 k
c-ares x86_64 1.6.0-2.el5 epel 47 k
cyrus-sasl-gssapi x86_64 2.1.22-5.el5_4.3 rhel-x86_64-client-5 30 k
libcollection x86_64 0.5.0-27.el5 epel 45 k
libdhash x86_64 0.4.0-27.el5 epel 32 k
libini_config x86_64 0.5.1-27.el5 epel 37 k
libldb x86_64 0.9.10-25.el5 epel 88 k
libtalloc x86_64 2.0.1-7.el5 epel 34 k
libtdb x86_64 1.2.1-4.el5 epel 28 k
libtevent x86_64 0.9.8-7.el5 epel 19 k
=> After using sssd for a while, group information is lost. In this case the computer was connected to internet but no access to ldap server which is behind firewall in internal network.

When starting terminal:
{{{
id: cannot find name for group ID 105
}}}

I may have catched this "on tape", see the log but not sure if this is excactly from the time when group info was lost. At least it is close. Same thing has happened on 1.1.0 and IIRC with previous versions also. This system is rhel 5. The same thing happens on rhel 6 beta 2 refresh also.

{{{
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_last_change has value shadowLastChange
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_min has value shadowMin
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_max has value shadowMax
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_warning has value shadowWarning
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_inactive has value shadowInactive
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_expire has value shadowExpire
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_shadow_flag has value shadowFlag
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_krb_last_pwd_change has value krbLastPwdChange
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_user_krb_password_expiration has value krbPasswordExpiration
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_pwd_attribute has value pwdAttribute
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_object_class has value posixGroup
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_name has value cn
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_pwd has value userPassword
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_gid_number has value gidNumber
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_member has value memberuid
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_uuid has value (null)
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_get_map] (5): Option ldap_group_modify_timestamp has value modifyTimestamp
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sssm_ldap_auth_init] (7): Service name for discovery set to ldap
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [be_fo_add_service] (6): Failover service already initialized!
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sdap_service_init] (6): Added URI ldaps://server.domain.com
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [fo_add_server] (3): Adding new server 'server.domain.com', to service 'LDAP'
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [main] (1): Backend provider (LDAP) started!
(Sun Sep 12 10:03:10 2010) [sssd] [client_registration] (4): Received ID registration: (%BE_LDAP,1)
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (5): Marking LDAP as started.
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (4): Now starting services!
(Sun Sep 12 10:03:10 2010) [sssd] [start_service] (4): Queueing service nss for startup
(Sun Sep 12 10:03:10 2010) [sssd] [start_service] (4): Queueing service pam for startup
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [ldb] (6): server_sort:Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [server_setup] (3): CONFDB: /var/lib/sss/db/config.ldb
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [confdb_get_domain_internal] (1): No enumeration for [LDAP]!
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sbus_init_connection] (5): Adding connection 15C55170
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [monitor_common_send_id] (4): Sending ID: (nss,1)
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sbus_init_connection] (5): Adding connection 15C56BB0
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [dp_common_send_id] (4): Sending ID to DP: (1,NSS)
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sysdb_domain_init_internal] (5): DB File for LDAP: /var/lib/sss/db/cache_LDAP.ldb
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [ldb] (6): asq: Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Adding connection 0x174c8980.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_init_connection] (5): Adding connection 174C8980
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd] [monitor_service_init] (3): Initializing D-BUS Service
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [id_callback] (4): Got id ack and version (1) from Monitor
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Adding connection 0x53a4e00.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_init_connection] (5): Adding connection 53A4E00
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [be_client_init] (4): Set-up Backend ID timeout [0x53a5920]
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [sss_process_init] (1): Responder Initialization complete
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [nss_process_init] (1): NSS Initialization complete
(Sun Sep 12 10:03:10 2010) [sssd] [client_registration] (4): Received ID registration: (nss,1)
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (5): Marking nss as started.
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [id_callback] (4): Got id ack and version (1) from Monitor
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [ldb] (6): server_sort:Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [server_setup] (3): CONFDB: /var/lib/sss/db/config.ldb
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [confdb_get_domain_internal] (1): No enumeration for [LDAP]!
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Adding connection 0x174ca370.
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_init_connection] (5): Adding connection 174CA370
(Sun Sep 12 10:03:10 2010) [sssd] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd] [monitor_service_init] (3): Initializing D-BUS Service
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sbus_init_connection] (5): Adding connection 37C3CB0
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [monitor_common_send_id] (4): Sending ID: (pam,1)
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sbus_init_connection] (5): Adding connection 37C56F0
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [dp_common_send_id] (4): Sending ID to DP: (1,PAM)
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sysdb_domain_init_internal] (5): DB File for LDAP: /var/lib/sss/db/cache_LDAP.ldb
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [ldb] (6): asq: Unable to register control with rootdse!
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [sss_process_init] (1): Responder Initialization complete
(Sun Sep 12 10:03:10 2010) [sssd] [client_registration] (4): Received ID registration: (pam,1)
(Sun Sep 12 10:03:10 2010) [sssd] [mark_service_as_started] (5): Marking pam as started.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Cancel DP ID timeout [0x53a5920]
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Added Frontend client [NSS]
(Sun Sep 12 10:03:10 2010) [sssd[nss]] [dp_id_callback] (4): Got id ack and version (1) from DP
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Entering.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Adding connection 0x53a76d0.
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_init_connection] (5): Adding connection 53A76D0
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [sbus_server_init_new_connection] (5): Got a connection
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [be_client_init] (4): Set-up Backend ID timeout [0x53a7f30]
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [id_callback] (4): Got id ack and version (1) from Monitor
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Cancel DP ID timeout [0x53a7f30]
(Sun Sep 12 10:03:10 2010) [sssd[be[LDAP]]] [client_registration] (4): Added Frontend client [PAM]
(Sun Sep 12 10:03:10 2010) [sssd[pam]] [dp_id_callback] (4): Got id ack and version (1) from DP
(Sun Sep 12 10:03:15 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:15 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:15 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:15 2010) [sssd] [services_startup_timeout] (6): Handling timeout
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [sss_cmd_get_version] (5): Received client version [1].
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [nss_cmd_getpwuid] (4): Requesting info for [999@LDAP]
(Sun Sep 12 10:03:18 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4097][1][idnumber=999]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][idnumber=999]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name not resolved'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'neutral'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name not resolved'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [resolv_gethostbyname_send] (4): Trying to resolve A record of 'server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [set_server_common_status] (4): Marking server 'server.domain.com' as 'resolving name'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [set_server_common_status] (4): Marking server 'server.domain.com' as 'name resolved'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [be_resolve_server_done] (4): Found address for server server.domain.com: [193.166.1.229]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=)][].
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: []
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [altServer]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [namingContexts]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedControl]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedExtension]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedFeatures]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedLDAPVersion]
(Sun Sep 12 10:03:18 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Sun Sep 12 10:03:20 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:20 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:20 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:20 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:20 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:20 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:20 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:20 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): ldap_search_ext failed: Can't contact LDAP server
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): Connection error: (null)
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'neutral'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [be_resolve_server_done] (4): Found address for server server.domain.com: [193.166.1.229]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=)][].
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: []
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [altServer]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [namingContexts]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedControl]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedExtension]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedFeatures]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedLDAPVersion]
(Sun Sep 12 10:03:22 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): ldap_search_ext failed: Can't contact LDAP server
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): Connection error: (null)
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'neutral'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [be_resolve_server_done] (4): Found address for server server.domain.com: [193.166.1.229]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_uri_callback] (6): Constructed uri 'ldaps://server.domain.com'
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=)][].
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: []
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [altServer]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [namingContexts]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedControl]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedExtension]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedFeatures]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedLDAPVersion]
(Sun Sep 12 10:03:23 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): ldap_search_ext failed: Can't contact LDAP server
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (3): Connection error: (null)
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'name resolved'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (1): No available servers for service 'LDAP'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_run_offline_cb] (3): Going offline. Running callbacks.
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 5, User lookup failed) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 5, User lookup failed
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_callback] (6): Returning info for user [999]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [acctinfo_callback] (4): Request processed. Returned 1,5,User lookup failed
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_timer] (4): Backend is marked offline, retry later!
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_set_timer] (6): Scheduling next cleanup at 1284285804.1694442
(Sun Sep 12 10:03:24 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid] (4): Requesting info for [105@LDAP]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 11, Fast reply - offline) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_callback] (6): Returning info for group [105]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_cmd_get_version] (5): Received client version [1].
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid] (4): Requesting info for [999@LDAP]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4097][1][idnumber=999]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][idnumber=999]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 11, Fast reply - offline) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getpwuid_callback] (6): Returning info for user [999]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid] (4): Requesting info for [105@LDAP]
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [LDAP][4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=105]
(Sun Sep 12 10:03:24 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 11, Fast reply - offline) from Data Provider
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Sun Sep 12 10:03:24 2010) [sssd[nss]] [nss_cmd_getgrgid_callback] (6): Returning info for group [105]
(Sun Sep 12 10:03:25 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:25 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:25 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:30 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:30 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:30 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:30 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:30 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:30 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:30 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:30 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:30 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:35 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:35 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:35 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:39 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:39 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:39 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:39 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:39 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:39 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:39 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:39 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:39 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:45 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:45 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:45 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:50 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:03:50 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:03:50 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:03:50 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:03:50 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:50 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:50 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:50 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:03:50 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:03:55 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:03:55 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:03:55 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:03:55 2010) [sssd[nss]] [client_recv] (5): Client disconnected!
(Sun Sep 12 10:04:00 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:04:00 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:04:00 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:04:00 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:04:00 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:04:00 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:04:00 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:04:00 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:04:00 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:04:05 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:04:05 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:04:05 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:04:10 2010) [sssd] [service_check_alive] (4): Checking service nss(5532) is still alive
(Sun Sep 12 10:04:10 2010) [sssd] [service_send_ping] (4): Pinging nss
(Sun Sep 12 10:04:10 2010) [sssd] [service_check_alive] (4): Checking service pam(5533) is still alive
(Sun Sep 12 10:04:10 2010) [sssd] [service_send_ping] (4): Pinging pam
(Sun Sep 12 10:04:10 2010) [sssd] [service_check_alive] (4): Checking service LDAP(5531) is still alive
(Sun Sep 12 10:04:10 2010) [sssd] [service_send_ping] (4): Pinging LDAP
(Sun Sep 12 10:04:10 2010) [sssd] [ping_check] (4): Service LDAP replied to ping
(Sun Sep 12 10:04:10 2010) [sssd] [ping_check] (4): Service nss replied to ping
(Sun Sep 12 10:04:10 2010) [sssd] [ping_check] (4): Service pam replied to ping
(Sun Sep 12 10:04:12 2010) [sssd] [monitor_quit] (0): Interrupt: killing children
}}}

Here are the package versions:
{{{
sssd x86_64 1.2.1-27.el5 epel 1.9 M
sssd-client x86_64 1.2.1-27.el5 epel
sssd-client i386 1.2.1-27.el5 epel 44 k
c-ares x86_64 1.6.0-2.el5 epel 47 k
cyrus-sasl-gssapi x86_64 2.1.22-5.el5_4.3 rhel-x86_64-client-5 30 k
libcollection x86_64 0.5.0-27.el5 epel 45 k
libdhash x86_64 0.4.0-27.el5 epel 32 k
libini_config x86_64 0.5.1-27.el5 epel 37 k
libldb x86_64 0.9.10-25.el5 epel 88 k
libtalloc x86_64 2.0.1-7.el5 epel 34 k
libtdb x86_64 1.2.1-4.el5 epel 28 k
libtevent x86_64 0.9.8-7.el5 epel 19 k
}}}

Today the laptop was in internal network and it was booted up. When logging in there was a message "authenticated with cached credentials" and when opening terminal:

id: cannot find name for group ID 105

..even when it should have access to ldap. Before the boot the laptop crashed in suspend.

Here is the current sssd.conf

[sssd]
config_file_version = 2
domains = LDAP
reconnection_retries = 3
sbus_timeout = 30
services = nss, pam

[nss]
filter_groups = root
filter_users = root
reconnection_retries = 3

[pam]
reconnection_retries = 3

[domain/LDAP]
# access_provider = allow
auth_provider = ldap
cache_credentials = TRUE
chpass_provider = ldap
enumerate = false
id_provider = ldap
ldap_group_search_base = ou=Groups,o=internal,dc=domain,dc=com
#ldap_network_timeout = 5
#ldap_search_timeout = 5 
ldap_tls_cacertdir = /etc/openldap/cacerts
ldap_uri = ldaps://server.domain.com
ldap_user_search_base = ou=People,o=internal,dc=domain,dc=com
ldap_search_base = dc=domain,dc=com

ldap_user_gecos = cn

#DNS lookups
#lookup_family_order = ipv4_only
#dns_resolver_timeout = 3
#max_id = 50000
min_id = 105
timeout = 5

Replying to [comment:2 w1lson]:

Today the laptop was in internal network and it was booted up. When logging in there was a message "authenticated with cached credentials" and when opening terminal:

This is not uncommon right at boot time. During boot, if another service requests information from the SSSD before the system has an IP address, it will go into offline mode for one minute (this is so we don't slow down the boot process). So you may have simply attempted login before that minute was up.

{{{
id: cannot find name for group ID 105
}}}

..even when it should have access to ldap. Before the boot the laptop crashed in suspend.

Like I said, it didn't have access to LDAP yet because of the offline minute I mentioned above. I'm not sure yet why group 105 was missing if it was available previously. Can you confirm that group 105 was accessible before?

Fields changed

milestone: NEEDS_TRIAGE => SSSD 1.2.4

Fields changed

milestone: SSSD 1.2.4 => NEEDS_TRIAGE

Ok,

probably the group info was lost when offline. It was offline when I suspended. When booting up online and after logging in, The group info was recovered after a while, maybe it was after that one minute. It didn't know about that one minute delay. Sounds a bit longish time though...

What's concerning me here is the assertion that the group was lost when offline. That shouldn't be able to happen, since we do not ever modify the cache while the SSSD is offline.

The only way that a cache entry can be deleted is if we make a request to LDAP for that cache entry and LDAP responds with "no such entry".

So if this entry is being deleted, something else is going on here.

Is it possible that you have two LDAP servers that are out of sync?

There is only one ldap server.

Is it possible that for some reason when a computer has connection to internet but no access to ldap (which is behind firewall) something goes wrong there? sssd sees the internet connection finds the server from dns, but cannot access it and then goes nuts.

That shouldn't be possible. Do you have logs that back that up?

If the LDAP server is not reachable, we time out and then mark as offline again (and return the results from the cache at that point).

Replying to [comment:6 w1lson]:

It didn't know about that one minute delay. Sounds a bit longish time though...

For the record, this should be less of an issue in 1.3.0 and later. We added a netlink monitor so that we will always attempt to go online if we detect a change in the routing table (e.g. NetworkManager changes IP addresses or a VPN comes up)

Is it possible that the LDAP server is reachable from outside the network, but offers different data? We had a user report today where the LDAP server returned different results based on the host IP address (e.g. if the range was within the internal network range, the results had all attributes, but if it was outside the internal network range, the search returned nothing).

You should check whether the server you are connected to has any similar restrictions. Are you sure the server is completely unreachable when you are not inside the network?

I catched it on the logs. There is "Found 1 expired group entries" and also "About to delete group ldapusers" (why?) and then there is also input/output error. The computer was suspended, see timestamps, and then I woke it up without network connection. The group info was lost immediately. I have the complete log if you need any more info but I think the group info is lost in the part I post below.

(Fri Sep 17 14:53:26 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: F172960
(Fri Sep 17 14:53:26 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Fri Sep 17 14:53:26 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Fri Sep 17 14:53:31 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: F172960
(Fri Sep 17 14:53:31 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Fri Sep 17 14:53:31 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Fri Sep 17 14:53:36 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: F172960
(Fri Sep 17 14:53:36 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Fri Sep 17 14:53:36 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [cleanup_users_send] (9): Cache expiration is set to 0 days
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sysdb_search_users_check_handle] (6): Search users with filter: (&(objectclass=user)(&(!(dataExpireTimestamp=0))(dataExpireTimestamp<=1284963699)(!(lastLogin=*))))
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sysdb_search_entry_done] (6): Error: Entry not Found!
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sysdb_search_groups_check_handle] (6): Search groups with filter: (&(objectclass=group)(&(!(dataExpireTimestamp=0))(dataExpireTimestamp<=1284963699)))
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [cleanup_groups_process] (4): Found 1 expired group entries!
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sysdb_search_users_check_handle] (6): Search users with filter: (&(objectclass=user)(memberOf=name=ldapusers,cn=groups,cn=LDAP,cn=sysdb))
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sysdb_search_entry_done] (6): Error: Entry not Found!
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [cleanup_groups_delete] (8): About to delete group ldapusers
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sldb_request_callback] (6): LDB Error: 1 (ltdb modify without transaction)
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sysdb_op_default_done] (6): Error: 5 (Input/output error)
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [cleanup_groups_delete_done] (2): Group delete returned 5 (Input/output error)
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_groups_done] (1): Failed to cleanup groups (5 [Input/output error]), retrying later!
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_set_timer] (6): Scheduling next cleanup at 1284974499.577980
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: F172960
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: F185750
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4099][1][name=postfix]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_initgr_send] (9): Retrieving info for initgroups call
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(uid=postfix)(objectclass=posixAccount))][ou=People,o=internal,dc=domain,dc=com].
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [objectClass]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [uid]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [userPassword]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [uidNumber]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [gidNumber]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [cn]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [homeDirectory]
(Mon Sep 20 09:21:39 2010) [sssd[be[LDAP]]] [sdap_get_generic_send] (7): Requesting attrs: [loginShell]

Thank you for attaching the logs. They indicate that this is a duplicate of ticket #621.

The problem is this - during initgroups, we never added the group "ldapusers" to the user entry, which means there was no link between ldapusers and the user entry (no member/memberof attributes). The way our current cleanup code works is that we remove group entries past their lifetime that are not referenced from any user entry. When we fix our initgroups processing so that the attributes are added, the problem will go away.

resolution: => duplicate
status: new => closed

This is not fixed.

id: cannot find name for group ID 105
[user@host ~]$ rpm -qa|grep sssd
sssd-client-1.2.1-28.el5.0.1.x86_64
sssd-1.2.1-28.el5.0.1.x86_64
sssd-client-1.2.1-28.el5.0.1.i386
[user@host ~]$

resolution: duplicate =>
status: closed => reopened

Needs investigation. Leaving in NEEDS TRIAGE for now.

owner: somebody => sgallagh
status: reopened => new

I set up a test which does 'id username' every minute and detach the computer from network. After exactly 12 hours of system uptime the group information is lost. Here is a log from that period.

(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][name=username]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][idnumber=999]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=105]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4099][1][name=username]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4099][1][name=username]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=105]
(Tue Nov  2 04:16:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:16:54 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:16:54 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:54 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:16:59 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:16:59 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:16:59 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:04 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:04 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:04 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [cleanup_users_send] (9): Cache expiration is set to 0 days
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sysdb_search_users_check_handle] (6): Search users with filter: (&(objectclass=user)(&(!(dataExpireTimestamp=0))(dataExpireTimestamp<=1288664227)(!(lastLogin=*))))
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sysdb_search_entry_done] (6): Error: Entry not Found!
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sysdb_search_groups_check_handle] (6): Search groups with filter: (&(objectclass=group)(&(!(dataExpireTimestamp=0))(dataExpireTimestamp<=1288664227)))
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [cleanup_groups_process] (4): Found 2 expired group entries!
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sysdb_search_users_check_handle] (6): Search users with filter: (&(objectclass=user)(memberOf=name=fuse,cn=groups,cn=LDAP,cn=sysdb))
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sysdb_search_users_check_handle] (6): Search users with filter: (&(objectclass=user)(memberOf=name=ldapusers,cn=groups,cn=LDAP,cn=sysdb))
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sysdb_search_entry_done] (6): Error: Entry not Found!
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [cleanup_groups_delete] (8): About to delete group ldapusers
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sldb_request_callback] (6): LDB Error: 1 (ltdb modify without transaction)
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [sysdb_op_default_done] (6): Error: 5 (Input/output error)
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [cleanup_groups_delete_done] (2): Group delete returned 5 (Input/output error)
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_groups_done] (1): Failed to cleanup groups (5 [Input/output error]), retrying later!
(Tue Nov  2 04:17:07 2010) [sssd[be[LDAP]]] [ldap_id_cleanup_set_timer] (6): Scheduling next cleanup at 1288675027.460240
(Tue Nov  2 04:17:08 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:08 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:08 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:14 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:14 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:14 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:19 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:19 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:19 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:24 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:24 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:24 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:29 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:29 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:29 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:34 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:34 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:34 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:39 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:44 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:44 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:44 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:49 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:49 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:49 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][name=username]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'working'
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [get_port_status] (7): Port status of port 636 for server 'server.domain.com' is 'not working'
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [get_port_status] (4): Reseting the status of port 636 for server 'server.domain.com'
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [get_server_status] (7): Status of server 'server.domain.com' is 'working'
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_resolve_server_done] (4): Found address for server server.domain.com: [123.123.123.123]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [setup_ldap_connection_callbacks] (9): LDAP connection callbacks are not supported.
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [simple_bind_send] (4): Executing simple bind as: (null)
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [simple_bind_send] (1): ldap_bind failed (-1)[Can't contact LDAP server]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [fo_set_port_status] (4): Marking port 636 of server 'server.domain.com' as 'not working'
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sdap_handle_release] (8): Trace: sh[0x17b3b930], connected[0], ops[(nil)], ldap[0x17c092b0], destructor_lock[0], release_memory[0]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_mark_offline] (8): Going offline!
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_run_offline_cb] (3): Going offline. Running callbacks.
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [acctinfo_callback] (4): Request processed. Returned 1,110,User lookup failed
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4097][1][idnumber=999]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=105]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4099][1][name=username]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B390C0
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Got request for [4099][1][name=username]
(Tue Nov  2 04:17:51 2010) [sssd[be[LDAP]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Tue Nov  2 04:17:54 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:54 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:54 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:17:59 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:17:59 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:17:59 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:04 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:04 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:04 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:09 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:09 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:09 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:14 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:14 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:14 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:19 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:19 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:19 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:24 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:24 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:24 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:29 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:29 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:29 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:34 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:34 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:34 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:39 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:39 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:44 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:44 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:44 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Nov  2 04:18:49 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): dbus conn: 17B25960
(Tue Nov  2 04:18:49 2010) [sssd[be[LDAP]]] [sbus_dispatch] (9): Dispatching.
(Tue Nov  2 04:18:49 2010) [sssd[be[LDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]

sssd-test.sh

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

#!/bin/bash
# test sssd

i="0"
while [ $i ]
do
date --rfc-3339=seconds | tr -d '\n\' >> /sssd-test.log
echo " " | tr -d '\n\' >> /sssd-test.log
id username >> /sssd-test.log
sleep 60
done

Hmm, very interesting. We have a cleanup task that exists to keep the filesize of the LDB cache down. Every twelve hours (by default), it runs and is meant to clean up users that have never logged in and groups that have no users in them.

The order of operations is this:
1) Search for users whose cache expiration has passed and who have never logged in. Remove any users that meet this search.
2) Search for groups whose cache expiration has passed and who have no users as members (I have opened ticket #633 to address the edge-case where a group has only other, nested groups in it, but no direct users). Remove groups who are passed cache timeout and have no members.

So I'm not certain why your system is deleting the group ldapusers. Given that {{{id username}}} is returning the group membership correctly before that. Can you install the {{{ldb-tools}}} package and show me the output of

ldbsearch -H /var/lib/sss/db/cache_LDAP.ldb name=ldapusers

and

ldbsearch -H /var/lib/sss/db/cache_LDAP.ldb name=username

I need to identify whether the member/memberOf link between ldapusers and username is broken.

We will provide the workaround #662 in 1.2.5 and fix this fully in 1.5.

milestone: NEEDS_TRIAGE => SSSD 1.5.0

This is the record when things are working:

[user@host]# ldbsearch -H /var/lib/sss/db/cache_LDAP.ldb name=ldapusers
asq: Unable to register control with rootdse!
# record 1
dn: name=ldapusers,cn=groups,cn=LDAP,cn=sysdb
createTimestamp: 1288765461
gidNumber: 105
name: ldapusers
objectClass: group
originalDN: cn=ldapusers,ou=Groups,o=internal,dc=domain,dc=com
originalModifyTimestamp: 20090915145102Z
lastUpdate: 1288765461
dataExpireTimestamp: 1288770861
distinguishedName: name=ldapusers,cn=groups,cn=LDAP,cn=sysdb

# returned 1 records
# 1 entries
# 0 referrals

If you delete groups that don't have any members then that is probably why the group gets deleted because ldapusers does not have any direct members. Users have gidNumber: 105 and it maps to ldapusers group automatically and has worked previously.

Aha! That definitely explains it, then. I should be able to fix this just by changing the search filter in the cache to look for gidNumber as well.

Thank you very much w1lson for your assistance (and patience) in helping to track this down.

Fields changed

status: new => assigned

Fixed by 91565f1

priority: major => critical
resolution: => fixed
status: assigned => closed

Fields changed

fixedin: => 1.2.5

This should be fixed in https://admin.fedoraproject.org/updates/sssd-1.2.1-28.el5.0.2 for EPEL 5.

One additional note: you can speed up your ability to test by changing the option {{{ldap_purge_cache_timeout}}}, which defaults to 12 hours (in seconds).

After updating to sssd-1.2.1-28.el5.0.2.x86_64 packages, group information does not disappear anymore in the few tests I have done.

Fields changed

rhbz: => 0

SSSD is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in SSSD's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/SSSD/sssd/issues/1666

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.