Bug 1377322

Summary: ipa override user id gets truncated
Product: Red Hat Enterprise Linux 7 Reporter: Roshni <rpattath>
Component: sssdAssignee: SSSD Maintainers <sssd-maint>
Status: CLOSED DUPLICATE QA Contact: Steeve Goveas <sgoveas>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.3CC: abokovoy, agk, bmarzins, grajaiya, heinzm, jhrozek, lslebodn, mbabinsk, mkosek, mmuehlfe, msnitzer, mzidek, pbrezina, prajnoha, pvoborni, rcritten, rpattath, sbose, spoore
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
undefined
 Story Points: ---
Clone Of: Environment:
Last Closed: 2016-10-28 16:42:49 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Roshni 2016-09-19 12:37:57 UTC 
Description of problem:
ipa override user id gets truncated

Version-Release number of selected component (if applicable):
ipa-server-4.4.0-10.el7.x86_64

How reproducible:
always

Steps to Reproduce:
ipa idoverrideuser-add "Default Trust View"
Anchor to override: troy.jones.1402301836

Actual results:
[root@auto-hv-02-guest07 ~]# ipa idoverrideuser-show "Default Trust View"
Anchor to override: troy.jones.140230183
  Anchor to override: troy.jones.140230183
 

Expected results:
override user id should be troy.jones.1402301836

Additional info:
When trying to login as the Ad user using smartcard, gdm login accepts only the truncated user id whereas su and ssh accepts the full userid.
Comment 2 Martin Babinsky 2016-09-19 15:26:36 UTC 
Can I see the relevant entries in /var/log/httpd/error_log?
Comment 3 Martin Babinsky 2016-09-20 08:18:59 UTC 
I was able to reproduce this and I am inclined to think that this is an expected behavior:

In order to resolve the AD user to SID, both IPA and SSSD lookup this name in the 'sAMAccountName' (https://msdn.microsoft.com/en-us/library/cc220838.aspx) attribute on AD domain controller.

This attribute can be at most 20 characters long, however, and AD automatically truncates the supplied logon name if it does not fit this limit (you can check that on your testing DC), that's why the search for the full user name fails but succeeds for the truncated name.

Alexander, does it make sense to make FreeIPA and SSSD to search also for 'userPrincipalName' (https://msdn.microsoft.com/en-us/library/cc220979.aspx) attribute so that 'long' usernames are correctly resolved?

BTW I have also tested this on RHEL 7.2 and it works the same there so it is not a regression.
Comment 4 Alexander Bokovoy 2016-09-20 08:23:49 UTC 
SSSD looks up both sAMAccountName and userPrincipalName -- if the latter is set and UPNs are enabled. RHEL 7.2 did not have UPN support enabled before.
Comment 5 Scott Poore 2016-09-23 19:33:06 UTC 
So if SSSD is looking up the user like that, why is GDM the only client that seems to be forcing the use of sAMAccountName.  Shouldn't GDM instead use SSSD to translate the name to the canonical name that ssh/su seem to use?

What am I missing here?  Is this maybe a GDM bug?
Comment 6 Alexander Bokovoy 2016-09-23 20:09:40 UTC 
Scott, can you provide me a debug output from gdm run?

add to /etc/locale.conf

G_MESSAGES_PREFIXED=all
G_MESSAGES_DEBUG=all
G_DEBUG=all

and reboot the machine. /etc/locale.conf is sourced by GDM systemd service file so it is an easiest way to get Glib debugging settings into GDM environment.
See https://developer.gnome.org/glib/stable/glib-running.html for more details on debugging Glib-based apps.
Comment 7 Roshni 2016-09-27 22:10:59 UTC 
The following is what I see in /var/log/messages after making config changes mentioned on cooment 6. Please let me know if you need any other log info


Sep 27 18:08:15 dhcp129-34 dbus-daemon: dbus[863]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service'
Sep 27 18:08:15 dhcp129-34 dbus[863]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service'
Sep 27 18:08:15 dhcp129-34 systemd: Starting Fingerprint Authentication Daemon...
Sep 27 18:08:15 dhcp129-34 dbus[863]: [system] Successfully activated service 'net.reactivated.Fprint'
Sep 27 18:08:15 dhcp129-34 dbus-daemon: dbus[863]: [system] Successfully activated service 'net.reactivated.Fprint'
Sep 27 18:08:15 dhcp129-34 fprintd: Launching FprintObject
Sep 27 18:08:15 dhcp129-34 fprintd: ** Message: D-Bus service launched with name: net.reactivated.Fprint
Sep 27 18:08:15 dhcp129-34 fprintd: ** Message: entering main loop
Sep 27 18:08:15 dhcp129-34 systemd: Started Fingerprint Authentication Daemon.
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:15 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:16 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:16 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:16 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:16 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:16 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?





Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:39 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:46 dhcp129-34 fprintd: ** Message: No devices in use, exit
Sep 27 18:08:48 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:48 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:48 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:48 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:48 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:48 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:48 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:49 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:51 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:51 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:51 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:51 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:51 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:51 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:52 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:52 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:52 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:52 dhcp129-34 systemd: Created slice user-891402706.slice.
Sep 27 18:08:52 dhcp129-34 systemd: Starting user-891402706.slice.
Sep 27 18:08:52 dhcp129-34 systemd-logind: New session 8 of user troy.jones.140230183.
Sep 27 18:08:52 dhcp129-34 systemd: Started Session 8 of user troy.jones.140230183.
Sep 27 18:08:52 dhcp129-34 systemd: Starting Session 8 of user troy.jones.140230183.
Sep 27 18:08:53 dhcp129-34 gnome-session: (gnome-settings-daemon:4815): GLib-GIO-WARNING **: Error releasing name org.gnome.SettingsDaemon: The connection is closed
Sep 27 18:08:53 dhcp129-34 gnome-session: (gnome-settings-daemon:4815): GLib-GIO-WARNING **: Invalid id 5 passed to g_bus_unown_name()
Sep 27 18:08:54 dhcp129-34 spice-vdagent[5353]: Cannot access vdagent virtio channel /dev/virtio-ports/com.redhat.spice.0
Sep 27 18:08:54 dhcp129-34 gnome-session: GPG_AGENT_INFO=/run/user/891402706/keyring/gpg:0:1
Sep 27 18:08:54 dhcp129-34 gnome-session: gnome-session[5145]: WARNING: App 'spice-vdagent.desktop' exited with code 1
Sep 27 18:08:54 dhcp129-34 gnome-session[5145]: WARNING: App 'spice-vdagent.desktop' exited with code 1
Sep 27 18:08:54 dhcp129-34 gnome-session: GPG_AGENT_INFO=/run/user/891402706/keyring/gpg:0:1
Sep 27 18:08:54 dhcp129-34 gnome-session: GPG_AGENT_INFO=/run/user/891402706/keyring/gpg:0:1
Sep 27 18:08:54 dhcp129-34 gnome-session: GPG_AGENT_INFO=/run/user/891402706/keyring/gpg:0:1
Sep 27 18:08:54 dhcp129-34 gnome-session: SSH_AUTH_SOCK=/run/user/891402706/keyring/ssh
Sep 27 18:08:54 dhcp129-34 rtkit-daemon[892]: Successfully made thread 5367 of process 5367 (/usr/bin/pulseaudio) owned by '891402706' high priority at nice level -11.
Sep 27 18:08:54 dhcp129-34 rtkit-daemon[892]: Successfully made thread 5372 of process 5367 (/usr/bin/pulseaudio) owned by '891402706' RT at priority 5.
Sep 27 18:08:54 dhcp129-34 dbus-daemon: dbus[863]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Sep 27 18:08:54 dhcp129-34 dbus[863]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Sep 27 18:08:54 dhcp129-34 systemd: Starting Hostname Service...
Sep 27 18:08:54 dhcp129-34 dbus-daemon: dbus[863]: [system] Successfully activated service 'org.freedesktop.hostname1'
Sep 27 18:08:54 dhcp129-34 dbus[863]: [system] Successfully activated service 'org.freedesktop.hostname1'
Sep 27 18:08:54 dhcp129-34 systemd: Started Hostname Service.
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 rtkit-daemon[892]: Successfully made thread 5385 of process 5367 (/usr/bin/pulseaudio) owned by '891402706' RT at priority 5.
Sep 27 18:08:54 dhcp129-34 rtkit-daemon[892]: Successfully made thread 5413 of process 5367 (/usr/bin/pulseaudio) owned by '891402706' RT at priority 5.
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 bluetoothd[900]: Endpoint registered: sender=:1.172 path=/MediaEndpoint/A2DPSource
Sep 27 18:08:54 dhcp129-34 bluetoothd[900]: Endpoint registered: sender=:1.172 path=/MediaEndpoint/A2DPSink
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/ui/extensionSystem.js 301]: octal literals and octal escape sequences are deprecated
Sep 27 18:08:54 dhcp129-34 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/ui/extensionSystem.js 301]: octal literals and octal escape sequences are deprecated
Sep 27 18:08:54 dhcp129-34 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/ui/extensionSystem.js 301]: octal literals and octal escape sequences are deprecated
Sep 27 18:08:54 dhcp129-34 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/gdm/loginDialog.js 1017]: anonymous function does not always return a value
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:54 dhcp129-34 dbus-daemon: dbus[863]: [system] Activating via systemd: service name='org.freedesktop.GeoClue2' unit='geoclue.service'
Sep 27 18:08:54 dhcp129-34 dbus[863]: [system] Activating via systemd: service name='org.freedesktop.GeoClue2' unit='geoclue.service'
Sep 27 18:08:54 dhcp129-34 systemd: Starting Location Lookup Service...
Sep 27 18:08:54 dhcp129-34 dbus-daemon: dbus[863]: [system] Successfully activated service 'org.freedesktop.GeoClue2'
Sep 27 18:08:54 dhcp129-34 dbus[863]: [system] Successfully activated service 'org.freedesktop.GeoClue2'
Sep 27 18:08:54 dhcp129-34 systemd: Started Location Lookup Service.
Sep 27 18:08:54 dhcp129-34 dbus[863]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service'
Sep 27 18:08:54 dhcp129-34 dbus-daemon: dbus[863]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service'
Sep 27 18:08:54 dhcp129-34 systemd: Starting Locale Service...
Sep 27 18:08:54 dhcp129-34 dbus-daemon: dbus[863]: [system] Successfully activated service 'org.freedesktop.locale1'
Sep 27 18:08:54 dhcp129-34 dbus[863]: [system] Successfully activated service 'org.freedesktop.locale1'
Sep 27 18:08:54 dhcp129-34 systemd: Started Locale Service.
Sep 27 18:08:54 dhcp129-34 gnome-session: (gnome-settings-daemon:5356): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Sep 27 18:08:55 dhcp129-34 gnome-session: vmware-user: could not open /proc/fs/vmblock/dev
Sep 27 18:08:55 dhcp129-34 gnome-session: (uint32 1,)
Sep 27 18:08:55 dhcp129-34 gnome-session: Entering running state
Sep 27 18:08:55 dhcp129-34 gnome-session: Gjs-Message: JS WARNING: [/usr/share/gnome-shell/extensions/launch-new-instance.github.com/extension.js 9]: assignment to undeclared variable _activateOriginal
Sep 27 18:08:55 dhcp129-34 gnome-session: Failed to play sound: File or data not found
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 gnome-keyring-daemon[5689]: another secret service is running
Sep 27 18:08:55 dhcp129-34 gnome-session: GDBus.Error:org.gtk.GDBus.UnmappedGError.Quark._imsettings_2derror_2dquark.Code5: Current desktop isn't targeted by IMSettings.
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 gnome-session: (gnome-shell:5419): mutter-WARNING **: STACK_OP_ADD: window 0x1e00001 already in stack
Sep 27 18:08:55 dhcp129-34 gnome-session: (gnome-shell:5419): mutter-WARNING **: STACK_OP_ADD: window 0x1e00001 already in stack
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:55 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:56 dhcp129-34 gnome-shell: GNOME Shell started at Tue Sep 27 2016 18:08:54 GMT-0400 (EDT)
Sep 27 18:08:58 dhcp129-34 gnome-session: (process:5822): GLib-CRITICAL **: g_slice_set_config: assertion 'sys_page_size == 0' failed
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:08:59 dhcp129-34 kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 4 with no TDs queued?
Sep 27 18:09:13 dhcp129-34 systemd-logind: Removed session c2.
Sep 27 18:09:13 dhcp129-34 systemd: Removed slice user-42.slice.
Sep 27 18:09:13 dhcp129-34 systemd: Stopping user-42.slice.
Comment 8 Alexander Bokovoy 2016-09-28 04:47:34 UTC 
Thanks for the logs. They don't show any problem with gdm itself (in fact, you haven't provided GDM part of the logs at all). GDM launches user session properly. However, we do see crash of the gnome-session:

Sep 27 18:08:56 dhcp129-34 gnome-shell: GNOME Shell started at Tue Sep 27 2016 18:08:54 GMT-0400 (EDT)
Sep 27 18:08:58 dhcp129-34 gnome-session: (process:5822): GLib-CRITICAL **: g_slice_set_config: assertion 'sys_page_size == 0' failed

perhaps, there is a memory issue with the VM?
Comment 9 Roshni 2016-09-28 13:33:06 UTC 
(In reply to Alexander Bokovoy from comment #8)
> Thanks for the logs. They don't show any problem with gdm itself (in fact,
> you haven't provided GDM part of the logs at all). GDM launches user session
> properly. However, we do see crash of the gnome-session:
These were the messages after I tailed on /var/log/messages when I was reproducing the issue. Let me know if you need any other information from any other logs.
> 
> Sep 27 18:08:56 dhcp129-34 gnome-shell: GNOME Shell started at Tue Sep 27
> 2016 18:08:54 GMT-0400 (EDT)
> Sep 27 18:08:58 dhcp129-34 gnome-session: (process:5822): GLib-CRITICAL **:
> g_slice_set_config: assertion 'sys_page_size == 0' failed
> 
> perhaps, there is a memory issue with the VM?
Comment 10 Alexander Bokovoy 2016-09-28 13:39:31 UTC 
As I said, I don't believe there is any problem with smartcard logon in GDM. Your logs confirm this. Why GNOME session is crashing, I don't know but it is definitely is irrelevant to the logon itself.

I would consider this whole bug as not a bug.
Comment 11 Roshni 2016-09-28 13:54:08 UTC 
I was wondering why gdm accepts the truncated userid troy.jones.140230183 of the ipaoverride user but su accepts the full userid troy.jones.1402301836 when 

root@auto-hv-02-guest07 ~]# ipa idoverrideuser-show "Default Trust View"
Anchor to override: troy.jones.140230183
  Anchor to override: troy.jones.140230183
Comment 12 Alexander Bokovoy 2016-09-28 14:01:32 UTC 
There is no 'truncated id'. There is a canonical ID and other associated identities. SSSD is responsible in making sure to accept all forms of identities that are valid and returns canonical form when resolving UID.
Comment 13 Scott Poore 2016-09-28 16:21:34 UTC 
Alexander,

I must be missing something.  So does GDM not use SSSD to lookup the name the same way su/ssh does?

Thanks,
Scott
Comment 14 Alexander Bokovoy 2016-09-28 16:57:18 UTC 
Scott, as I said, there are no issues with GDM itself -- it accepted the name and logged user in properly because we see logs of GNOME session which only can happen after GDM successfully logs the user in.

GDM uses PAM and we see it perfectly accepting canonical user name SSSD returned to it:

Sep 27 18:08:52 dhcp129-34 systemd: Created slice user-891402706.slice.
Sep 27 18:08:52 dhcp129-34 systemd: Starting user-891402706.slice.
Sep 27 18:08:52 dhcp129-34 systemd-logind: New session 8 of user troy.jones.140230183.
Sep 27 18:08:52 dhcp129-34 systemd: Started Session 8 of user troy.jones.140230183.
Sep 27 18:08:52 dhcp129-34 systemd: Starting Session 8 of user troy.jones.140230183.

so there is no problem at all.

The session then fails -- for whatever reason, gnome-session app has failed to set up own configuration:

Sep 27 18:08:58 dhcp129-34 gnome-session: (process:5822): GLib-CRITICAL **: g_slice_set_config: assertion 'sys_page_size == 0' failed

but at this point GDM is all done already.

gnome-session error, I suspect, is due to VM having some misconfiguration or lack of memory or something. It has nothing to do with smartcard logon.
Comment 15 Scott Poore 2016-09-28 20:41:22 UTC 
Alexander,

Could we possibly have PAM configured wrong for GDM then?  If it's working, why would GDM be prompting for a password instead of the certificate pin?

I think Roshni might have more info to add from a log perspective.

Thanks,
Scott
Comment 16 Roshni 2016-09-28 20:44:25 UTC 
I see the following message in p11_child log of sssd during su with the longer userid troy.jones.1402301836 which prompted for pin

(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x0400): p11_child started.
(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x2000): Running in [pre-auth] mode.
(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x2000): Running with real IDs [0][0].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Default Module List:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): common name: [NSS Internal PKCS #11 Module].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): common name: [CoolKey PKCS #11 Module].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): dll name: [libcoolkeypk11.so].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Dead Module List:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): DB Module List:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): common name: [NSS Internal Module].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Description [NSS User Private Key and Certificate Services                   Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Description [NSS Internal Cryptographic Services                             Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Description [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405) Unknown                         ] Manufacturer [Unknown                         ] flags [7].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Found [TROY.JONES.1402301836] in slot [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405)][1] of module [2].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Token is NOT friendly.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Trying to switch to friendly to read certificate.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Login required.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x0020): Login required but no pin available, continue.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Encryption Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Filtered certificates:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:40 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:41 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): More than one certificate found, using just the first one.
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x0400): p11_child started.
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x2000): Running in [auth] mode.
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x2000): Running with real IDs [0][0].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Default Module List:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): common name: [NSS Internal PKCS #11 Module].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): common name: [CoolKey PKCS #11 Module].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): dll name: [libcoolkeypk11.so].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Dead Module List:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): DB Module List:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): common name: [NSS Internal Module].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Description [NSS User Private Key and Certificate Services                   Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Description [NSS Internal Cryptographic Services                             Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Description [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405) Unknown                         ] Manufacturer [Unknown                         ] flags [7].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Found [TROY.JONES.1402301836] in slot [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405)][1] of module [2].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Token is NOT friendly.
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Login required.
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Encryption Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Filtered certificates:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:54 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:55 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): More than one certificate found, using just the first one.
(Wed Sep 28 16:29:56 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Certificate verified and validated.

The following for gdm login for the same userid when it prompted for password

(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x0400): p11_child started.
(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x2000): Running in [pre-auth] mode.
(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Wed Sep 28 16:29:38 2016) [[sssd[p11_child[24580]]]] [main] (0x2000): Running with real IDs [0][0].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Default Module List:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): common name: [NSS Internal PKCS #11 Module].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): common name: [CoolKey PKCS #11 Module].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): dll name: [libcoolkeypk11.so].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Dead Module List:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): DB Module List:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): common name: [NSS Internal Module].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Description [NSS User Private Key and Certificate Services                   Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Description [NSS Internal Cryptographic Services                             Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Description [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405) Unknown                         ] Manufacturer [Unknown                         ] flags [7].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Found [TROY.JONES.1402301836] in slot [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405)][1] of module [2].
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Token is NOT friendly.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Trying to switch to friendly to read certificate.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Login required.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x0020): Login required but no pin available, continue.
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Encryption Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): Filtered certificates:
(Wed Sep 28 16:29:39 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:40 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:41 2016) [[sssd[p11_child[24580]]]] [do_work] (0x4000): More than one certificate found, using just the first one.
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x0400): p11_child started.
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x2000): Running in [auth] mode.
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Wed Sep 28 16:29:52 2016) [[sssd[p11_child[24588]]]] [main] (0x2000): Running with real IDs [0][0].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Default Module List:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): common name: [NSS Internal PKCS #11 Module].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): common name: [CoolKey PKCS #11 Module].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): dll name: [libcoolkeypk11.so].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Dead Module List:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): DB Module List:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): common name: [NSS Internal Module].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): dll name: [(null)].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Description [NSS User Private Key and Certificate Services                   Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Description [NSS Internal Cryptographic Services                             Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Description [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405) Unknown                         ] Manufacturer [Unknown                         ] flags [7].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Found [TROY.JONES.1402301836] in slot [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405)][1] of module [2].
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Token is NOT friendly.
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Login required.
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Encryption Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Filtered certificates:
(Wed Sep 28 16:29:53 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:54 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
(Wed Sep 28 16:29:55 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): More than one certificate found, using just the first one.
(Wed Sep 28 16:29:56 2016) [[sssd[p11_child[24588]]]] [do_work] (0x4000): Certificate verified and validated.
Comment 17 Roshni 2016-09-29 15:42:57 UTC 
The p11_child log messages during gdm login (when using longer userid and prompted for password) is as below (the ones in the above comment are incorrect)

    (Wed Sep 28 16:30:43 2016) [[sssd[p11_child[25022]]]] [main] (0x0400): p11_child started.
    (Wed Sep 28 16:30:43 2016) [[sssd[p11_child[25022]]]] [main] (0x2000): Running in [pre-auth] mode.
    (Wed Sep 28 16:30:43 2016) [[sssd[p11_child[25022]]]] [main] (0x2000): Running with effective IDs: [0][0].
    (Wed Sep 28 16:30:43 2016) [[sssd[p11_child[25022]]]] [main] (0x2000): Running with real IDs [0][0].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Default Module List:
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): common name: [NSS Internal PKCS #11 Module].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): dll name: [(null)].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): common name: [CoolKey PKCS #11 Module].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): dll name: [libcoolkeypk11.so].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Dead Module List:
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): DB Module List:
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): common name: [NSS Internal Module].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): dll name: [(null)].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Description [NSS User Private Key and Certificate Services                   Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Description [NSS Internal Cryptographic Services                             Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Description [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405) Unknown                         ] Manufacturer [Unknown                         ] flags [7].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Found [TROY.JONES.1402301836] in slot [SCM Microsystems Inc. SCR 331 [CCID Interface] (21120612212405)][1] of module [2].
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Token is NOT friendly.
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Trying to switch to friendly to read certificate.
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Login required.
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x0020): Login required but no pin available, continue.
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Encryption Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): Filtered certificates:
    (Wed Sep 28 16:30:44 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC ID Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
    (Wed Sep 28 16:30:45 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): found cert[TROY.JONES.1402301836:CAC Email Signature Certificate][CN=TROY.JONES.1402301836,OU=NOAA,OU=PKI,OU=DoD,O=U.S. Government,C=US]
    (Wed Sep 28 16:30:46 2016) [[sssd[p11_child[25022]]]] [do_work] (0x4000): More than one certificate found, using just the first one.
Comment 18 Scott Poore 2016-10-10 15:32:41 UTC 
Alexander,

From Roshni's update in comment #17, is there a way to determine why she's not seeing the "Certificate verified and validated" message when using troy.jones.140230183?

I still don't understand here why GDM is working if it's prompting for a password there.  Shouldn't it be prompting for the certificate pin?

Thanks,
Scott
Comment 19 Alexander Bokovoy 2016-10-11 07:09:54 UTC 
Scott,

I talked with Sumit and he promised to look into the environment that Roshni has. I'm sorry but from the logs Roshni provided it is not visible if there is any issue at all.