Bug 786468

Summary: Smart card password is requested twice during login.
Product: Red Hat Enterprise Linux 5 Reporter: Asha Akkiangady <aakkiang>
Component: gdmAssignee: Ray Strode [halfline] <rstrode>
Status: CLOSED WONTFIX QA Contact: Desktop QE <desktop-qa-list>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 5.8CC: aakkiang, ckannan, collura, jmagne, ovasik, rrelyea
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: coolkey-1.1.0-21.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-06-25 20:58:52 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Asha Akkiangady 2012-02-01 14:19:07 UTC 
Description of problem:
Smart card password is requested twice during login to graphical console.

Version-Release number of selected component (if applicable):
gdm-2.16.0-59.el5

How reproducible:


Steps to Reproduce:
This problem is not consistently reproducible.

1. RHEL 5.8 X86_64 desktop is configured with smart card support enabled.

Use smart card: ON

Enforce smart card: OFF

Log out behavior configured to: Ignore smart card removal

This user is not in the /etc/passwd file, authentication is
configured with userDatabase to LDAP server.

2. A smart card is enrolled for the user.
3. In graphical console to login,  "Please insert your smart card" is displayed.
4. Insert the smart card. "Smart card password" is requested. "Welcome user!" message is not displayed.

  
Actual results:
5. Enter correct or incorrect smart card password, this requests for smart card password again and "Welcome user!" message displayed. 

6. Enter correct smart card password, user is logged in.

Expected results:
Should not request smart card password twice during login.

Additional info:
/var/log/messages has:
Jan 31 16:09:33 dhcp231-57 pcscd: ifdhandler.c:924:IFDHPowerICC() lun: 0, action: PowerUp
Jan 31 16:09:34 dhcp231-57 pcscd: eventhandler.c:431:EHStatusHandlerThread() Card inserted into OmniKey CardMan 3121 00 00
Jan 31 16:09:34 dhcp231-57 pcscd: Card ATR: 3B 95 95 40 FF AE 01 03 00 00 
Jan 31 16:09:34 dhcp231-57 pcscd: prothandler.c:130:PHSetProtocol() Attempting PTS to T=0
Jan 31 16:09:34 dhcp231-57 pcscd: ifdhandler.c:488:IFDHSetProtocolParameters() lun: 0, protocol T=0
Jan 31 16:09:34 dhcp231-57 pcscd: ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
Jan 31 16:09:34 dhcp231-57 last message repeated 9 times
Jan 31 16:10:10 dhcp231-57 gdm[4364]: writing failed session attempt record
Jan 31 16:10:10 dhcp231-57 gdm[4364]: using username (unknown)
Jan 31 16:10:10 dhcp231-57 gdm[4364]: using id 
Jan 31 16:10:10 dhcp231-57 gdm[4364]: using line :0
Jan 31 16:10:10 dhcp231-57 gdm[4364]: using time 1328044210
Jan 31 16:10:10 dhcp231-57 gdm[4364]: using type USER_PROCESS
Jan 31 16:10:10 dhcp231-57 gdm[4364]: using pid 4364
Jan 31 16:10:10 dhcp231-57 gdm[4364]: writing failed session attempt record to /var/log/btmp
Jan 31 16:10:10 dhcp231-57 gdm[4364]: gdm_slave_wait_for_login: end verify for ''
Jan 31 16:10:10 dhcp231-57 gdm[4364]: canceling...
Jan 31 16:10:10 dhcp231-57 gdm[4364]: gdm_slave_wait_for_login: In loop
Jan 31 16:10:10 dhcp231-57 pcscd: ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
Jan 31 16:10:36 dhcp231-57 last message repeated 22 times
Jan 31 16:10:37 dhcp231-57 gdm[4364]: Sending QUERYLOGIN == <secret> for slave 4364
Jan 31 16:10:37 dhcp231-57 gdm[4321]: Handling message: 'QUERYLOGIN 4364 kdcuser'
Jan 31 16:10:37 dhcp231-57 gdm[4321]: Got QUERYLOGIN kdcuser
Jan 31 16:10:38 dhcp231-57 gdm[4364]: gdm_slave_wait_for_login: end verify for 'kdcuser'
Jan 31 16:10:38 dhcp231-57 gdm[4364]: gdm_slave_wait_for_login: got_login for 'kdcuser'
Jan 31 16:10:38 dhcp231-57 gdm[4364]: Sending LOGGED_IN == 1 for slave 4364
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling message: 'LOGGED_IN 4364 1'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Got logged in == TRUE
Jan 31 16:10:38 dhcp231-57 gdm[4364]: Sending LOGIN == <secret> for slave 4364
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling message: 'LOGIN 4364 kdcuser'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Got LOGIN == kdcuser
Jan 31 16:10:38 dhcp231-57 gdm[4364]: gdm_slave_session_start: Attempting session for user 'kdcuser'
Jan 31 16:10:38 dhcp231-57 gdm[4364]: Initial setting: session: 'default' language: '' 
Jan 31 16:10:38 dhcp231-57 gdm[4364]: gdm_slave_session_start: Authentication completed. Whacking greeter
Jan 31 16:10:38 dhcp231-57 gdm[4364]: slave_waitpid: waiting on 6377
Jan 31 16:10:38 dhcp231-57 gdm[4364]: slave_waitpid: done_waiting
Jan 31 16:10:38 dhcp231-57 gdm[4364]: Sending GREETPID == 0 for slave 4364
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling message: 'GREETPID 4364 0'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Got GREETPID == 0
Jan 31 16:10:38 dhcp231-57 gdm[4364]: get_local_auths: Setting up socket access
Jan 31 16:10:38 dhcp231-57 gdm[4364]: get_local_auths: Setting up network access
Jan 31 16:10:38 dhcp231-57 gdm[4364]: get_local_auths: Setting up access for :0 - 2 entries
Jan 31 16:10:38 dhcp231-57 gdm[4364]: gdm_auth_user_add: Adding cookie for 510
Jan 31 16:10:38 dhcp231-57 gdm[4364]: gdm_auth_user_add: Using /tmp/.gdmC86Z8V for cookies
Jan 31 16:10:38 dhcp231-57 gdm[4364]: gdm_auth_user_add: Done
Jan 31 16:10:38 dhcp231-57 gdm[4364]: Sending WRITE_X_SERVERS == 0 for slave 4364
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling message: 'WRITE_X_SERVERS 4364 0'
Jan 31 16:10:38 dhcp231-57 gdm[4364]: writing session record
Jan 31 16:10:38 dhcp231-57 gdm[4364]: using username kdcuser
Jan 31 16:10:38 dhcp231-57 gdm[4364]: using id 
Jan 31 16:10:38 dhcp231-57 gdm[4364]: using line :0
Jan 31 16:10:38 dhcp231-57 gdm[4364]: using time 1328044238
Jan 31 16:10:38 dhcp231-57 gdm[4364]: using type USER_PROCESS
Jan 31 16:10:38 dhcp231-57 gdm[4364]: using pid 6417
Jan 31 16:10:38 dhcp231-57 gdm[4364]: writing session record to /var/log/wtmp
Jan 31 16:10:38 dhcp231-57 gdm[4364]: Sending SESSPID == 6417 for slave 4364
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling message: 'SESSPID 4364 6417'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Got SESSPID == 6417
Jan 31 16:10:38 dhcp231-57 gdm[4364]: slave_waitpid: waiting on 6417
Jan 31 16:10:38 dhcp231-57 gdm[4321]: gdm_socket_handler: Accepting new connection fd 8
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling user message: 'VERSION'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling user message: 'GET_CONFIG daemon/PidFile :0'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling user message: 'CLOSE'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: gdm_socket_handler: Accepting new connection fd 8
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling user message: 'VERSION'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling user message: 'GET_CONFIG greeter/GraphicalThemedColor :0'
Jan 31 16:10:38 dhcp231-57 gdm[4321]: Handling user message: 'CLOSE'
Jan 31 16:10:38 dhcp231-57 gdm[6417]: Running /etc/X11/xinit/Xsession default  for kdcuser on :0
Jan 31 16:10:39 dhcp231-57 gconfd (kdcuser-6484): starting (version 2.14.0), pid 6484 user 'kdcuser'
Jan 31 16:10:39 dhcp231-57 gconfd (kdcuser-6484): Resolved address "xml:readonly:/etc/gconf/gconf.xml.mandatory" to a read-only configuration source at position 0
Jan 31 16:10:39 dhcp231-57 gconfd (kdcuser-6484): Resolved address "xml:readwrite:/home/kdcuser/.gconf" to a writable configuration source at position 1
Jan 31 16:10:39 dhcp231-57 gconfd (kdcuser-6484): Resolved address "xml:readonly:/etc/gconf/gconf.xml.defaults" to a read-only configuration source at position 2
Jan 31 16:10:41 dhcp231-57 gconfd (kdcuser-6484): Resolved address "xml:readwrite:/home/kdcuser/.gconf" to a writable configuration source at position 0
Jan 31 16:10:42 dhcp231-57 pcscd: ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
Jan 31 16:10:42 dhcp231-57 last message repeated 4 times
Jan 31 16:10:45 dhcp231-57 hcid[3871]: Default passkey agent (:1.83, /org/bluez/applet) registered
Jan 31 16:10:48 dhcp231-57 pcscd: ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
Comment 1 Ray Strode [halfline] 2012-02-02 18:28:08 UTC 
This is a bug in gdm's pam handling code.

Resets aren't processed by the slave until the next time the greeter writes at least one byte.  In most cases, this is right away because of the timing of things, but in some cases it does't happen until the user does something.

Can fix it, by changing the slave's greater data reading call to be cancellable.
Comment 2 RHEL Program Management 2014-03-07 12:51:50 UTC 
This bug/component is not included in scope for RHEL-5.11.0 which is the last RHEL5 minor release. This Bugzilla will soon be CLOSED as WONTFIX (at the end of RHEL5.11 development phase (Apr 22, 2014)). Please contact your account manager or support representative in case you need to escalate this bug.
Comment 3 RHEL Program Management 2014-03-10 19:39:27 UTC 
This request was evaluated by Red Hat Product Management for
inclusion in the current release of Red Hat Enterprise Linux.
Because the affected component is not scheduled to be updated
in the current release, Red Hat is unable to address this
request at this time.

Red Hat invites you to ask your support representative to
propose this request, if appropriate, in the next release of
Red Hat Enterprise Linux.
Comment 4 Asha Akkiangady 2014-03-10 20:36:59 UTC 
Okay to automatically close this bug.
Comment 5 Ondrej Vasik 2014-06-25 20:58:52 UTC 
Ok, closing WONTFIX for RHEL 5, thanks for reply.