Bug 647816

Summary: Login screen freezes for more than 2mins when configured SSSD for proxy auth.
Product: Red Hat Enterprise Linux 6 Reporter: Gowrishankar Rajaiyan <grajaiya>
Component: sssdAssignee: Stephen Gallagher <sgallagh>
Status: CLOSED ERRATA QA Contact: Chandrasekar Kannan <ckannan>
Severity: medium Docs Contact:
Priority: low    
Version: 6.0CC: benl, dpal, jgalipea, kbanerje
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: sssd-1.5.0-1.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-05-19 11:41:51 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 579778    
Attachments:
Description Flags
sssd_PROXYLDAP.log.tgz none

Description Gowrishankar Rajaiyan 2010-10-29 15:13:14 UTC 
Description of problem:
The gnome-screensaver freezes for more than 2 minutes when configured SSSD for proxy id and auth.

Version-Release number of selected component (if applicable):
sssd-1.2.1-28.el6_0.1.x86_64

How reproducible:


Steps to Reproduce:
1. Configure SSSD for proxy provider and auth.
2. Login to the system using GDM.
3. Go to System | Preferences | About me
4. Change your password.
5. Lock screen.
6. Try incorrect or blank passwords for multiple times.
7. Wait for few minutes (~5 mins)
8. Now try to unlock the screen with correct/incorrect password.
  
Actual results:
gnome-screensaver-dialog freezes at 'checking...' for more than 2 mins.

Work-around: restart SSSD service.

Expected results:
Should not freeze and return "Incorrect password" immediately after the password validation.

Additional info:

Relevant sssd.conf:
[domain/PROXYLDAP]
id_provider = proxy
proxy_lib_name = ldap
proxy_pam_target = sssdproxyldap
debug_level = 9
debug_to_files = true
auth_provider = proxy
cache_credentials = True
enumerate = true

/var/log/sssd/sssd_PROXYLDAP:
(Fri Oct 29 20:29:28 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): dbus conn: 2129590
(Fri Oct 29 20:29:28 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): Dispatching.
(Fri Oct 29 20:29:28 2010) [sssd[be[PROXYLDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Fri Oct 29 20:29:35 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): dbus conn: 212C500
(Fri Oct 29 20:29:35 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): Dispatching.
(Fri Oct 29 20:29:35 2010) [sssd[be[PROXYLDAP]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Fri Oct 29 20:29:35 2010) [sssd[be[PROXYLDAP]]] [be_get_account_info] (4): Got request for [3][1][name=puser1]
(Fri Oct 29 20:29:35 2010) [sssd[be[PROXYLDAP]]] [ldb] (9): start ldb transaction (nesting: 0)
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [get_initgr_groups_process] (2): proxy -> initgroups_dyn failed (0)[Success]
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [ldb] (9): cancel ldb transaction (nesting: 0)
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [acctinfo_callback] (4): Request processed. Returned 3,5,Internal Error (Input/output error)
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): dbus conn: 212C500
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): Dispatching.
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [sbus_message_handler] (9): Received SBUS method [pamHandler]
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [be_pam_handler] (4): Got request with the following data
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): domain: PROXYLDAP
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): user: puser1
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): service: gnome-screensaver
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): tty: :0.0
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): ruser: 
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): rhost: 
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): authtok type: 1
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): authtok size: 10
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): newauthtok type: 0
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): newauthtok size: 0
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): priv: 0
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [pam_print_data] (4): cli_pid: 4274
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [proxy_child_send] (8): Queueing request [14]
(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [proxy_child_send] (8): All available child slots are full, queuing request
(Fri Oct 29 20:29:38 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): dbus conn: 2129590
(Fri Oct 29 20:29:38 2010) [sssd[be[PROXYLDAP]]] [sbus_dispatch] (9): Dispatching.
(Fri Oct 29 20:29:38 2010) [sssd[be[PROXYLDAP]]] [sbus_message_handler] (9): Received SBUS method [ping]
Comment 2 Stephen Gallagher 2010-10-29 15:33:40 UTC 
Please gzip and attach the complete log for this domain.

(Fri Oct 29 20:29:36 2010) [sssd[be[PROXYLDAP]]] [proxy_child_send] (8): All
available child slots are full, queuing request

This shouldn't happen unless you have a lot of other auth requests waiting to be processed (or stuck somehow). I need to see a longer history to figure out why that happened.
Comment 3 Gowrishankar Rajaiyan 2010-10-29 20:04:33 UTC 
Created attachment 456551 [details]
sssd_PROXYLDAP.log.tgz
Comment 4 Dmitri Pal 2010-10-29 22:31:43 UTC 
https://fedorahosted.org/sssd/ticket/660
Comment 6 Gowrishankar Rajaiyan 2011-03-22 07:39:38 UTC 
Method:
1. Set up proxy auth 
2. Perform more than 12 auth attempts (successful or not doesn't matter)

Result: No more timeouts seen, as expected.


relevant sssd.conf:
[domain/default]
id_provider = proxy
auth_provider = proxy
proxy_lib_name = ldap
proxy_pam_target = sssdproxyldap
debug_level = 9
cache_credentials = true
enumerate = true


/var/log/sssd/sssd_domain.log:
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F95F10
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for [3][1][name=puser1]
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 0)
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 1)
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0xfdfc90

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x100acc0

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Destroying timer event 0x100acc0 "ltdb_timeout"

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Ending timer event 0xfdfc90 "ltdb_callback"

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 2)
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1012770

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1012890

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Destroying timer event 0x1012890 "ltdb_timeout"

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): tevent: Ending timer event 0x1012770 "ltdb_callback"

(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): commit ldb transaction (nesting: 2)
(Tue Mar 22 13:04:12 2011) [sssd[be[default]]] [ldb] (9): commit ldb transaction (nesting: 1)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [get_initgr_groups_process] (2): proxy -> initgroups_dyn failed (5)[Input/output error]
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [ldb] (9): cancel ldb transaction (nesting: 0)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [acctinfo_callback] (4): Request processed. Returned 3,5,Internal Error (Memory buffer error)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F95F10
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [pamHandler]
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [be_pam_handler] (4): Got request with the following data
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): domain: default
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): user: puser1
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): service: gnome-screensaver
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): tty: :0.0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): ruser: 
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): rhost: 
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): authtok type: 1
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): authtok size: 6
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok type: 0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok size: 0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): priv: 0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): cli_pid: 1673
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [proxy_child_send] (8): Queueing request [37]
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [proxy_child_init_send] (7): Starting proxy child with args [/usr/libexec/sssd/proxy_child -d 9 --debug-to-files --domain default --id 37]
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_server_init_new_connection] (5): Entering.
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_server_init_new_connection] (5): Adding connection 0x100ac00.
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_init_connection] (5): Adding connection 100AC00
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_add_watch] (8): 0x100b0d0/0xff9f90 (26), -/W (disabled)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x100b0d0/0xfbe4c0 (26), R/- (enabled)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_server_init_new_connection] (5): Got a connection
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [proxy_client_init] (4): Set-up proxy client ID timeout [0x10113b0]
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 100AC00
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x100b0d0/0xfbe4c0 (26), R/- (disabled)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x100b0d0/0xff9f90 (26), -/W (enabled)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x100b0d0/0xfbe4c0 (26), R/- (enabled)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x100b0d0/0xff9f90 (26), -/W (disabled)
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 100AC00
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [RegisterService]
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [client_registration] (4): Cancel proxy client ID timeout [0x10113b0]
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [client_registration] (4): Proxy client [37] connected
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [proxy_pam_conv_send] (4): Sending request with the following data:
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): domain: default
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): user: puser1
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): service: gnome-screensaver
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): tty: :0.0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): ruser: 
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): rhost: 
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): authtok type: 1
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): authtok size: 6
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok type: 0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok size: 0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): priv: 0
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [pam_print_data] (4): cli_pid: 1673
(Tue Mar 22 13:04:13 2011) [sssd[be[default]]] [sbus_add_timeout] (8): 0x100fa80
(Tue Mar 22 13:04:14 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F92EF0
(Tue Mar 22 13:04:14 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:14 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [sbus_remove_timeout] (8): 0x100fa80
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 100AC00
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [proxy_pam_conv_reply] (8): Handling pam conversation reply
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [proxy_pam_conv_reply] (4): received: [7][default]
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [proxy_child_destructor] (8): Removing proxy child id [37]
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Backend returned: (0, 0, <NULL>) [Success]
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Sending result [7][default]
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Sent result [7][default]
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [sbus_remove_watch] (8): 0x100b0d0/0xfbe4c0
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [sbus_remove_watch] (8): 0x100b0d0/0xff9f90
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 100AC00
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [sbus_dispatch] (3): Connection is not open for dispatching.
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [proxy_child_sig_handler] (7): Waiting for child [1687].
(Tue Mar 22 13:04:15 2011) [sssd[be[default]]] [proxy_child_sig_handler] (4): child [1687] was terminated by signal [9].
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F95F10
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for [3][1][name=puser1]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 0)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 1)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x100b170

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x100b220

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Destroying timer event 0x100b220 "ltdb_timeout"

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Ending timer event 0x100b170 "ltdb_callback"

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 2)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x10149c0

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1014ae0

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Destroying timer event 0x1014ae0 "ltdb_timeout"

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): tevent: Ending timer event 0x10149c0 "ltdb_callback"

(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): commit ldb transaction (nesting: 2)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): commit ldb transaction (nesting: 1)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [get_initgr_groups_process] (2): proxy -> initgroups_dyn failed (5)[Input/output error]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [ldb] (9): cancel ldb transaction (nesting: 0)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [acctinfo_callback] (4): Request processed. Returned 3,5,Internal Error (Memory buffer error)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F95F10
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [pamHandler]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [be_pam_handler] (4): Got request with the following data
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): domain: default
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): user: puser1
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): service: gnome-screensaver
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): tty: :0.0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): ruser: 
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): rhost: 
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): authtok type: 1
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): authtok size: 11
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok type: 0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok size: 0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): priv: 0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): cli_pid: 1673
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [proxy_child_send] (8): Queueing request [38]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [proxy_child_init_send] (7): Starting proxy child with args [/usr/libexec/sssd/proxy_child -d 9 --debug-to-files --domain default --id 38]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_server_init_new_connection] (5): Entering.
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_server_init_new_connection] (5): Adding connection 0x10161e0.
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_init_connection] (5): Adding connection 10161E0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_add_watch] (8): 0x1011810/0x100fa30 (26), -/W (disabled)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x1011810/0xff3340 (26), R/- (enabled)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_server_init_new_connection] (5): Got a connection
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [proxy_client_init] (4): Set-up proxy client ID timeout [0x1011a80]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 10161E0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x1011810/0xff3340 (26), R/- (disabled)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x1011810/0x100fa30 (26), -/W (enabled)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x1011810/0xff3340 (26), R/- (enabled)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_toggle_watch] (8): 0x1011810/0x100fa30 (26), -/W (disabled)
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 10161E0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [RegisterService]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [client_registration] (4): Cancel proxy client ID timeout [0x1011a80]
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [client_registration] (4): Proxy client [38] connected
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [proxy_pam_conv_send] (4): Sending request with the following data:
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): command: PAM_AUTHENTICATE
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): domain: default
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): user: puser1
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): service: gnome-screensaver
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): tty: :0.0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): ruser: 
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): rhost: 
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): authtok type: 1
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): authtok size: 11
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok type: 0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok size: 0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): priv: 0
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [pam_print_data] (4): cli_pid: 1673
(Tue Mar 22 13:04:22 2011) [sssd[be[default]]] [sbus_add_timeout] (8): 0xff21e0
(Tue Mar 22 13:04:24 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F92EF0
(Tue Mar 22 13:04:24 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:24 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_remove_timeout] (8): 0xff21e0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 10161E0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [proxy_pam_conv_reply] (8): Handling pam conversation reply
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [proxy_pam_conv_reply] (4): received: [0][default]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [proxy_child_destructor] (8): Removing proxy child id [38]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 0)
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1008450

(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1008570

(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [ldb] (9): tevent: Destroying timer event 0x1008570 "ltdb_timeout"

(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [ldb] (9): tevent: Ending timer event 0x1008450 "ltdb_callback"

(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [ldb] (9): commit ldb transaction (nesting: 0)
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Backend returned: (0, 0, <NULL>) [Success]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Sending result [0][default]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Sent result [0][default]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [proxy_child_sig_handler] (7): Waiting for child [1690].
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [proxy_child_sig_handler] (4): child [1690] was terminated by signal [9].
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_remove_watch] (8): 0x1011810/0xff3340
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_remove_watch] (8): 0x1011810/0x100fa30
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 10161E0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (3): Connection is not open for dispatching.
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F95F10
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [pamHandler]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler] (4): Got request with the following data
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): command: PAM_ACCT_MGMT
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): domain: default
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): user: puser1
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): service: gnome-screensaver
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): tty: :0.0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): ruser: 
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): rhost: 
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): authtok type: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): authtok size: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok type: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok size: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): priv: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): cli_pid: 1673
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_target_access_permit] (9): be_target_access_permit called, returning PAM_SUCCESS.
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Backend returned: (0, 0, <NULL>) [Success]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Sending result [0][default]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler_callback] (4): Sent result [0][default]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: F95F10
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching.
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [pamHandler]
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler] (4): Got request with the following data
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): command: PAM_SETCRED
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): domain: default
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): user: puser1
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): service: gnome-screensaver
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): tty: :0.0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): ruser: 
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): rhost: 
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): authtok type: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): authtok size: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok type: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): newauthtok size: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): priv: 0
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [pam_print_data] (4): cli_pid: 1673
(Tue Mar 22 13:04:25 2011) [sssd[be[default]]] [be_pam_handler] (4): Sending result [0][default]
Comment 7 Gowrishankar Rajaiyan 2011-03-22 07:40:21 UTC 
# rpm -qi sssd | head
Name        : sssd                         Relocations: (not relocatable)
Version     : 1.5.1                             Vendor: Red Hat, Inc.
Release     : 14.el6                        Build Date: Thu 10 Mar 2011 01:00:12 AM IST
Install Date: Tue 22 Mar 2011 11:38:48 AM IST      Build Host: x86-009.build.bos.redhat.com
Group       : Applications/System           Source RPM: sssd-1.5.1-14.el6.src.rpm
Size        : 3418526                          License: GPLv3+
Signature   : (none)
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
URL         : http://fedorahosted.org/sssd/
Summary     : System Security Services Daemon


Verified.
Comment 8 errata-xmlrpc 2011-05-19 11:41:51 UTC 
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2011-0560.html
Comment 9 errata-xmlrpc 2011-05-19 13:08:51 UTC 
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2011-0560.html