Bug 1367919 – pam_pkcs11 unable to detect cards when opensc and coolkey modules co-exist

Bugzilla will be upgraded to version 5.0 on a still to be determined date in the near future. The original upgrade date has been delayed.

Bug 1367919 - pam_pkcs11 unable to detect cards when opensc and coolkey modules co-exist

Summary:	pam_pkcs11 unable to detect cards when opensc and coolkey modules co-exist

Status:	CLOSED WORKSFORME

Aliases:	None

Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	pam_pkcs11 (Show other bugs)
Sub Component:
Version:	7.3
Hardware:	Unspecified Unspecified

Priority	urgent Severity urgent
Target Milestone:	rc
Target Release:	7.4
Assigned To:	Bob Relyea
QA Contact:	Asha Akkiangady
Docs Contact:	Marc Muehlfeld

URL:
Whiteboard:
Keywords:

Depends On:	rhel7-opensc-with-cac
Blocks:
	Show dependency tree / graph

Reported:	2016-08-17 15:37 EDT by Roshni
Modified:	2017-03-13 18:48 EDT (History)
CC List:	14 users (show)

See Also:
Fixed In Version:
Doc Type:	Known Issue
Doc Text:	"pam_pkcs11" only supports one token The PKCS#11 modules in the _opensc_ and _coolkey_ packages provide support for various types of smart cards. However the "pam_pkcs11" module only supports one of them at a time. As a consequence, you cannot use PKCS#15 and CAC tokens using the same configuration. To work around the problem, install one of the following: * the _opensc_ package for PKCS#15 and PIV support * the _coolkey_ package for CAC, Coolkey, and PIV support
Story Points:	---
Clone Of:
Environment:
Last Closed:	2017-03-13 18:48:17 EDT
Type:	Bug
Regression:	---
Mount Type:	---
Documentation:	---
CRM:
Verified Versions:
Category:	---
oVirt Team:	---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---

Attachments	(Terms of Use)
sssd_nss log (168.03 KB, text/plain) 2016-08-18 09:17 EDT, Roshni	no flags	Details
sssd logs (36.51 KB, text/plain) 2016-08-18 11:09 EDT, Roshni	no flags	Details
Add an attachment (proposed patch, testcase, etc.)

Groups: None (edit)

Description Roshni 2016-08-17 15:37:44 EDT

Description of problem:
Unable to login using smartcards tha thave ipa user certificates

Version-Release number of selected component (if applicable):
sssd-1.14.0-18.el7.x86_64
ipa-client-4.4.0-7.el7.x86_64

How reproducible:
always

Steps to Reproduce:
1. Write IPA issued certificates onto a smartcard.
2. Trust the IPA CA under /etc/pki/nssdb
3. Add the folllowing line in sssd.conf

[pam]
pam_cert_auth = True

Actual results:
su using smartcard prompts for the user password

Expected results:
su using smartcard should prompt for the smartcard pin

Additional info:
Tried testing using CAC cards, su is prompting for pin and login is successful but gdm login fails when smartcard pin is provided. Noticed the following log messages

/var/log/secure

Aug 17 15:23:06 dhcp129-72 gdm-password]: pam_sss(gdm-password:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost= user=last.day.2001428082
Aug 17 15:23:06 dhcp129-72 gdm-password]: pam_sss(gdm-password:auth): received for user last.day.2001428082: 4 (System error)
Aug 17 15:23:06 dhcp129-72 gdm-password]: gkr-pam: no password is available for user
Aug 17 15:23:17 dhcp129-72 gdm-password]: gkr-pam: no password is available for user


/var/log/messages

[root@dhcp129-72 ~]# cat /var/log/messages | grep "Aug 17 15:23:*"
Aug 17 15:23:07 dhcp129-72 dbus-daemon: dbus[726]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service'
Aug 17 15:23:07 dhcp129-72 dbus[726]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service'
Aug 17 15:23:07 dhcp129-72 systemd: Starting Fingerprint Authentication Daemon...
Aug 17 15:23:07 dhcp129-72 dbus-daemon: dbus[726]: [system] Successfully activated service 'net.reactivated.Fprint'
Aug 17 15:23:07 dhcp129-72 dbus[726]: [system] Successfully activated service 'net.reactivated.Fprint'
Aug 17 15:23:07 dhcp129-72 systemd: Started Fingerprint Authentication Daemon.
Aug 17 15:23:07 dhcp129-72 fprintd: Launching FprintObject
Aug 17 15:23:07 dhcp129-72 fprintd: ** Message: D-Bus service launched with name: net.reactivated.Fprint
Aug 17 15:23:07 dhcp129-72 fprintd: ** Message: entering main loop
Aug 17 15:23:13 dhcp129-72 gdm: GdmCommon: process (pid:2837, command 'gdm-session-worker [pam/gdm-password]') isn't dying after 5 seconds, now ignoring it.
Aug 17 15:23:30 dhcp129-72 systemd: Created slice user-1000.slice.
Aug 17 15:23:30 dhcp129-72 systemd: Starting user-1000.slice.
Aug 17 15:23:30 dhcp129-72 systemd-logind: New session 1 of user rpattath.
Aug 17 15:23:30 dhcp129-72 systemd: Started Session 1 of user rpattath.
Aug 17 15:23:30 dhcp129-72 systemd: Starting Session 1 of user rpattath.
Aug 17 15:23:31 dhcp129-72 gnome-session: (gnome-settings-daemon:2492): GLib-GIO-WARNING **: Error releasing name org.gnome.SettingsDaemon: The connection is closed
Aug 17 15:23:31 dhcp129-72 gnome-session: (gnome-settings-daemon:2492): GLib-GIO-WARNING **: Invalid id 5 passed to g_bus_unown_name()
Aug 17 15:23:31 dhcp129-72 kernel: fuse init (API version 7.22)
Aug 17 15:23:31 dhcp129-72 systemd: Mounting FUSE Control File System...
Aug 17 15:23:31 dhcp129-72 systemd: Mounted FUSE Control File System.
Aug 17 15:23:31 dhcp129-72 spice-vdagent[3076]: Cannot access vdagent virtio channel /dev/virtio-ports/com.redhat.spice.0
Aug 17 15:23:31 dhcp129-72 gnome-session: gnome-session[2862]: WARNING: App 'spice-vdagent.desktop' exited with code 1
Aug 17 15:23:31 dhcp129-72 gnome-session[2862]: WARNING: App 'spice-vdagent.desktop' exited with code 1
Aug 17 15:23:31 dhcp129-72 gnome-session: GPG_AGENT_INFO=/run/user/1000/keyring/gpg:0:1
Aug 17 15:23:31 dhcp129-72 gnome-session: GPG_AGENT_INFO=/run/user/1000/keyring/gpg:0:1
Aug 17 15:23:31 dhcp129-72 gnome-session: GPG_AGENT_INFO=/run/user/1000/keyring/gpg:0:1
Aug 17 15:23:31 dhcp129-72 gnome-session: GPG_AGENT_INFO=/run/user/1000/keyring/gpg:0:1
Aug 17 15:23:31 dhcp129-72 gnome-session: SSH_AUTH_SOCK=/run/user/1000/keyring/ssh
Aug 17 15:23:31 dhcp129-72 rtkit-daemon[744]: Successfully made thread 3086 of process 3086 (/usr/bin/pulseaudio) owned by '1000' high priority at nice level -11.
Aug 17 15:23:31 dhcp129-72 rtkit-daemon[744]: Successfully made thread 3095 of process 3086 (/usr/bin/pulseaudio) owned by '1000' RT at priority 5.
Aug 17 15:23:31 dhcp129-72 rtkit-daemon[744]: Successfully made thread 3098 of process 3086 (/usr/bin/pulseaudio) owned by '1000' RT at priority 5.
Aug 17 15:23:31 dhcp129-72 dbus-daemon: dbus[726]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service'
Aug 17 15:23:31 dhcp129-72 dbus[726]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service'
Aug 17 15:23:32 dhcp129-72 dbus[726]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Aug 17 15:23:32 dhcp129-72 dbus-daemon: dbus[726]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Aug 17 15:23:32 dhcp129-72 systemd: Starting Hostname Service...
Aug 17 15:23:32 dhcp129-72 dbus-daemon: dbus[726]: [system] Successfully activated service 'org.freedesktop.hostname1'
Aug 17 15:23:32 dhcp129-72 dbus[726]: [system] Successfully activated service 'org.freedesktop.hostname1'
Aug 17 15:23:32 dhcp129-72 systemd: Started Hostname Service.
Aug 17 15:23:32 dhcp129-72 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/ui/extensionSystem.js 301]: octal literals and octal escape sequences are deprecated
Aug 17 15:23:32 dhcp129-72 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/ui/extensionSystem.js 301]: octal literals and octal escape sequences are deprecated
Aug 17 15:23:32 dhcp129-72 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/ui/extensionSystem.js 301]: octal literals and octal escape sequences are deprecated
Aug 17 15:23:32 dhcp129-72 gnome-session: Gjs-Message: JS WARNING: [resource:///org/gnome/shell/gdm/loginDialog.js 1017]: anonymous function does not always return a value
Aug 17 15:23:33 dhcp129-72 dbus-daemon: dbus[726]: [system] Activating via systemd: service name='org.freedesktop.GeoClue2' unit='geoclue.service'
Aug 17 15:23:33 dhcp129-72 dbus[726]: [system] Activating via systemd: service name='org.freedesktop.GeoClue2' unit='geoclue.service'
Aug 17 15:23:33 dhcp129-72 systemd: Starting Location Lookup Service...
Aug 17 15:23:33 dhcp129-72 dbus[726]: [system] Successfully activated service 'org.freedesktop.GeoClue2'
Aug 17 15:23:33 dhcp129-72 systemd: Started Location Lookup Service.
Aug 17 15:23:33 dhcp129-72 dbus-daemon: dbus[726]: [system] Successfully activated service 'org.freedesktop.GeoClue2'
Aug 17 15:23:33 dhcp129-72 dbus-daemon: dbus[726]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service'
Aug 17 15:23:33 dhcp129-72 dbus[726]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service'
Aug 17 15:23:33 dhcp129-72 systemd: Starting Locale Service...
Aug 17 15:23:33 dhcp129-72 dbus-daemon: dbus[726]: [system] Successfully activated service 'org.freedesktop.locale1'
Aug 17 15:23:33 dhcp129-72 dbus[726]: [system] Successfully activated service 'org.freedesktop.locale1'
Aug 17 15:23:33 dhcp129-72 systemd: Started Locale Service.
Aug 17 15:23:33 dhcp129-72 gnome-session: (gnome-settings-daemon:3078): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 17 15:23:33 dhcp129-72 gnome-session: Gjs-Message: JS WARNING: [/usr/share/gnome-shell/extensions/launch-new-instance@gnome-shell-extensions.gcampax.github.com/extension.js 9]: assignment to undeclared variable _activateOriginal
Aug 17 15:23:34 dhcp129-72 gnome-session: vmware-user: could not open /proc/fs/vmblock/dev
Aug 17 15:23:34 dhcp129-72 gnome-session: Entering running state
Aug 17 15:23:34 dhcp129-72 gnome-session: (uint32 1,)
Aug 17 15:23:34 dhcp129-72 gnome-session: Failed to play sound: File or data not found
Aug 17 15:23:34 dhcp129-72 gnome-session: GDBus.Error:org.gtk.GDBus.UnmappedGError.Quark._imsettings_2derror_2dquark.Code5: Current desktop isn't targeted by IMSettings.
Aug 17 15:23:35 dhcp129-72 gnome-shell: GNOME Shell started at Wed Aug 17 2016 15:23:33 GMT-0400 (EDT)
Aug 17 15:23:37 dhcp129-72 kernel: intel_powerclamp: No package C-state available
Aug 17 15:23:37 dhcp129-72 kernel: RRIP_1991A
Aug 17 15:23:37 dhcp129-72 udisksd[2705]: Mounted /dev/sr0 at /run/media/rpattath/RHEL-7.2 Client.x86_64 on behalf of uid 1000
Aug 17 15:23:37 dhcp129-72 gnome-session: (gnome-shell:3113): mutter-WARNING **: STACK_OP_ADD: window 0x2200001 already in stack
Aug 17 15:23:37 dhcp129-72 gnome-session: (gnome-shell:3113): mutter-WARNING **: STACK_OP_ADD: window 0x2200001 already in stack
Aug 17 15:23:38 dhcp129-72 fprintd: ** Message: No devices in use, exit
Aug 17 15:23:40 dhcp129-72 gnome-session: (process:3505): GLib-CRITICAL **: g_slice_set_config: assertion 'sys_page_size == 0' failed
Aug 17 15:23:40 dhcp129-72 dbus-daemon: dbus[726]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
Aug 17 15:23:40 dhcp129-72 dbus[726]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
Aug 17 15:23:40 dhcp129-72 dbus-daemon: dbus[726]: [system] Successfully activated service 'org.freedesktop.problems'
Aug 17 15:23:40 dhcp129-72 dbus[726]: [system] Successfully activated service 'org.freedesktop.problems'
Aug 17 15:23:45 dhcp129-72 dbus-daemon: dbus[726]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service'
Aug 17 15:23:45 dhcp129-72 dbus[726]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service'
Aug 17 15:23:45 dhcp129-72 systemd: Starting Fingerprint Authentication Daemon...
Aug 17 15:23:45 dhcp129-72 dbus-daemon: dbus[726]: [system] Successfully activated service 'net.reactivated.Fprint'
Aug 17 15:23:45 dhcp129-72 dbus[726]: [system] Successfully activated service 'net.reactivated.Fprint'
Aug 17 15:23:45 dhcp129-72 systemd: Started Fingerprint Authentication Daemon.
Aug 17 15:23:45 dhcp129-72 fprintd: Launching FprintObject
Aug 17 15:23:45 dhcp129-72 fprintd: ** Message: D-Bus service launched with name: net.reactivated.Fprint
Aug 17 15:23:45 dhcp129-72 fprintd: ** Message: entering main loop
Aug 17 15:23:46 dhcp129-72 su: (to root) rpattath on pts/0
Aug 17 15:23:51 dhcp129-72 systemd-logind: Removed session c1.
Aug 17 15:23:51 dhcp129-72 systemd: Removed slice user-42.slice.
Aug 17 15:23:51 dhcp129-72 systemd: Stopping user-42.slice.
Aug 17 15:23:56 dhcp129-72 pulseaudio[3086]: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
Aug 17 15:23:56 dhcp129-72 dbus[726]: [system] Failed to activate service 'org.bluez': timed out
Aug 17 15:23:56 dhcp129-72 dbus-daemon: dbus[726]: [system] Failed to activate service 'org.bluez': timed out
Aug 17 15:23:58 dhcp129-72 chronyd[774]: Source 128.199.123.83 replaced with 38.229.71.1

Comment 3 Jakub Hrozek 2016-08-18 04:12:26 EDT

Can you also provide SSSD config and logs, please?

Comment 4 Roshni 2016-08-18 09:16:50 EDT

Jakub,

I am not very sure if this is an sssd bug because I am seeing different behaviour when using different card. The changes I made to the default sssd.conf is in the bug description. I am not sure which sssd log you want to have a look at, the following is what I am seeing

[root@dhcp129-72 sssd]# cat krb5_child.log
[root@dhcp129-72 sssd]# cat ldap_child.log
[root@dhcp129-72 sssd]# cat p11_child.log
[root@dhcp129-72 sssd]# cat selinux_child.log
[root@dhcp129-72 sssd]# cat sssd.log
[root@dhcp129-72 sssd]# cat sssd_pac.log
[root@dhcp129-72 sssd]# cat sssd_pam.log
[root@dhcp129-72 sssd]# cat sssd_ssh.log
[root@dhcp129-72 sssd]# cat sssd_sudo.log
[root@dhcp129-72 sssd]# cat sssd_testrelm.test.log
(Wed Aug 17 14:08:33 2016) [sssd[be[testrelm.test]]] [id_callback] (0x0010): The Monitor returned an error [org.freedesktop.DBus.Error.NoReply]

I am attching the sssd_nss.log to the bug.

One more thing I noticed is that, on RHEL 7.2 the IPA CA certificate was imported under /etc/pki/nssdb after ipa-client-install was done but with RHEL 7.3 latest nightly compose build I had to manually import it under /etc/pki/nssdb from /etc/ipa/nssdb.

Comment 5 Roshni 2016-08-18 09:17 EDT

Created attachment 1191868 [details]
sssd_nss log

Comment 6 Roshni 2016-08-18 11:09 EDT

Created attachment 1191904 [details]
sssd logs

These are the logs after setting debug_level = 10 in sssd.conf.

I also see the following:

[root@dhcp129-72 nssdb]# certutil -L -d /etc/pki/nssdb/ -h all

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

Enter Password or Pin for "OpenSC Card":
dod-ca-root                                                  CT,C,C
dod-ca-email-31                                              CT,C,C
TESTRELM.TEST IPA CA                                         CT,C,C
dod-ca-31                                                    CT,C,C
OpenSC Card:Certificate                                      ,,


I do not see the username with the opensc certificate, I verified ipa user and smartcard has the same certificate.

Comment 7 Roshni 2016-08-22 15:16:10 EDT

Sumit,

There are issues when coolkey and opensc co-exist. After opensc module was added using modutil, login using opensc smartcard was successful but CAC card login was failing. I had to remove opensc package for the CAC card login using su to work. Still seeing issues with gdm login using CAC cards (no prompt for pin)

Comment 14 Bob Relyea 2017-03-13 18:48:17 EDT

OK, I've look into this and there is already support for multiple modules in pam_pkcs11. They way it's configured is change the use_pkcs11_module line to:

      use_pkcs11_module = nss;

Then add a module:

pkcs11_module nss {
                module = "any module";
                description = "Any NSS Ssmartcard in /etc/pki/nssdb";
                slot_num = 0;
                nss_dir = dbm:/etc/pki/nssdb;
                cert_policy = ca, signature;
        }
}

Load both tokens in /etc/pki/nssdb and pam_pkcs11 should pick the correct module.

Caveats:
1. Currently I have no tokens that are only supported by one of the modules (all my tokens are supported by both opensc and coolkey). I was able to verify that this configuration worked with both modules loaded, but I don't know if both are working properly.certutil -L -h all -d /etc/pki/nssdb will prompt for both modules and list both sets of cert under both names properly

2. When trying to turn off some of the builtin access for opensc, I found opensc would calls applications to hang if I try to use on of the now unrecognized cards (like certutil or modutil even).

3. This functionality for coolkey and opensc are less important since now they support mostly the same cards (with opensc providing better support for pkcs15 cards).

bob

Note You need to log in before you can comment on or make changes to this bug.