Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1718193

Summary: p11_child should have an option to skip C_WaitForSlotEvent if the PKCS#11 module does not implement it properly
Product: Red Hat Enterprise Linux 8 Reporter: adam winberg <adam.winberg>
Component: sssdAssignee: Sumit Bose <sbose>
Status: CLOSED ERRATA QA Contact: sssd-qe <sssd-qe>
Severity: high Docs Contact:
Priority: high    
Version: 8.0CC: aheverle, amitkuma, atikhono, dchen, grajaiya, jhrozek, lslebodn, msauton, mzidek, pbrezina, sbose, sgoveas, spoore, spurrier, toneata, tscherf
Target Milestone: rcKeywords: ZStream
Target Release: 8.0Flags: jhrozek: mirror+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: sync-to-jira
Fixed In Version: sssd-2.2.3-17.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1816591 (view as bug list) Environment:
Last Closed: 2020-04-28 16:56:02 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:
Embargoed:
Bug Depends On:    
Bug Blocks: 1816591    
Attachments:
Description Flags
test build
none
2nd test build none

Description adam winberg 2019-06-07 08:30:48 UTC 
Description of problem:
With gdm and sssd configured to require smartcard for login, the GDM login screen does not seem to wait for smart card insertion properly. Instead it switches between messages:
"Please enter smart card"
and 
"Sorry, that didn't work. Please try again"

After smartcard insertion it works as expected, i.e. requesting and waiting for pin input. 

Dconf:
[org/gnome/login-screen]
enable-smartcard-authentication=true
enable-password-authentication=false
enable-fingerprint-authentication=false

/etc/pam.d/smartcard-auth
auth        required                                     pam_env.so
auth        sufficient                                   pam_sss.so allow_missing_name require_cert_auth
auth        required                                     pam_deny.so



Version-Release number of selected component (if applicable):
sssd-2.0.0-43.el8_0.3.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Configure required smartcard authentication 
2. Boot to GDM login screen without inserting smart card
3.

Actual results:
Alternating messages:
"Please enter smart card"
and 
"Sorry, that didn't work. Please try again"
Alternating every 3s. 

Expected results:
Should only display "Please enter smart card" and wait for smart card insertion.

Additional info:

Debug logs from SSSD:

p11_child.log:
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [main] (0x0400): p11_child started.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): Module List:
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): common name: [netid].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [do_card] (0x4000): Token not present.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [main] (0x0040): do_work failed.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16925]]]] [main] (0x0020): p11_child failed!
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [main] (0x0400): p11_child started.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): Module List:
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): common name: [netid].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x4000): Token not present.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [do_card] (0x0040): C_GetTokenInfo failed.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [main] (0x0040): do_work failed.
(Fri Jun  7 10:23:15 2019) [[sssd[p11_child[16929]]]] [main] (0x0020): p11_child failed!



sssd_pam.log
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[19419].
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x56009b786e30][27]
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 19419
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [19423]
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [19423]
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [19423].
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [19423] failed with status [1].
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 19419
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [19427]
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [19427]
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [19427].
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [19427] failed with status [1].
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 10:24:53 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x56009b786e30][27]


And repeated every 3s.
Comment 1 Sumit Bose 2019-06-07 09:20:30 UTC 
Hi,

can you send the logs of the following 3 or 4 requests as well?

It is expected to have a request with

> (Fri Jun  7 10:24:53 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320

first, which tells SSSD to check if a card is currently in the reader or not. If not, pam_sss will send the "Please enter smart card" message to the client and send a new SSS_PAM_PREAUTH request to SSSD with different flags asking to wait for the insertion of a Smartcard for some time.

bye,
Sumit
Comment 2 adam winberg 2019-06-07 09:26:54 UTC 
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[6840].
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 6840
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [6844]
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [6844]
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [6844].
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [6844] failed with status [1].
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 6840
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [6848]
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [6848]
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [6848].
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [6848] failed with status [1].
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 11:21:31 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[6922].
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 6922
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [6926]
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [6926]
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [6926].
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [6926] failed with status [1].
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 6922
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [6930]
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [6930]
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [6930].
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [6930] failed with status [1].
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 11:21:34 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[7005].
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7005
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [7009]
(Fri Jun  7 11:21:37 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [7009]
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [7009].
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [7009] failed with status [1].
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7005
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [7013]
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [7013]
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [7013].
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [7013] failed with status [1].
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 11:21:38 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[7087].
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7087
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [7091]
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [7091]
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [7091].
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [7091] failed with status [1].
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7087
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [7095]
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [7095]
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [7095].
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [7095] failed with status [1].
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 11:21:41 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[7169].
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55f8a656f6d0][27]
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7169
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [7173]
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [7173]
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [7173].
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [7173] failed with status [1].
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7169
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [7177]
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [7177]
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [7177].
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [7177] failed with status [1].
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 11:21:44 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x55f8a656f6d0][27]
Comment 3 adam winberg 2019-06-07 10:49:32 UTC 
As a side note, this behaviour also eventually leads to gdm crashing with:

...
Jun 07 12:35:27 c21637.ad.smhi.se gdm-smartcard][2927]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:31 c21637.ad.smhi.se gdm-smartcard][3016]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:34 c21637.ad.smhi.se gdm-smartcard][3102]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:37 c21637.ad.smhi.se gdm-smartcard][3191]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:40 c21637.ad.smhi.se gdm-smartcard][3277]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:44 c21637.ad.smhi.se gdm-smartcard][3360]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:47 c21637.ad.smhi.se gdm-smartcard][3442]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:50 c21637.ad.smhi.se gdm-smartcard][3524]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:53 c21637.ad.smhi.se gdm-smartcard][3606]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card
Jun 07 12:35:57 c21637.ad.smhi.se gdm[13634]: Could not start command '/usr/libexec/gdm-session-worker': Too many open files



Checking with 'lsof' shows that I have over 40000 gdm related file handles (user=gdm and/or command=gdm), so it seems that each iteration in the gdm login screen spawns a lot of file handles which are not cleaned properly.
Comment 4 Sumit Bose 2019-06-07 11:00:39 UTC 
Hi,

so there is a sequence of 

    [sssd[pam]] [pam_print_data] (0x0100): flags: 320
    [sssd[pam]] [pam_print_data] (0x0100): flags: 576

in the logs which is expected. What is not expected is that p11_child returns immediately in the '576' case. Can you attach the p11_child.log from the same time frame as sssd_pam.log as well?

Can you attach the list of open file as an attachment as well? Or grep for 'sss' in the list to see if some SSSD components like pam_sss or libnss_sss are not closing files properly?

Thanks

bye,
Sumit
Comment 5 adam winberg 2019-06-07 11:31:21 UTC 
I accidentally purged the logs, so i'm attaching new ones. 

Regarding the open files that seems to be a non-sssd issue, there is no increase in any 'sss'-related file handles - as opposed to the gdm related file handles which are increasing fast. 


sssd_pam.log
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[30995].
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x562d132be580][27]
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 30995
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [30999]
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [30999]
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [30999].
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [30999] failed with status [1].
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 30995
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [31003]
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [31003]
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [31003].
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [31003] failed with status [1].
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 13:23:32 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x562d132be580][27]
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[31078].
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x562d132be580][27]
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 31078
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 320
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [31082]
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [31082]
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [31082].
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [31082] failed with status [1].
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): user: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty1
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 31078
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: not set
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 576
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [31086]
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [31086]
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_forwarder_cert_cb] (0x0020): No certificate found and no logon name given, authentication not possible.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [10]: User not known to the underlying authentication module.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 8
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_sig_handler] (0x1000): Waiting for child [31086].
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [child_sig_handler] (0x0020): child [31086] failed with status [1].
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 13:23:35 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x562d132be580][27]



p11_child.log:
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [main] (0x0400): p11_child started.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): Module List:
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): common name: [netid].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [do_card] (0x4000): Token not present.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [main] (0x0040): do_work failed.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[30999]]]] [main] (0x0020): p11_child failed!
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [main] (0x0400): p11_child started.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): Module List:
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): common name: [netid].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x4000): Token not present.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [do_card] (0x0040): C_GetTokenInfo failed.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [main] (0x0040): do_work failed.
(Fri Jun  7 13:23:32 2019) [[sssd[p11_child[31003]]]] [main] (0x0020): p11_child failed!
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [main] (0x0400): p11_child started.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): Module List:
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): common name: [netid].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [do_card] (0x4000): Token not present.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [main] (0x0040): do_work failed.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31082]]]] [main] (0x0020): p11_child failed!
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [main] (0x0400): p11_child started.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): Module List:
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): common name: [netid].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x4000): Token not present.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [do_card] (0x0040): C_GetTokenInfo failed.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [main] (0x0040): do_work failed.
(Fri Jun  7 13:23:35 2019) [[sssd[p11_child[31086]]]] [main] (0x0020): p11_child failed!
Comment 6 Sumit Bose 2019-06-07 14:20:24 UTC 
Hi,

it looks a bit like p11_child is not called with the --wait_for_card option. Can you manually try to call:

    /usr/libexec/sssd/p11_child -d 10 --debug-fd=1 --pre --nssdb=/etc/sssd/pki/sssd_auth_ca_db.pem --verify=no_ocsp --wait_for_card

(maybe you have to change the value for the --nssdb option to your CA certificate file location, please don't mind the option name).

If it show a similar output without a card inserted, i.e. it does not wait for the card please try 

# pkcs11-tool --test-hotplug
Testing card detection using C_GetSlotList()
Please press return to continue, x to exit: x                <- press 'x' to skip C_GetSlotList() test
Testing card detection using C_WaitForSlotEvent()
Please press return to continue, x to exit:                  <- here I pressed 'enter' with a card inserted
Calling C_WaitForSlotEvent: event on slot 0x0
Available slots:
Slot 0 (0x0): Gemalto PC Twin Reader (CB6D4E02) 00 00
  token label        : Sumit Bose (OpenSC Card)
  token manufacturer : OpenSC Project
  token model        : PKCS#15
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 0.0
  firmware version   : 0.0
  serial num         : 56561A120E35
  pin min/max        : 4/8
Please press return to continue, x to exit:                 <- I removed the card and pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x0
Available slots:
Slot 0 (0x0): Gemalto PC Twin Reader (CB6D4E02) 00 00
  (empty)
Please press return to continue, x to exit:                <- press 'enter' again
Calling C_WaitForSlotEvent: event on slot 0x0

                                                           <- here the program waited until I inserted the card again


Available slots:
Slot 0 (0x0): Gemalto PC Twin Reader (CB6D4E02) 00 00
  token label        : Sumit Bose (OpenSC Card)
  token manufacturer : OpenSC Project
  token model        : PKCS#15
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 0.0
  firmware version   : 0.0
  serial num         : 56561A120E35
  pin min/max        : 4/8
Please press return to continue, x to exit: x
Using slot 0 with a present token (0x0)


Does C_WaitForSlotEvent wait for your card with pkcs11-tool?

bye,
Sumit
Comment 7 adam winberg 2019-06-10 06:11:48 UTC 
p11_child output:

----------------------------------------------------------
[root@c21637 ~]# /usr/libexec/sssd/p11_child -d 10 --debug-fd=1 --pre --nssdb=/tmp/certchain.pem --verify=no_ocsp --wait_for_card
(Mon Jun 10 07:59:10:359943 2019) [[sssd[p11_child[25097]]]] [main] (0x0400): p11_child started.
(Mon Jun 10 07:59:10:360026 2019) [[sssd[p11_child[25097]]]] [main] (0x2000): Running in [pre-auth] mode.
(Mon Jun 10 07:59:10:360034 2019) [[sssd[p11_child[25097]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Mon Jun 10 07:59:10:360040 2019) [[sssd[p11_child[25097]]]] [main] (0x2000): Running with real IDs [0][0].
(Mon Jun 10 07:59:10:360050 2019) [[sssd[p11_child[25097]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Mon Jun 10 07:59:10:380841 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): Module List:
(Mon Jun 10 07:59:10:380865 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Mon Jun 10 07:59:10:380872 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Mon Jun 10 07:59:10:380880 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Mon Jun 10 07:59:10:380888 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Mon Jun 10 07:59:10:380895 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): common name: [netid].
(Mon Jun 10 07:59:10:380901 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Mon Jun 10 07:59:10:380953 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Mon Jun 10 07:59:10:380963 2019) [[sssd[p11_child[25097]]]] [do_card] (0x4000): Token not present.
(Mon Jun 10 07:59:10:381040 2019) [[sssd[p11_child[25097]]]] [do_card] (0x0040): C_GetTokenInfo failed.
(Mon Jun 10 07:59:10:448719 2019) [[sssd[p11_child[25097]]]] [main] (0x0040): do_work failed.
(Mon Jun 10 07:59:10:448751 2019) [[sssd[p11_child[25097]]]] [main] (0x0020): p11_child failed!
----------------------------------------------------------

So that fails. Note that we are using a proprietary provider for our smart card interaction (libiidp11.so), not opensc. 

So, installing opensc to run pkcs11-tool following your instructions:
----------------------------------------------------------
[root@c21637 ~]# pkcs11-tool --test-hotplug
Testing card detection using C_GetSlotList()
Please press return to continue, x to exit: x
Testing card detection using C_WaitForSlotEvent()
Please press return to continue, x to exit: <pressed 'enter'>
Calling C_WaitForSlotEvent: event on slot 0x0
Available slots:
Slot 0 (0x0): Alcor Micro AU9560 00 00
  token label        : identification (Instant EID IP9)
  token manufacturer : Gemalto
  token model        : PKCS#15
  token flags        : login required, rng, token initialized, PIN initialized
  hardware version   : 0.0
  firmware version   : 0.0
  serial num         : 2634357095419540
  pin min/max        : 4/8
Slot 1 (0x1): Alcor Micro AU9560 00 00
  token label        : signature (Instant EID IP9)
  token manufacturer : Gemalto
  token model        : PKCS#15
  token flags        : login required, rng, token initialized, PIN initialized
  hardware version   : 0.0
  firmware version   : 0.0
  serial num         : 2634357095419540
  pin min/max        : 4/8
Please press return to continue, x to exit:        <- I removed the card and pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x0
Available slots:
Slot 0 (0x0): Alcor Micro AU9560 00 00
  (empty)
Slot 1 (0x1): Alcor Micro AU9560 00 00
  (empty)
Please press return to continue, x to exit:       <- pressed 'enter' again
Calling C_WaitForSlotEvent: 
<Command waiting for smartcard until i insert the card>


event on slot 0x0
Available slots:
...
----------------------------------------------------------

So, that command works and waits for smartcard insertion. 

Now, if I switch from our smartcard provider lib to opensc the p11_child command works - i.e. it's waiting for smartcard insertion. So for some reason 'C_GetTokenInfo' fails with our provider lib. Unfortunately we cant use opensc since our newer smart cards does not work with that.

So, is SSSD/p11_child dependent on opensc in some way? SSSD/p11_child has no problems communicating with our cards otherwise with our libiidp11.so, this is the only problem I've encountered.
Comment 8 Sumit Bose 2019-06-11 08:35:09 UTC 
Hi,

thanks for the details. Please try to run the pkcs11-tool test with

     pkcs11-tool --module=/usr/lib64/libiidp11.so --test-hotplug

so that your PKCS#11 module is used instead of OpenSC. Currently I assume the libiidp11.so either implements C_WaitForSlotEvent not correctly or does not return CKR_FUNCTION_NOT_SUPPORTED. I the latter case p11_child would poll and wait scheme.

bye,
Sumit
Comment 9 adam winberg 2019-06-11 10:13:56 UTC 
Yeah, that does not work:

[root@c21637 ~]# pkcs11-tool --test-hotplug --module=/usr/lib64/libiidp11.so
Testing card detection using C_GetSlotList()
Please press return to continue, x to exit: x              <-------- Pressed 'x'
Testing card detection using C_WaitForSlotEvent()
Please press return to continue, x to exit:               <-------- Pressed 'enter' with smart card inserted
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:
Slot 0 (0x1): Alcor Micro AU9560 00 00
  token label        : Instant EID IP9
  token manufacturer : Gemalto
  token model        : SetCosXpresso
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 2.10
  firmware version   : 2.0
  serial num         : 2263435709541954
  pin min/max        : 4/8
Slot 1 (0x64): Virtual Slot 100
  token state:   uninitialized
Please press return to continue, x to exit:                <-------- I removed the card and pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:
Slot 0 (0x1): Alcor Micro AU9560 00 00
  (empty)
Slot 1 (0x64): Virtual Slot 100
  token state:   uninitialized
Please press return to continue, x to exit:                 <-------- 'enter' again
Calling C_WaitForSlotEvent: failed.
  ERR: C_WaitForSlotEvent failed: CKR_NO_EVENT (0x8)
Using slot 1 with a present token (0x64)
[root@c21637 ~]#


So is this a bad pkcs11 implementation in my driver (libiidp11.so)?
Comment 10 Sumit Bose 2019-06-11 11:46:25 UTC 
Hi,

if I read http://docs.oasis-open.org/pkcs11/pkcs11-base/v3.0/pkcs11-base-v3.0.html or earlier versions correctly I would say that the implementation is not fully compliant.

CKR_NO_EVENT should only be returned in non-blocking mode if CKR_NO_EVENT is set in first argument (https://docs.oasis-open.org/pkcs11/pkcs11-base/v3.0/csprd01/pkcs11-base-v3.0-csprd01.html#_Toc10472644). p11_child uses '0' here, so it run in blocking mode where CKR_NO_EVENT is not expected. So it looks a bit like libiidp11.so uses the non-blocking mode unconditionally.

If libiidp11.so does not implement C_WaitForSlotEvent it should return CKR_FUNCTION_NOT_SUPPORTED (https://docs.oasis-open.org/pkcs11/pkcs11-base/v3.0/csprd01/pkcs11-base-v3.0-csprd01.html#_Toc10472574).

Feel free to make the vendor of libiidp11.so aware of this ticket so that we can discuss the details here.

With respect to p11_child I will think of a way how to configure to skip C_WaitForSlotEvent and use poll-and-wait instead.

bye,
Sumit
Comment 11 adam winberg 2019-06-11 12:52:18 UTC 
Not sure if this is of any importance, but if I reverse the test and run the pkcs11-tool command without card present first it seems to work:



[root@c21637 ~]# pkcs11-tool --test-hotplug --module=/usr/lib64/libiidp11.so
Testing card detection using C_GetSlotList()                  <------- Card not inserted
Please press return to continue, x to exit: x                  <------- Pressed 'x'
Testing card detection using C_WaitForSlotEvent()
Please press return to continue, x to exit:                   <------- Pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:
Slot 0 (0x1): Alcor Micro AU9560 00 00
  (empty)
Slot 1 (0x64): Virtual Slot 100
  token state:   uninitialized
Please press return to continue, x to exit:                   <------- Pressed 'enter' again
Calling C_WaitForSlotEvent:                                   <------- Process is waiting...

event on slot 0x1                                             <------- Inserted card
Available slots:
Slot 0 (0x1): Alcor Micro AU9560 00 00
  token label        : Instant EID IP9
  token manufacturer : Gemalto
  token model        : SetCosXpresso
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 2.10
  firmware version   : 2.0
  serial num         : 2263435709541954
  pin min/max        : 4/8
Slot 1 (0x64): Virtual Slot 100
  token state:   uninitialized
Please press return to continue, x to exit: Calling C_WaitForSlotEvent:     <------- Process is waiting...


event on slot 0x1                                             <------- Removed card
Available slots:
Slot 0 (0x1): Alcor Micro AU9560 00 00
  (empty)
Slot 1 (0x64): Virtual Slot 100
  token state:   uninitialized
Please press return to continue, x to exit: Calling C_WaitForSlotEvent:      <------- Process is waiting...

event on slot 0x1                                             <------- Inserted card
Available slots:
Slot 0 (0x1): Alcor Micro AU9560 00 00
  token label        : Instant EID IP9
  token manufacturer : Gemalto
  token model        : SetCosXpresso
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 2.10
  firmware version   : 2.0
  serial num         : 2263435709541954
  pin min/max        : 4/8
Slot 1 (0x64): Virtual Slot 100
  token state:   uninitialized
Please press return to continue, x to exit: Calling C_WaitForSlotEvent: 



The documentation from the driver provider suggests that C_WaitForSlotEvent is supported, there is a configuration option mentioning it ("This entry is used to enable/disable update of slot list when library is called for active event list (C_WaitForSlotEvent)"). This option is enabled, but there might be some misconfiguration somewhere else, I will check with the vendor.
Comment 12 adam winberg 2019-06-12 14:56:32 UTC 
Thank you for your awesome support as always - we've also had very good support from our vendor who where able to locate the cause. It's a bug in the vendor driver. So I guess this can be closed as notabug. 

Thank you for helping us track this down!
Comment 13 Sumit Bose 2019-06-12 15:07:11 UTC 
Hi,

thank you for the feedback. I'd prefer to keep the ticket around to make the waiting scheme configurable. There might be other PKCS#11 modules around which might not work as expected with C_WaitForSlotEvent.

bye,
Sumit
Comment 14 adam winberg 2019-07-02 12:03:04 UTC 
I got an updated driver from our vendor which works as expected with the pkcs11-tool test, but I still get the same behaviour in GDM. 

If i instead try the proposed test with p11_child it fails when started without card inserted:

$ /usr/libexec/sssd/p11_child -d 10 --debug-fd=1 --pre --nssdb /tmp/cert.pem --verify=no_ocsp --wait_for_card 
(Tue Jul  2 13:55:42:307180 2019) [[sssd[p11_child[12160]]]] [main] (0x0400): p11_child started.
(Tue Jul  2 13:55:42:307324 2019) [[sssd[p11_child[12160]]]] [main] (0x2000): Running in [pre-auth] mode.
(Tue Jul  2 13:55:42:307331 2019) [[sssd[p11_child[12160]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Tue Jul  2 13:55:42:307337 2019) [[sssd[p11_child[12160]]]] [main] (0x2000): Running with real IDs [0][0].
(Tue Jul  2 13:55:42:307347 2019) [[sssd[p11_child[12160]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Tue Jul  2 13:55:42:319157 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): Module List:
(Tue Jul  2 13:55:42:319180 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Tue Jul  2 13:55:42:319186 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Tue Jul  2 13:55:42:319192 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Tue Jul  2 13:55:42:319197 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Tue Jul  2 13:55:42:319203 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): common name: [netid].
(Tue Jul  2 13:55:42:319207 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Tue Jul  2 13:55:42:319256 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Tue Jul  2 13:55:42:319263 2019) [[sssd[p11_child[12160]]]] [do_card] (0x4000): Token not present.
(Tue Jul  2 13:55:42:319364 2019) [[sssd[p11_child[12160]]]] [do_card] (0x0040): C_GetTokenInfo failed.
(Tue Jul  2 13:55:42:386677 2019) [[sssd[p11_child[12160]]]] [main] (0x0040): do_work failed.
(Tue Jul  2 13:55:42:386712 2019) [[sssd[p11_child[12160]]]] [main] (0x0020): p11_child failed!
Comment 15 Sumit Bose 2019-07-02 20:18:22 UTC 
Hi,

does new new driver works in both schemes you described in comment #9 and #11?

Can you enable OpenSC debugging by un-commenting the 'debug = 3' and 'debug_file = ...' lines in the 'app default' section of /etc/opensc-x86_64.conf, run p11_child with --wait_for_card again and send the OpenSC log file?

bye,
Sumit
Comment 16 adam winberg 2019-07-03 06:01:33 UTC 
Yes, new driver works in both tests/schemes. 

Regarding the opensc debug, I guess that would be non-applicable here since I don't use opensc? I do however have trace logs from our provider from a p11_child run, don't know if that might be of any help:



[0430:23291380] 00.00.00.000 Trace - Date 2019-07-03 07:57:08, '/var/log/iid_trace.log'
[0430:23291380] 00.00.00.000 Pkcs11 - C_Initialize ...
[0430:23291380] 00.00.00.000 Pkcs11 - Little endian build (64 bit CK_ULONG)
[0430:23291380] 00.00.00.001 Helper - Calling application: '/usr/libexec/sssd/p11_child'
[0430:23291380] 00.00.00.001 Config - Open '/etc/iid.conf' (r)
[0430:23291380] 00.00.00.001 CryptoKi - Initialize ...
[0430:23291380] 00.00.00.001 Config - Open '/etc/iid.conf' (r)
[0430:23291380] 00.00.00.001 Object - Friendly name format: '%subject.2.5.4.3%, %subject.2.5.4.10%'
[0430:23291380] 00.00.00.001 Supervisor - Initialize ...
[0430:23291380] 00.00.00.001 PCSC - Scope:        USER
[0430:23291380] 00.00.00.001 PCSC - UseCritical:  ON
[0430:23291380] 00.00.00.001 PCSC - StateTimeout: OFF
[0430:23291380] 00.00.00.001 PCSC - Notification: OFF
[0430:23291380] 00.00.00.001 PCSC - Size DWORD:   64 bits
[0430:23291380] 00.00.00.001 PCSC - Library '/usr/lib64/libpcsclite.so.1' loaded
[0430:23291380] 00.00.00.001 Supervisor - CacheValidity:         10080
[0430:23291380] 00.00.00.001 Supervisor - CachePrivate:          FALSE
[0430:23291380] 00.00.00.001 Supervisor - CachePath:             
[0430:23291380] 00.00.00.001 Supervisor - CacheServer:           FALSE
[0430:23291380] 00.00.00.001 Supervisor - CacheAcceptUnknown:    0
[0430:23291380] 00.00.00.001 Supervisor - CacheValidateCounter:  TRUE
[0430:23291380] 00.00.00.001 Supervisor - CacheOnDisk:           TRUE
[0430:23291380] 00.00.00.001 Supervisor - PinType:               0
[0430:23291380] 00.00.00.001 Supervisor - PinExpire:             0
[0430:23291380] 00.00.00.001 Supervisor - ObjectSortMode:        0
[0430:23291380] 00.00.00.001 Supervisor - ExternCardCacheUpdate: FALSE
[0430:23291380] 00.00.00.001 Supervisor - UseInternalUpdate:     TRUE
[0430:23291380] 00.00.00.001 Supervisor - CreateUpdateCounter:   TRUE
[0430:23291380] 00.00.00.001 Supervisor - ValidateUpdateCounter: FALSE
[0430:23291380] 00.00.00.001 Supervisor - DefaultProfile:        
[0430:23291380] 00.00.00.001 Supervisor - UseLastUpdate:         TRUE
[0430:23291380] 00.00.00.001 Supervisor - Detect:                1
[0430:23291380] 00.00.00.001 Supervisor - Poll:                  333
[0430:23291380] 00.00.00.001 Supervisor - Accepted:              ''
[0430:23291380] 00.00.00.001 Supervisor - Denied:                ''
[0430:23291380] 00.00.00.001 Supervisor - Mode:                  1
[0430:23291380] 00.00.00.001 Supervisor - LockTimeout:           30
[0430:23291380] 00.00.00.001 Supervisor - LockDelay:             0
[0430:23291380] 00.00.00.001 Supervisor - MaxTransfer:           255
[0430:23291380] 00.00.00.001 Supervisor - Protocol:              -1
[0430:23291380] 00.00.00.001 Supervisor - KeepLoggedInLocked:    FALSE
[0430:23291380] 00.00.00.001 Supervisor - ReloadOnError:         1
[0430:23291380] 00.00.00.001 Supervisor - RestartService:        FALSE
[0430:23291380] 00.00.00.001 Supervisor - SingleConnection:      TRUE
[0430:23291380] 00.00.00.001 Supervisor - AllowReaderRemoval:    FALSE
[0430:23291380] 00.00.00.001 Supervisor - CheckPinPad:           FALSE
[0430:23291380] 00.00.00.001 Supervisor - CheckInformation:      FALSE
[0430:23291380] 00.00.00.001 Supervisor - KeepPinCache:          0
[0430:23291380] 00.00.00.001 Supervisor - ReuseSlotID:           FALSE
[0430:23291380] 00.00.00.001 Supervisor - DetectReaders ...
[0430:23291380] 00.00.00.007 PCSC - Initializing reader 'Alcor Micro AU9560 00 00'
[0430:23291380] 00.00.00.007 PCSC - Library load (2 times)
[0430:23291380] 00.00.00.009 PCSC - Single reader connection
[0430:23291380] 00.00.00.009 PCSC - Reader 'Alcor Micro AU9560 00 00' available (1392063182:-1)
[0430:23291380] 00.00.00.009 Supervisor - Added handler 0: 'Alcor Micro AU9560 00 00'
[0430:23291380] 00.00.00.009 Supervisor - DetectReaders ... done
[0430:23291380] 00.00.00.009 Supervisor - SendEvents ...
[0430:23291380] 00.00.00.009 CryptoKi - Slot 1 inserted
[0430:23291380] 00.00.00.009 Supervisor - Reader INSERTED slot 1
[0430:23291380] 00.00.00.009 CryptoKi - Single pin specified (slot 2 ignored)
[0430:23291380] 00.00.00.009 Supervisor - Reader INSERTED slot 2
[0430:23291380] 00.00.00.009 CryptoKi - Single pin specified (slot 3 ignored)
[0430:23291380] 00.00.00.009 Supervisor - Reader INSERTED slot 3
[0430:23291380] 00.00.00.009 Supervisor - SendEvents ... done
[0430:23291380] 00.00.00.009 Supervisor - Initialized readers
[0430:23291380] 00.00.00.009 Supervisor - Initialized card status
[0430:23291380] 00.00.00.009 Supervisor - Start polling ...
[0430:23291380] 00.00.00.009 Supervisor - Start polling .. done
[0430:23291380] 00.00.00.009 Supervisor - Initialize ... done
[0430:23291380] 00.00.00.009 Config - Open '/root/.iid/iid.conf' (r)
[0430:23291380] 00.00.00.009 Config - Open '/etc/iid.conf' (r)
[0430:23291380] 00.00.00.009 CryptoKi - Insert soft tokens ...
[0430:23291380] 00.00.00.009 Config - Open '/etc/iid.conf' (r)
[0430:23291380] 00.00.00.009 CryptoKi - Insert soft tokens ... done
[0430:23291380] 00.00.00.009 CryptoKi - Initialize ... done
[0430:23291380] 00.00.00.009 Pkcs11 - Return CKR_OK
[0430:23291380] 00.00.00.013 Pkcs11 - C_GetSlotList ...
[0430:23291380] 00.00.00.013 Slot - Info slot id 1: flags 0x06, 'Alcor Micro AU9560 00 00'
[0430:23291380] 00.00.00.013 Pkcs11 - Return CKR_OK
[0430:23291380] 00.00.00.013 Pkcs11 - C_GetSlotInfo ...
[0430:23291380] 00.00.00.013 Slot - Info slot id 1: flags 0x06, 'Alcor Micro AU9560 00 00'
[0430:23291380] 00.00.00.013 Pkcs11 - Return CKR_OK
[0430:23291380] 00.00.00.013 CryptoKi - An event on slot 1
[0430:23291380] 00.00.00.013 Pkcs11 - C_GetTokenInfo ...
[0430:23291380] 00.00.00.013 Pkcs11 - Failed to get token
[0430:23291380] 00.00.00.013 Pkcs11 - Return CKR_TOKEN_NOT_PRESENT
[0430:23291380] 00.00.00.013 Pkcs11 - C_Finalize ...
[0430:23291380] 00.00.00.013 CryptoKi - Finalize ...
[0430:23291380] 00.00.00.013 TokenSC - Destructor 1
[0430:23291380] 00.00.00.013 Supervisor - Finalize ...
[0430:23291380] 00.00.00.080 Supervisor - Delete handler objects
[0430:23291380] 00.00.00.080 PCSC - Library unload (1 left)
[0430:23291380] 00.00.00.080 PCSC - Finalized
[0430:23291380] 00.00.00.080 Supervisor - Append 'Alcor Micro AU9560 00 00' to delete list (0: 1-3)
[0430:23291380] 00.00.00.080 Supervisor - Delete 'Alcor Micro AU9560 00 00' (0: 1-3)
[0430:23291380] 00.00.00.080 PCSC - Finalized
[0430:23291380] 00.00.00.081 PCSC - Library unload (0 left)
[0430:23291380] 00.00.00.081 Supervisor - Finalize ... done
[0430:23291380] 00.00.00.081 CryptoKi - Finalize ... done
[0430:23291380] 00.00.00.081 Pkcs11 - Return CKR_OK
[0430:23291380] 00.00.00.081 WrapperPkcs11 - Destroyed
Comment 17 Sumit Bose 2019-07-03 06:41:05 UTC 
(In reply to adam winberg from comment #16)
> Yes, new driver works in both tests/schemes. 
> 
> Regarding the opensc debug, I guess that would be non-applicable here since
> I don't use opensc? I do however have trace logs from our provider from a

oops, sorry, I wanted to ask for pcscd logs but for whatever reasons my mind switched to OpenSC.

> p11_child run, don't know if that might be of any help:
> 

yes, they show the PKCS#11 calls as well and ....

> 
> 
> [0430:23291380] 00.00.00.000 Trace - Date 2019-07-03 07:57:08,
> '/var/log/iid_trace.log'
> [0430:23291380] 00.00.00.000 Pkcs11 - C_Initialize ...
> [0430:23291380] 00.00.00.000 Pkcs11 - Little endian build (64 bit CK_ULONG)
> [0430:23291380] 00.00.00.001 Helper - Calling application:
> '/usr/libexec/sssd/p11_child'
> [0430:23291380] 00.00.00.001 Config - Open '/etc/iid.conf' (r)
> [0430:23291380] 00.00.00.001 CryptoKi - Initialize ...
> [0430:23291380] 00.00.00.001 Config - Open '/etc/iid.conf' (r)
> [0430:23291380] 00.00.00.001 Object - Friendly name format:
> '%subject.2.5.4.3%, %subject.2.5.4.10%'
> [0430:23291380] 00.00.00.001 Supervisor - Initialize ...
> [0430:23291380] 00.00.00.001 PCSC - Scope:        USER
> [0430:23291380] 00.00.00.001 PCSC - UseCritical:  ON
> [0430:23291380] 00.00.00.001 PCSC - StateTimeout: OFF
> [0430:23291380] 00.00.00.001 PCSC - Notification: OFF
> [0430:23291380] 00.00.00.001 PCSC - Size DWORD:   64 bits
> [0430:23291380] 00.00.00.001 PCSC - Library '/usr/lib64/libpcsclite.so.1'
> loaded
> [0430:23291380] 00.00.00.001 Supervisor - CacheValidity:         10080
> [0430:23291380] 00.00.00.001 Supervisor - CachePrivate:          FALSE
> [0430:23291380] 00.00.00.001 Supervisor - CachePath:             
> [0430:23291380] 00.00.00.001 Supervisor - CacheServer:           FALSE
> [0430:23291380] 00.00.00.001 Supervisor - CacheAcceptUnknown:    0
> [0430:23291380] 00.00.00.001 Supervisor - CacheValidateCounter:  TRUE
> [0430:23291380] 00.00.00.001 Supervisor - CacheOnDisk:           TRUE
> [0430:23291380] 00.00.00.001 Supervisor - PinType:               0
> [0430:23291380] 00.00.00.001 Supervisor - PinExpire:             0
> [0430:23291380] 00.00.00.001 Supervisor - ObjectSortMode:        0
> [0430:23291380] 00.00.00.001 Supervisor - ExternCardCacheUpdate: FALSE
> [0430:23291380] 00.00.00.001 Supervisor - UseInternalUpdate:     TRUE
> [0430:23291380] 00.00.00.001 Supervisor - CreateUpdateCounter:   TRUE
> [0430:23291380] 00.00.00.001 Supervisor - ValidateUpdateCounter: FALSE
> [0430:23291380] 00.00.00.001 Supervisor - DefaultProfile:        
> [0430:23291380] 00.00.00.001 Supervisor - UseLastUpdate:         TRUE
> [0430:23291380] 00.00.00.001 Supervisor - Detect:                1
> [0430:23291380] 00.00.00.001 Supervisor - Poll:                  333
> [0430:23291380] 00.00.00.001 Supervisor - Accepted:              ''
> [0430:23291380] 00.00.00.001 Supervisor - Denied:                ''
> [0430:23291380] 00.00.00.001 Supervisor - Mode:                  1
> [0430:23291380] 00.00.00.001 Supervisor - LockTimeout:           30
> [0430:23291380] 00.00.00.001 Supervisor - LockDelay:             0
> [0430:23291380] 00.00.00.001 Supervisor - MaxTransfer:           255
> [0430:23291380] 00.00.00.001 Supervisor - Protocol:              -1
> [0430:23291380] 00.00.00.001 Supervisor - KeepLoggedInLocked:    FALSE
> [0430:23291380] 00.00.00.001 Supervisor - ReloadOnError:         1
> [0430:23291380] 00.00.00.001 Supervisor - RestartService:        FALSE
> [0430:23291380] 00.00.00.001 Supervisor - SingleConnection:      TRUE
> [0430:23291380] 00.00.00.001 Supervisor - AllowReaderRemoval:    FALSE
> [0430:23291380] 00.00.00.001 Supervisor - CheckPinPad:           FALSE
> [0430:23291380] 00.00.00.001 Supervisor - CheckInformation:      FALSE
> [0430:23291380] 00.00.00.001 Supervisor - KeepPinCache:          0
> [0430:23291380] 00.00.00.001 Supervisor - ReuseSlotID:           FALSE
> [0430:23291380] 00.00.00.001 Supervisor - DetectReaders ...
> [0430:23291380] 00.00.00.007 PCSC - Initializing reader 'Alcor Micro AU9560
> 00 00'
> [0430:23291380] 00.00.00.007 PCSC - Library load (2 times)
> [0430:23291380] 00.00.00.009 PCSC - Single reader connection
> [0430:23291380] 00.00.00.009 PCSC - Reader 'Alcor Micro AU9560 00 00'
> available (1392063182:-1)
> [0430:23291380] 00.00.00.009 Supervisor - Added handler 0: 'Alcor Micro
> AU9560 00 00'
> [0430:23291380] 00.00.00.009 Supervisor - DetectReaders ... done
> [0430:23291380] 00.00.00.009 Supervisor - SendEvents ...
> [0430:23291380] 00.00.00.009 CryptoKi - Slot 1 inserted
> [0430:23291380] 00.00.00.009 Supervisor - Reader INSERTED slot 1
> [0430:23291380] 00.00.00.009 CryptoKi - Single pin specified (slot 2 ignored)
> [0430:23291380] 00.00.00.009 Supervisor - Reader INSERTED slot 2
> [0430:23291380] 00.00.00.009 CryptoKi - Single pin specified (slot 3 ignored)
> [0430:23291380] 00.00.00.009 Supervisor - Reader INSERTED slot 3
> [0430:23291380] 00.00.00.009 Supervisor - SendEvents ... done
> [0430:23291380] 00.00.00.009 Supervisor - Initialized readers
> [0430:23291380] 00.00.00.009 Supervisor - Initialized card status
> [0430:23291380] 00.00.00.009 Supervisor - Start polling ...
> [0430:23291380] 00.00.00.009 Supervisor - Start polling .. done
> [0430:23291380] 00.00.00.009 Supervisor - Initialize ... done
> [0430:23291380] 00.00.00.009 Config - Open '/root/.iid/iid.conf' (r)
> [0430:23291380] 00.00.00.009 Config - Open '/etc/iid.conf' (r)
> [0430:23291380] 00.00.00.009 CryptoKi - Insert soft tokens ...
> [0430:23291380] 00.00.00.009 Config - Open '/etc/iid.conf' (r)
> [0430:23291380] 00.00.00.009 CryptoKi - Insert soft tokens ... done
> [0430:23291380] 00.00.00.009 CryptoKi - Initialize ... done
> [0430:23291380] 00.00.00.009 Pkcs11 - Return CKR_OK
> [0430:23291380] 00.00.00.013 Pkcs11 - C_GetSlotList ...
> [0430:23291380] 00.00.00.013 Slot - Info slot id 1: flags 0x06, 'Alcor Micro
> AU9560 00 00'
> [0430:23291380] 00.00.00.013 Pkcs11 - Return CKR_OK
> [0430:23291380] 00.00.00.013 Pkcs11 - C_GetSlotInfo ...
> [0430:23291380] 00.00.00.013 Slot - Info slot id 1: flags 0x06, 'Alcor Micro
> AU9560 00 00'
> [0430:23291380] 00.00.00.013 Pkcs11 - Return CKR_OK
> [0430:23291380] 00.00.00.013 CryptoKi - An event on slot 1

... C_WaitForSlotEvent is completely missing.

Do you have a chance to check with gdb why p11_child does not try to call C_WaitForSlotEvent. The related code is:

1501     if (!(info.flags & CKF_TOKEN_PRESENT)) {
1502         DEBUG(SSSDBG_TRACE_ALL, "Token not present.\n");
1503         if (p11_ctx->wait_for_card) {
1504             ret = wait_for_card(modules[c], &slot_id);
1505             if (ret != EOK) {
1506                 DEBUG(SSSDBG_OP_FAILURE, "wait_for_card failed.\n");
1507                 goto done;
1508             }
1509         } else {
1510             ret = EIO;
1511             goto done;
1512         }
1513     }

If you set a breakpoint at wait_for_card() and then step through wait_for_card() it should show what is happening. C_WaitForSlotEvent should be the first call in wait_for_card():

1290 static errno_t wait_for_card(CK_FUNCTION_LIST *module, CK_SLOT_ID *slot_id)
1291 {
1292     CK_FLAGS wait_flags = 0;
1293     CK_RV rv;
1294     CK_SLOT_INFO info;
1295 
1296     rv = module->C_WaitForSlotEvent(wait_flags, slot_id, NULL);
1297     if (rv != CKR_OK) {
1298         if (rv != CKR_FUNCTION_NOT_SUPPORTED) {
1299             DEBUG(SSSDBG_OP_FAILURE,
1300                   "C_WaitForSlotEvent failed [%lu][%s].\n",
1301                   rv, p11_kit_strerror(rv)); 
1302             return EIO;
1303         }
1304 
1305         /* Poor man's wait */
1306         do {


Thanks

bye,
Sumit

> [0430:23291380] 00.00.00.013 Pkcs11 - C_GetTokenInfo ...
> [0430:23291380] 00.00.00.013 Pkcs11 - Failed to get token
> [0430:23291380] 00.00.00.013 Pkcs11 - Return CKR_TOKEN_NOT_PRESENT
> [0430:23291380] 00.00.00.013 Pkcs11 - C_Finalize ...
> [0430:23291380] 00.00.00.013 CryptoKi - Finalize ...
> [0430:23291380] 00.00.00.013 TokenSC - Destructor 1
> [0430:23291380] 00.00.00.013 Supervisor - Finalize ...
> [0430:23291380] 00.00.00.080 Supervisor - Delete handler objects
> [0430:23291380] 00.00.00.080 PCSC - Library unload (1 left)
> [0430:23291380] 00.00.00.080 PCSC - Finalized
> [0430:23291380] 00.00.00.080 Supervisor - Append 'Alcor Micro AU9560 00 00'
> to delete list (0: 1-3)
> [0430:23291380] 00.00.00.080 Supervisor - Delete 'Alcor Micro AU9560 00 00'
> (0: 1-3)
> [0430:23291380] 00.00.00.080 PCSC - Finalized
> [0430:23291380] 00.00.00.081 PCSC - Library unload (0 left)
> [0430:23291380] 00.00.00.081 Supervisor - Finalize ... done
> [0430:23291380] 00.00.00.081 CryptoKi - Finalize ... done
> [0430:23291380] 00.00.00.081 Pkcs11 - Return CKR_OK
> [0430:23291380] 00.00.00.081 WrapperPkcs11 - Destroyed
Comment 18 adam winberg 2019-07-03 08:26:43 UTC 
gdb is not very familiar to me, so I'm not sure I did it right.

gdb output:


(gdb) b p11_child_openssl.c:1503
Breakpoint 1 at 0xa5d4: file src/p11_child/p11_child_openssl.c, line 1503.
(gdb)  run --pre --nssdb /tmp/cert.pem --verify=no_ocsp --wait_for_card 
Starting program: /usr/libexec/sssd/p11_child --pre --nssdb /tmp/cert.pem --verify=no_ocsp --wait_for_card
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff323c700 (LWP 18137)]

Thread 1 "p11_child" hit Breakpoint 1, do_card (mem_ctx=0x555555766760, p11_ctx=0x555555785df0, mode=OP_PREAUTH, pin=0x0, module_name_in=0x0, token_name_in=0x0, 
    key_id_in=0x0, uri_str=0x0, _multi=0x7fffffffdbd8) at src/p11_child/p11_child_openssl.c:1503
1503	src/p11_child/p11_child_openssl.c: No such file or directory.
(gdb) step
1504	in src/p11_child/p11_child_openssl.c
(gdb) step
wait_for_card (module=0x55555579c590, module=0x55555579c590, slot_id=0x7fffffffd570) at src/p11_child/p11_child_openssl.c:1296
1296	in src/p11_child/p11_child_openssl.c
(gdb) step
1297	in src/p11_child/p11_child_openssl.c
(gdb) step
do_card (mem_ctx=0x555555766760, p11_ctx=0x555555785df0, mode=OP_PREAUTH, pin=0x0, module_name_in=0x0, token_name_in=0x0, key_id_in=0x0, uri_str=0x0, 
    _multi=0x7fffffffdbd8) at src/p11_child/p11_child_openssl.c:1505
1505	in src/p11_child/p11_child_openssl.c
(gdb) step
1515	in src/p11_child/p11_child_openssl.c
(gdb)
Comment 19 Sumit Bose 2019-07-03 11:12:31 UTC 
Thanks, so it looks like C_WaitForSlotEvent is called and immediately returns CKR_OK.

To get a bit more details in the gdb output it would be good to install the debuginfo packages with

    debuginfo-install sssd

Can you run the test again and check if the event is on the expected slot_id by calling

(gdb) p *slot_id

after 'wait_for_card (module=0x55555579c590, module=0x55555579c590, slot_id=0x7fffffffd570) at src/p11_child/p11_child_openssl.c:1296' is shown?

Then 'step' and 'p *slot_id' in a sequence until 'do_card (mem_ctx=0x555555766760, p11_ctx=0x555555785df0, mode=OP_PREAUTH,' is shown.

Additionally can you send the pkcs11-tool output for the new version as well?

bye,
Sumit
Comment 20 adam winberg 2019-07-03 11:28:01 UTC 
I already have the debuginfo packages installed:

[root@c21637 ~]# rpm -qa | grep sssd | grep debug
sssd-common-debuginfo-2.0.0-43.el8_0.3.x86_64
sssd-debuginfo-2.0.0-43.el8_0.3.x86_64

Should there be more info in the gdb?


gdb output with var printing:

(gdb) b p11_child_openssl.c:1503
Breakpoint 1 at 0xa5d4: file src/p11_child/p11_child_openssl.c, line 1503.
(gdb) run --pre --nssdb /tmp/cert.pem --verify=no_ocsp --wait_for_card 
Starting program: /usr/libexec/sssd/p11_child --pre --nssdb /tmp/cert.pem --verify=no_ocsp --wait_for_card
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff323c700 (LWP 29508)]

Thread 1 "p11_child" hit Breakpoint 1, do_card (mem_ctx=0x555555766760, p11_ctx=0x555555785df0, mode=OP_PREAUTH, pin=0x0, module_name_in=0x0, token_name_in=0x0, 
    key_id_in=0x0, uri_str=0x0, _multi=0x7fffffffdbb8) at src/p11_child/p11_child_openssl.c:1503
1503	src/p11_child/p11_child_openssl.c: No such file or directory.
(gdb) s
1504	in src/p11_child/p11_child_openssl.c
(gdb) s
wait_for_card (module=0x55555579c590, module=0x55555579c590, slot_id=0x7fffffffd550) at src/p11_child/p11_child_openssl.c:1296
1296	in src/p11_child/p11_child_openssl.c
(gdb) p *slot_id
$1 = 1
(gdb) s
1297	in src/p11_child/p11_child_openssl.c
(gdb) p *slot_id
$2 = 1
(gdb) s
do_card (mem_ctx=0x555555766760, p11_ctx=0x555555785df0, mode=OP_PREAUTH, pin=0x0, module_name_in=0x0, token_name_in=0x0, key_id_in=0x0, uri_str=0x0, 
    _multi=0x7fffffffdbb8) at src/p11_child/p11_child_openssl.c:1505
1505	in src/p11_child/p11_child_openssl.c
(gdb) p *slot_id
Cannot access memory at address 0x1
(gdb) 


Output of pkcs11-tool:

[root@c21637 ~]# pkcs11-tool --test-hotplug --module=/usr/lib64/libiidp11.so
Testing card detection using C_GetSlotList()
Please press return to continue, x to exit: x             <-------- Pressed 'x' (with card inserted)
Testing card detection using C_WaitForSlotEvent()
Please press return to continue, x to exit:              <-------- Pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:
Slot 0 (0x1): Alcor Micro AU9560 00 00
  token label        : Instant EID IP
  token manufacturer : Gemalto
  token model        : SetCosXpresso
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 2.10
  firmware version   : 2.0
  serial num         : 2263435709541954
  pin min/max        : 4/8
Please press return to continue, x to exit:              <-------- Pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:                                         <-------- Card removed
Slot 0 (0x1): Alcor Micro AU9560 00 00
  (empty)
Please press return to continue, x to exit:              <-------- Pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:                                         <-------- Card inserted
Slot 0 (0x1): Alcor Micro AU9560 00 00
  token label        : Instant EID IP
  token manufacturer : Gemalto
  token model        : SetCosXpresso
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 2.10
  firmware version   : 2.0
  serial num         : 2263435709541954
  pin min/max        : 4/8
Please press return to continue, x to exit:               <-------- Pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:                                         <-------- Card removed
Slot 0 (0x1): Alcor Micro AU9560 00 00
  (empty)
Please press return to continue, x to exit:                <-------- Pressed 'enter'
Calling C_WaitForSlotEvent: event on slot 0x1
Available slots:                                         <-------- Card inserted
Slot 0 (0x1): Alcor Micro AU9560 00 00
  token label        : Instant EID IP
  token manufacturer : Gemalto
  token model        : SetCosXpresso
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 2.10
  firmware version   : 2.0
  serial num         : 2263435709541954
  pin min/max        : 4/8
Please press return to continue, x to e
Comment 21 Jakub Hrozek 2019-07-03 11:43:07 UTC 
Could you also try installing the debugsource package?
Comment 22 adam winberg 2019-07-03 11:51:30 UTC 
ok, that yields a bit more info:


Thread 1 "p11_child" hit Breakpoint 1, do_card (mem_ctx=0x555555766760, p11_ctx=0x555555785de0, mode=OP_PREAUTH, pin=0x0, module_name_in=0x0, token_name_in=0x0, 
    key_id_in=0x0, uri_str=0x0, _multi=0x7fffffffdbb8) at src/p11_child/p11_child_openssl.c:1503
1503	        if (p11_ctx->wait_for_card) {
(gdb) s
1504	            ret = wait_for_card(modules[c], &slot_id);
(gdb) s
wait_for_card (module=0x55555579b670, module=0x55555579b670, slot_id=0x7fffffffd550) at src/p11_child/p11_child_openssl.c:1296
1296	    rv = module->C_WaitForSlotEvent(wait_flags, slot_id, NULL);
(gdb) p *slot_id
$1 = 1
(gdb) s
1297	    if (rv != CKR_OK) {
(gdb) p *slot_id
$2 = 1
(gdb) s
do_card (mem_ctx=0x555555766760, p11_ctx=0x555555785de0, mode=OP_PREAUTH, pin=0x0, module_name_in=0x0, token_name_in=0x0, key_id_in=0x0, uri_str=0x0, 
    _multi=0x7fffffffdbb8) at src/p11_child/p11_child_openssl.c:1505
1505	            if (ret != EOK) {
(gdb) p *slot_id
Cannot access memory at address 0x1
Comment 23 adam winberg 2019-08-14 11:24:27 UTC 
Any ideas based on the output with debugsource packages installed?
Comment 24 adam winberg 2019-08-30 06:27:41 UTC 
Is there anything else I can do to help debugging this?
Comment 25 Sumit Bose 2019-08-30 16:29:36 UTC 
Hi,

I starred for a couple of times at the pkcs11-tool and p11_child code to find a difference but failed so far.

One difference might be that pkcs11-tool used the PKCS#11 module directly while p11_child uses p11-kit in between. Can you try

    pkcs11-tool --test-hotplug --module=/usr/lib64/p11-kit-proxy.so

and check if C_WaitForSlotEvent works here as well?

bye,
Sumit
Comment 26 adam winberg 2019-09-18 09:09:02 UTC 
Sorry for the delay!

Output:

[root@c21637:~]$ pkcs11-tool --test-hotplug --module=/usr/lib64/p11-kit-proxy.so
Testing card detection using C_GetSlotList()
Please press return to continue, x to exit: x
Testing card detection using C_WaitForSlotEvent()
Please press return to continue, x to exit: 
Calling C_WaitForSlotEvent: failed.
  ERR: C_WaitForSlotEvent failed: CKR_FUNCTION_NOT_SUPPORTED (0x54)
Using slot 0 with a present token (0x10)
[root@c21637:~]

So that did not work... Same with card inserted or not inserted at command execution.
Comment 27 adam winberg 2019-10-09 12:19:50 UTC 
Any updates on this?
Comment 28 adam winberg 2019-11-14 10:49:02 UTC 
Again - any thougths on Comment #26?
Comment 29 adam winberg 2020-01-30 07:11:02 UTC 
wow, haven't heard anything here in a long while, anything?
Comment 30 Sumit Bose 2020-01-30 10:00:26 UTC 
Hi,

thanks for the reminder. I did some testing during the holidays, but forgot to update this ticket when I returned. Please let me know which version of SSSD you are currently using so that I can prepare a test build.

bye,
Sumit
Comment 31 adam winberg 2020-01-30 10:36:17 UTC 
sssd-2.2.0-19.el8.x86_64
Comment 32 Sumit Bose 2020-01-30 13:56:10 UTC 
Created attachment 1656500 [details]
test build

Hi,

please find a test build in the attached tar ball.

bye,
Sumit
Comment 33 adam winberg 2020-01-31 13:45:20 UTC 
I have installed the test builds but get the same behaviour with the test in comment 26. 

The p11_child test in comment 14 works though! But behaviour in GDM is the same...
Comment 34 Sumit Bose 2020-01-31 14:36:24 UTC 
(In reply to adam winberg from comment #33)
> I have installed the test builds but get the same behaviour with the test in
> comment 26. 
> 
> The p11_child test in comment 14 works though! But behaviour in GDM is the
> same...

Hi,

thanks for testing, do I understand correctly that p11_child with --wait_for_card now waits properly until a card is inserted and then returns the list of certificates? If that's the case can you attach new sssd_pam.log and p11_child.log with debug_level=9 in the [pam] section of sssd.conf?

bye,
Sumit
Comment 35 adam winberg 2020-01-31 15:01:01 UTC 
Yes, running the p11_child command waits properly:

[root@c21637:~]$ /usr/libexec/sssd/p11_child -d 10 --debug-fd=1 --pre --nssdb /etc/pki/ca-trust/source/anchors/smartcart-cert-chain.pem --verify=no_ocsp --wait_for_card
(Fri Jan 31 15:57:02:595787 2020) [[sssd[p11_child[21584]]]] [main] (0x0400): p11_child started.
(Fri Jan 31 15:57:02:595938 2020) [[sssd[p11_child[21584]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jan 31 15:57:02:595962 2020) [[sssd[p11_child[21584]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jan 31 15:57:02:595983 2020) [[sssd[p11_child[21584]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jan 31 15:57:02:596012 2020) [[sssd[p11_child[21584]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jan 31 15:57:02:651248 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): Module List:
(Fri Jan 31 15:57:02:651289 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jan 31 15:57:02:651308 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jan 31 15:57:02:651326 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jan 31 15:57:02:651344 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ] Manufacturer [PKCS#11 Kit                     ] flags [1] removable [false] token present [true].
(Fri Jan 31 15:57:02:651362 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): common name: [netid].
(Fri Jan 31 15:57:02:651376 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jan 31 15:57:02:651499 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].
(Fri Jan 31 15:57:02:651521 2020) [[sssd[p11_child[21584]]]] [do_card] (0x4000): Token not present.
(Fri Jan 31 15:57:02:651676 2020) [[sssd[p11_child[21584]]]] [wait_for_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [6] removable [true] token present [false].

-------> Waiting here for smartcard


-------> Inserting smartcard 
(Fri Jan 31 15:57:08:894597 2020) [[sssd[p11_child[21584]]]] [wait_for_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ] Manufacturer [Alcor Micro AU9560 00 00        ] flags [7] removable [true] token present [true].









p11_child.log when removing card, thus locking screen and gdm starts complaining with "Sorry, that didn't work.."
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [main] (0x0400): p11_child started.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): Module List:
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ^A] Manufacturer [PKCS#11 Kit                     ^A] flags [1] removable [false] token present [true].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ^A] Manufacturer [PKCS#11 Kit                     ^A] flags [1] removable [false] token present [true].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): common name: [netid].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ^F] Manufacturer [Alcor Micro AU9560 00 00        ^F] flags [6] removable [true] token present [false].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [do_card] (0x4000): Token not present.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [main] (0x0040): do_work failed.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8702]]]] [main] (0x0020): p11_child failed!
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [main] (0x0400): p11_child started.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [parse_cert_verify_opts] (0x4000): Found 'no_ocsp' option, disabling OCSP.
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): Module List:
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): common name: [p11-kit-trust].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): dll name: [/usr/lib64/pkcs11/p11-kit-trust.so].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): Description [/etc/pki/ca-trust/source                                        PKCS#11 Kit                     ^A] Manufacturer [PKCS#11 Kit                     ^A] flags [1] removable [false] token present [true].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): Description [/usr/share/pki/ca-trust-source                                  PKCS#11 Kit                     ^A] Manufacturer [PKCS#11 Kit                     ^A] flags [1] removable [false] token present [true].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): common name: [netid].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): dll name: [/usr/lib64/libiidp11.so].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): Description [Alcor Micro AU9560 00 00                                        Alcor Micro AU9560 00 00        ^F] Manufacturer [Alcor Micro AU9560 00 00        ^F] flags [6] removable [true] token present [false].
(Fri Jan 31 15:48:15 2020) [[sssd[p11_child[8707]]]] [do_card] (0x4000): Token not present.
(Fri Jan 31 15:48:16 2020) [[sssd[p11_child[8707]]]] [main] (0x0040): do_work failed.
(Fri Jan 31 15:48:16 2020) [[sssd[p11_child[8707]]]] [main] (0x0020): p11_child failed!
(Fri Jan 31 15:48:20 2020) [[sssd[p11_child[8849]]]] [main] (0x0400): p11_child started.
(Fri Jan 31 15:48:20 2020) [[sssd[p11_child[8849]]]] [main] (0x2000): Running in [pre-auth] mode.



sssd_pam.log
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[102] pid[8693].
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x5565f9d550b0][25]
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected!
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [sss_domain_get_state] (0x1000): Domain ad.example.com is Active
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'a001329' matched without domain, user is a001329
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): user: a001329
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): service: gdm-smartcard
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/tty2
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 0
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 8693
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): logon name: a001329
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_print_data] (0x0100): flags: 322
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_callback": 0x5565f9d55e80

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_timeout": 0x5565f9d6c7d0

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x5565f9d55e80 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d6c7d0 "ldb_kv_timeout"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d55e80 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_callback": 0x5565f9d7fda0

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_timeout": 0x5565f9d55e80

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x5565f9d7fda0 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d55e80 "ldb_kv_timeout"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d7fda0 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_callback": 0x5565f9d56920

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_timeout": 0x5565f9d7fda0

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x5565f9d56920 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d7fda0 "ldb_kv_timeout"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d56920 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_callback": 0x5565f9d7e770

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_timeout": 0x5565f9d56920

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x5565f9d7e770 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d56920 "ldb_kv_timeout"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d7e770 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [8702]
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [child_handler_setup] (0x2000): Signal handler set up for pid [8702]
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [read_pipe_handler] (0x0400): EOF received, client finished
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [parse_p11_child_response] (0x1000): No certificate found.
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_forwarder_cert_cb] (0x4000): try_cert_auth flag set but no certificate available, request finished.
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_callback": 0x5565f9d6c7d0

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_timeout": 0x5565f9d7e770

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x5565f9d6c7d0 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d7e770 "ldb_kv_timeout"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d6c7d0 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_reply] (0x4000): pam_reply initially called with result [9]: Authentication service cannot retrieve authentication info. this result might be changed during processing
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [pam_reply] (0x0040): Assuming offline authentication setting status for pam call 249 to PAM_SUCCESS.
(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_callback": 0x5565f9d6c7d0

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_timeout": 0x5565f9d7e770

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x5565f9d6c7d0 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d7e770 "ldb_kv_timeout"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d6c7d0 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_callback": 0x5565f9d55e80

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ldb_kv_timeout": 0x5565f9d6c7d0

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x5565f9d55e80 "ldb_kv_callback"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d6c7d0 "ldb_kv_timeout"

(Fri Jan 31 15:48:15 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x5565f9d55e80 "ldb_kv_callback"
Comment 36 adam winberg 2020-01-31 15:31:59 UTC 
Actually, it seems to work on first login but not when i remove the smartcard and locking the gnome session. Bringing up the gdm unlock page without entering the smartcard results in the error messages. 

But on the gdm login page I can't see the error anymore.
Comment 37 Sumit Bose 2020-01-31 15:58:04 UTC 
Hi,

is the error message after removing the card displayed only once or in regular intervals? Can you attach to corresponding pam log from the journal or /var/log/secure as well?

bye,
Sumit
Comment 38 adam winberg 2020-01-31 16:30:10 UTC 
It's displayed in regular intervals. I'll have to get back to you regarding logs after the weekend!
Comment 39 adam winberg 2020-02-03 06:19:16 UTC 
Pam logs when locking gnome session and gdm 'waits' for smart card:
Feb  3 07:14:27 c21637 gdm-smartcard][10573]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 Instant EID IP9
Feb  3 07:14:27 c21637 gdm-smartcard][10573]: gkr-pam: no password is available for user
Feb  3 07:14:31 c21637 gdm-smartcard][10691]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 Instant EID IP9
Feb  3 07:14:31 c21637 gdm-smartcard][10691]: gkr-pam: no password is available for user
Feb  3 07:14:36 c21637 gdm-smartcard][10816]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 Instant EID IP9
Feb  3 07:14:36 c21637 gdm-smartcard][10816]: gkr-pam: no password is available for user
Comment 40 Sumit Bose 2020-02-06 14:45:20 UTC 
Created attachment 1658229 [details]
2nd test build

Hi,

please find attached another test build. It looks like when in unlocking mode gdm does not run with UID 0 but not with GID 0 which is currently required to request SSSD to wait for the card. I relaxed the check in the test build.

HTH

bye,
Sumit
Comment 41 adam winberg 2020-02-07 06:12:35 UTC 
Tested and it works - good work finding the cause for that.
Comment 44 Sumit Bose 2020-02-19 11:55:16 UTC 
Upstream ticket:
https://pagure.io/SSSD/sssd/issue/4159
Comment 46 Sumit Bose 2020-02-24 12:01:55 UTC 
Upstream:

    master
        37780b8 - PAM client: only require UID 0 for private socket
        7b64733 - p11_child: check if card is present in wait_for_car
Comment 54 Scott Poore 2020-03-02 17:07:25 UTC 
Verified.

Version ::

sssd-2.2.3-17.el8.x86_64

Results ::

First reproducing with sssd-2.2.3-13.el8.x86_64

Setup IPA Smart Card Authentication 

Setup GDM on client

Setup Smart Card setting for autoselect:

authselect enable-feature with-smartcard-required
authselect enable-feature with-smartcard-lock-on-removal
systemctl stop sssd; rm -rf /var/lib/sss/{db,mc}/*; systemctl start sssd

Login with PIN and userhint (ipauser1)

Remove Smart Card while watching /var/log/secure in another window:

Mar  2 10:48:11 client gdm-smartcard][5161]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)
Mar  2 10:48:15 client gdm-smartcard][5172]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)
Mar  2 10:48:19 client gdm-smartcard][5181]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)
Mar  2 10:48:24 client gdm-smartcard][5193]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)
Mar  2 10:48:28 client gdm-smartcard][5205]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)
Mar  2 10:48:32 client gdm-smartcard][5217]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)
Mar  2 10:48:37 client gdm-smartcard][5226]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)
^C

When Screensaver appears trigger login and I see:

Please enter smart card labeled...
Sorry that didn't work, please try again

looping every few seconds.

Now to verify the fix with sssd-2.2.3-17.el8.x86_64


dnf update sssd
...

Now remove card with GDM login screen up:

Mar  2 11:01:48 client gdm-smartcard][30829]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card

Enter card and login with pin and username hint (ipauser1):

Mar  2 11:02:20 client gdm-smartcard][30829]: pam_sss(gdm-smartcard:auth): authentication success; logname= uid=0 euid=0 tty=/dev/tty1 ruser= rhost= user=ipauser1
Mar  2 11:02:20 client systemd[30848]: pam_unix(systemd-user:session): session opened for user ipauser1 by (uid=0)
Mar  2 11:02:20 client gdm-smartcard][30829]: pam_unix(gdm-smartcard:session): session opened for user ipauser1 by (uid=0)
Mar  2 11:02:24 client polkitd[863]: Registered Authentication Agent for unix-session:4 (system bus name :1.285 [/usr/bin/gnome-shell], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)


Remove card:

Screen locks

Swipe up to trigger login prompt

Please enter smart card labeled...

Mar  2 11:04:13 client gdm-smartcard][31577]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)

I do not see sorry that didn't work loop.

Click cancel:

Mar  2 11:04:57 client gdm-smartcard][31601]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)

Swipe up:

Mar  2 11:05:00 client gdm-smartcard][31613]: pam_sss(gdm-smartcard:auth): User info message: Please enter smart card labeled#012 sctest (MyEID)

Insert Card, enter pin:

Mar  2 11:06:29 client gdm-smartcard][31613]: pam_sss(gdm-smartcard:auth): authentication success; logname=ipauser1 uid=0 euid=0 tty=/dev/tty2 ruser= rhost= user=ipauser1
Comment 65 errata-xmlrpc 2020-04-28 16:56:02 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:1863