Bug 1729928 - Failed to enable Smartcard authentication on Redhat 8
Summary: Failed to enable Smartcard authentication on Redhat 8
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: sssd
Version: 8.4
Hardware: x86_64
OS: Linux
unspecified
urgent
Target Milestone: rc
: 8.0
Assignee: SSSD Maintainers
QA Contact: sssd-qe
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-07-15 10:48 UTC by NingYu
Modified: 2019-07-26 08:19 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-07-26 08:19:43 UTC
Type: Bug
Target Upstream Version:


Attachments (Terms of Use)
sssd logs (250.43 KB, application/zip)
2019-07-16 09:07 UTC, NingYu
no flags Details
sssd logs (36.13 KB, application/zip)
2019-07-22 10:41 UTC, NingYu
no flags Details
sssd logs 7-23 (48.36 KB, application/zip)
2019-07-23 09:59 UTC, NingYu
no flags Details
sssd logs 7-24 (82.09 KB, application/zip)
2019-07-24 10:17 UTC, NingYu
no flags Details

Description NingYu 2019-07-15 10:48:26 UTC
Description of problem:
Failed to enable Smartcard authentication on Redhat 8

We followed https://access.redhat.com/articles/4253861 to setup the smartcard authentication environment, expect the greeter prompts PIN code, user could logon  the desktop successfully after input the correct PIN code, but the greeter directly prompting the password, showing "Sorry, that did't work. Please try again" and flushing(it looks like the authentication startup in the background repeatedly and always fails).

Version-Release number of selected component (if applicable):


How reproducible:



Steps to Reproduce:


On Redhat 7, smartcard works well, the following is what we do on Redhat 8:

1. Join AD following https://access.redhat.com/articles/3023951, but replace "authconfig --update --enablesssd --enablesssdauth --enablemkhomedir" with "authselect select sssd with-smartcad";
2. Add certificate to nss database by "certutil -A -d /etc/pki/nssdb -n "root CA cert" -t "CT,C,C" -i certificate.pem";
3. add pkcs11 library to nss database by "modutil -add "piv card 2.0" -libfile /usr/lib64/libcmP11.so -dbdir /etc/pki/nssdb/";
4. Config sssd.conf;


Actual results:
the greeter directly prompting the password, showing "Sorry, that did't work. Please try again"

Expected results:
the greeter prompts PIN code, user could logon

Additional info:

The following the sssd.conf:
~
[sssd]
config_file_version = 2
domains = rzview2.com
services = nss, pam, pac

[domain/RZVIEW2.COM]
debug_level = 0x1310
id_provider = ad
auth_provider = ad
chpass_provider = ad
access_provider = ad

cache_credentials = true

[domain/shadowutils]
id_provider = ad

[pam]
pam_cert_auth = True
~

GDM log shows that user is null:
~
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmManager: trying to open new session
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmDBusServer: new connection 0x7f1dcc0431c0
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Handling new connection from outside
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmManager: client connected
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmDisplay: Got timed login details for display: 0
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: starting conversation gdm-smartcard
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSessionWorkerJob: Starting worker...
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSessionWorkerJob: Running session_worker_job process: gdm-session-worker [pam/gdm-smartcard] /usr/libexec/gdm-session-worker
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSessionWorkerJob: : SessionWorkerJob on pid 3087
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: Enabling debugging
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: connecting to address: unix:abstract=/tmp/dbus-2jLjANh6
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmDBusServer: new connection 0x7f1dcc04de00
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Handling new connection from worker
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Authenticating new connection
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: worker connection is 0x7f1dcc04de00
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Emitting conversation-started signal
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmManager: session conversation started for service gdm-smartcard
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: getting session command for file 'gnome.desktop'
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: checking if file 'gnome.desktop' is wayland session: yes
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: setting session to type 'wayland'
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Beginning initialization
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: getting session command for file 'gnome.desktop'
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: checking if file 'gnome.desktop' is wayland session: yes
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: getting session command for file 'gnome.desktop'
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Conversation started
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: AccountsService: ActUserManager: system OS is 'rhel'
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: AccountsService: ActUserManager: system OS version is '8.0'
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: AccountsService: Failed to identify the current session: No data available
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: AccountsService: ActUserManager: seat unloaded, so trying to set loaded property
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: AccountsService: ActUserManager: Seat wouldn't load, so giving up on it and setting loaded property
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: AccountsService: ActUserManager: already loaded, so not setting loaded property
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: attempting to change state to SETUP_COMPLETE
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: initializing PAM; service=gdm-smartcard username=(null) seat=seat0
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: Set PAM environment variable: 'XDG_SEAT=seat0'
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: state SETUP_COMPLETE
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: attempting to change state to AUTHENTICATED
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: authenticating user (null)
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: authentication returned 7: Authentication failure
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: uninitializing PAM
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: jumping to VT 1
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: first setting graphics mode to prevent flicker
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: couldn't set graphics mode: Inappropriate ioctl for device
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: VT mode did not need to be fixed
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: couldn't manage VTs manually: Inappropriate ioctl for device
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: couldn't initiate jump to VT 1: Inappropriate ioctl for device
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: state NONE
Jul 12 17:31:53 rhel8sc gdm-smartcard][3087]: GdmSessionWorker: Unable to verify user
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: stopping conversation gdm-smartcard
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSessionWorkerJob: Stopping job pid:3087
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmCommon: sending signal 15 to process 3087
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSessionWorkerJob: child (pid:3087) done (status:0)
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Worker job exited: 0
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmSession: Emitting conversation-stopped signal
Jul 12 17:31:53 rhel8sc gdm[1077]: GdmManager: session conversation 'gdm-smartcard' stopped
~

Comment 1 Alexey Tikhonov 2019-07-15 11:22:30 UTC
Hi,

Would you please attach corresponding `sssd_pam.log`, `p11_child.log`, `sssd_RZVIEW2.COM.log` and `krb5_child.log` with debug level set to 10?
(Sensitive information may be removed or attachment marked as private)

For details how to set debug level, please refer to https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html "SSSD debug logs" section.

Comment 2 NingYu 2019-07-16 09:07:40 UTC
Created attachment 1591004 [details]
sssd logs

Comment 3 NingYu 2019-07-16 09:11:16 UTC
hi,
Attachment is the logs, but the p11_child.log and krb5_child.log is empty. It looks sssd don't call p11 module.

I update my sssd.conf with the p11_uri.

[sssd]
config_file_version = 2
domains = rzview2.com
services = nss, pam, pac

[domain/RZVIEW2.COM]
debug_level = 10
id_provider = ad
auth_provider = ad
chpass_provider = ad
access_provider = ad
cache_credentials = true


[pam]
pam_cert_auth = True
p11_uri = pkcs11:model=Gemalto%20TOP%20D...;manufacturer=;serial=;token=Gemalto%20TOP%20DL%20V2%20PIV%20profile

Comment 4 NingYu 2019-07-18 08:37:56 UTC
hi do you have any update on this issue?

Comment 5 Pavel Březina 2019-07-18 09:30:24 UTC
Hi, 'authselect select sssd with-smartcad' with-smartcad is not a valid option, it should be 'with-smartcard'. Is this only a typo in bugzilla or perhaps you configured your system like this? What does 'authselect current' show?

Comment 6 NingYu 2019-07-18 10:52:47 UTC
hi, thanks for your comments, it's only typo. we use "with-smartcard" as the parameter.

Comment 7 Pavel Březina 2019-07-19 07:40:56 UTC
Sumit, our expert on smartcard integration is currently on vacation and I do not know much about it. But RHEL transitioned from nss to openssl in RHEL8 and the default ca database path has thus changed to        /etc/sssd/pki/sssd_auth_ca_db.pem. So perhaps this is the issue, see pam_cert_db_path option in manual page.

The logs are unfortunately insufficient, please set debug_level = 10 also in [pam] section.

Comment 8 NingYu 2019-07-19 09:41:25 UTC
hi , i already put the ca to /etc/sssd/pki/ folder, and see comment #2, i already set the debug_level =10, this log still insufficient.

Comment 9 Alexey Tikhonov 2019-07-19 09:49:18 UTC
(In reply to NingYu from comment #8)
> hi , i already put the ca to /etc/sssd/pki/ folder, and see comment #2, i
> already set the debug_level =10, this log still insufficient.

Would you please:
1) include 'debug_level = 10' option in both [domain/RZVIEW2.COM] and [pam] sections of /etc/sssd.conf
2) systemctl stop sssd
3) rm or backup (if you need it) /var/log/sssd/*
4) systemctl start sssd
5) date
6) attempt SC auth
7) attach resulting logs + output of 'date'

Thank you.

Comment 10 NingYu 2019-07-22 10:41:44 UTC
Created attachment 1592556 [details]
sssd logs

Comment 11 NingYu 2019-07-22 10:42:48 UTC
the date output:  Mon Jul 22 06:35:59 EDT 2019

Comment 12 NingYu 2019-07-22 10:43:50 UTC
and note that, we are testing rhel8 in a vmware workstation virtual machine.

Comment 13 NingYu 2019-07-23 08:44:46 UTC
hi, i found the failures in p11_child, is it cert configuration issue?

(Mon Jul 22 06:36:07 2019) [[sssd[p11_child[2724]]]] [init_verification] (0x0040): X509_LOOKUP_load_file failed [33558530][error:02001002:system library:fopen:No such file or directory].
(Mon Jul 22 06:36:07 2019) [[sssd[p11_child[2724]]]] [do_work] (0x0040): init_verification failed.

Comment 14 NingYu 2019-07-23 09:59:12 UTC
Created attachment 1592851 [details]
sssd logs 7-23

upload new logs, the output of date:  Tue Jul 23 05:46:24 EDT 2019

I change the cert name to "sssd_auth_ca_db.pem" under /etc/sssd/pki/ folder, and then do SC auth, but the greeter still show password dialog, and input the correct pin code, can't be able to login.


from the p11.log, it looks like found the card and keys.

(Tue Jul 23 05:46:37 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): dll name: [/usr/lib64/libcmP11.so].
(Tue Jul 23 05:46:37 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): Description [ActivIdentity USB Reader V3 [CCID Interface] 00 00              ActivIdentity USB Reader V3 [...] Manufacturer [ActivIdentity USB Reader V3 [...] flags [7] removable [true] token present [true].
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): Token label [Gemalto TOP DL V2 PIV profile                                   Gemalto TOP D...                
].
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): Found [Gemalto TOP DL V2 PIV profile] in slot [ActivIdentity USB Reader V3 [CCID Interface] 00 00][1] of module [2][/usr/lib64/libcmP11.so].
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): Login NOT required.
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [read_certs] (0x4000): found cert[te-SmartcardUserRZVIEW2-3bb7ee27-5476-477e-8117-65c26bc1f24a][/DC=com/DC=rzview2/OU=rhel75sc/CN=rzview sc2/emailAddress=rzview-sc2@rzview2.com]
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [do_ocsp] (0x0020): No OCSP URL in certificate and no default responder defined, skipping OCSP check.
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): (null) /usr/lib64/libcmP11.so (null) Gemalto TOP DL V2 PIV profile (null) 74652D536D6172746361726455736572525A56494557322D33626237656532372D353437362D343737652D383131372D363563323662633166323461.
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): uri: pkcs11:library-description=cm%20PKCS%2311%20module;library-manufacturer=charismathics%20gmbh;library-version=5.0;slot-description=ActivIdentity%20USB%20Reader%20V3%20%5bCCID%20Interface%5d%2000%2000;slot-manufacturer=ActivIdentity%20USB%20Reader%20V3%20%5b...;slot-id=1;model=Gemalto%20TOP%20D...;manufacturer=;serial=;token=Gemalto%20TOP%20DL%20V2%20PIV%20profile;id=%74%65%2d%53%6d%61%72%74%63%61%72%64%55%73%65%72%52%5a%56%49%45%57%32%2d%33%62%62%37%65%65%32%37%2d%35%34%37%36%2d%34%37%37%65%2d%38%31%31%37%2d%36%35%63%32%36%62%63%31%66%32%34%61;object=te-SmartcardUserRZVIEW2-3bb7ee27-5476-477e-8117-65c26bc1f24a;type=cert.
(Tue Jul 23 05:46:38 2019) [[sssd[p11_child[3113]]]] [do_card] (0x4000): Found certificate has key id [74652D536D6172746361726455736572525A56494557322D33626237656532372D353437362D343737652D383131372D363563323662633166323461].

Comment 15 Alexey Tikhonov 2019-07-23 15:15:09 UTC
Hello,

Sorry for not responding long time.


(In reply to NingYu from comment #13)
> hi, i found the failures in p11_child, is it cert configuration issue?
> 
> (Mon Jul 22 06:36:07 2019) [[sssd[p11_child[2724]]]] [init_verification]
> (0x0040): X509_LOOKUP_load_file failed [33558530][error:02001002:system
> library:fopen:No such file or directory].

This indicates fail to load cert db with CA cert.


(In reply to NingYu from comment #14)
> I change the cert name to "sssd_auth_ca_db.pem" under /etc/sssd/pki/ folder,

This path can be configured with [pam] 'pam_cert_db_path' option (see sssd.conf(5))

'/etc/sssd/pki/sssd_auth_ca_db.pem' is default for OpenSSL (RHEL8) build.


> and then do SC auth, but the greeter still show password dialog, and input
> the correct pin code, can't be able to login.


The problem is sssd_pam failed to lookup this cert.

According to the log, it checks implicit_files (not found, naturally) and then checks ad-provider:
```
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #0: Using domain [RZVIEW2.COM]
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #0: Looking up CERT:kEphgU83nE@RZVIEW2.COM
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: Checking negative cache for [CERT:kEphgU83nE@RZVIEW2.COM]
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/CERT...]
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: [CERT:kEphgU83nE@RZVIEW2.COM] is not present in negative cache
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0: Looking up [CERT:kEphgU83nE@RZVIEW2.COM] in cache
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [sysdb_search_object_attr] (0x0400): No such entry.
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [sysdb_search_user_by_cert_with_views] (0x0040): sysdb_search_user_by_cert failed.
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0: Object [CERT:kEphgU83nE@RZVIEW2.COM] was not found in cache
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #0: Looking up [CERT:kEphgU83nE@RZVIEW2.COM] in data provider
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [sss_dp_get_account_send] (0x0400): Creating request for [RZVIEW2.COM][0x14][BE_REQ_BY_CERT [cert=MIIG0TCC...U83nE:-]
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [sbus_reply_check] (0x4000): D-Bus error [org.freedesktop.DBus.Error.Disconnected]: SSSD is offline
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_common_process_dp_reply] (0x0040): CR #0: Could not get account info [1432158212]: SSSD is offline
(Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_common_process_dp_reply] (0x0400): CR #0: Due to an error we will return cached data
```

The same requested being served by ad-provider:
```
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [dp_get_account_info_send] (0x0200): Got request for [0x14][BE_REQ_BY_CERT][cert=MIIG0...83nE]
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [dp_attach_req] (0x0400): DP Request [Account #5]: New request. Flags [0x0001].
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [dp_attach_req] (0x0400): Number of active DP request: 1
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [sss_domain_get_state] (0x1000): Domain RZVIEW2.COM is Active
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [_dp_req_recv] (0x0400): DP Request [Account #5]: Receiving request data.
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [dp_req_destructor] (0x0400): DP Request [Account #5]: Request removed.
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline
(Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [sbus_dispatch] (0x4000): Dispatching.
```


So either:
1) it was a sporatic dbus problem and you was "lucky" to hit it
or
2) there is a bug in sbus impl (new in RHEL8) triggered by this specific payload (this cert)


NingYu, could you please repeat your attempt several time and check if those "org.freedesktop.DBus.Error.Disconnected" in sssd_pam and "sssd.dataprovider.getAccountInfo: Error ...: SSSD is offline" are persistent?

Comment 16 Alexey Tikhonov 2019-07-23 18:28:24 UTC
(In reply to Alexey Tikhonov from comment #15)
> The problem is sssd_pam failed to lookup this cert.
> 
> According to the log, it checks implicit_files (not found, naturally) and
> then checks ad-provider:
> ```
> (Tue Jul 23 05:46:38 2019) [sssd[pam]] [sbus_reply_check] (0x4000): D-Bus
> error [org.freedesktop.DBus.Error.Disconnected]: SSSD is offline
> ```
> 
> The same requested being served by ad-provider:
> ```
> (Tue Jul 23 05:46:38 2019) [sssd[be[RZVIEW2.COM]]] [sbus_issue_request_done]
> (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is
> offline
> ```
> 
> 
> So either:
> 1) it was a sporatic dbus problem and you was "lucky" to hit it
> or
> 2) there is a bug in sbus impl (new in RHEL8) triggered by this specific
> payload (this cert)
> 
> 

I am sorry, my bad.
As Jakub pointed out, ad-provider is just offline.

It can be seen in the log:
```
(Tue Jul 23 05:46:37 2019) [sssd[be[RZVIEW2.COM]]] [ad_subdomains_refresh_connect_done] (0x0020): Unable to connect to LDAP [11]: Resource temporarily unavailable
(Tue Jul 23 05:46:37 2019) [sssd[be[RZVIEW2.COM]]] [ad_subdomains_refresh_connect_done] (0x0080): No AD server is available, cannot get the subdomain list while offline
```
etc

Please, fix this issue first and then try SC auth again.

Comment 17 Jakub Hrozek 2019-07-23 19:13:08 UTC
Just to add some more context, this is why sssd is switching to offline mode:

(Tue Jul 23 05:46:37 2019) [[sssd[ldap_child[3118]]]] [ldap_child_get_tgt_sync] (0x0010): Failed to init credentials: Preauthentication failed
(Tue Jul 23 05:46:37 2019) [[sssd[ldap_child[3118]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_RZVIEW2.COM_gdo9S2]
(Tue Jul 23 05:46:37 2019) [[sssd[ldap_child[3118]]]] [main] (0x0020): ldap_child_get_tgt_sync failed.
(Tue Jul 23 05:46:37 2019) [[sssd[ldap_child[3118]]]] [prepare_response] (0x0400): Building response for result [-1765328360]

The keytab can't be used to auth to AD. Maybe re-enroll the client, looks like the machine password was rotated or such.

Comment 18 NingYu 2019-07-24 10:17:34 UTC
Created attachment 1593095 [details]
sssd logs 7-24

thanks for your comments. After re-join the ad, the input pin code greeter has shown up, but it fails to login even if inputting the correct pin code. 

From the logs, it shows the preauth failed. Is there any setting changes in /etc/pam.d/smartcard_auth?  looks like that this error related with pam. My card user is mapping to a domain user.

Comment 19 Alexey Tikhonov 2019-07-24 16:38:06 UTC
(In reply to NingYu from comment #18)

> My card user is mapping to a domain user.

Is this - rzview-sc2@rzview2.com - user you expect card to map to?



krb5_child.log:
```
(Wed Jul 24 05:58:41 2019) [[sssd[krb5_child[3151]]]] [main] (0x0400): Will perform pre-auth
...
(Wed Jul 24 05:58:43 2019) [[sssd[krb5_child[3151]]]] [answer_pkinit] (0x4000): Setting pkinit_prompting.
(Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]] [sss_krb5_prompter] (0x4000): Prompt [0][rzview sc2                       PIN].
(Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]] [sss_child_krb5_trace_cb] (0x4000): [3151] 1563962324.600170: PKINIT client has no configured identity; giving up
```

I am not sure if this ^^ is a problem.


But then:
```
(Wed Jul 24 05:58:52 2019) [[sssd[krb5_child[3154]]]] [main] (0x0400): krb5_child started.
...
(Wed Jul 24 05:58:52 2019) [[sssd[krb5_child[3154]]]] [main] (0x0400): Will perform online auth
...
(Wed Jul 24 05:58:56 2019) [[sssd[krb5_child[3154]]]] [answer_pkinit] (0x4000): Setting pkinit_prompting.
(Wed Jul 24 05:58:56 2019) [[sssd[krb5_child[3154]]]] [pkinit_identity_matches] (0x4000): Found [module_name=/usr/lib64/pkcs11/opensc-pkcs11.so] in identity [PKCS11:module_name=/usr/lib64/pkcs11/opensc-pkcs11.so:slotid=0:token=rzview sc2].
(Wed Jul 24 05:58:56 2019) [[sssd[krb5_child[3154]]]] [pkinit_identity_matches] (0x4000): Found [token=rzview sc2] in identity [PKCS11:module_name=/usr/lib64/pkcs11/opensc-pkcs11.so:slotid=0:token=rzview sc2].
(Wed Jul 24 05:58:58 2019) [[sssd[krb5_child[3154]]]] [sss_child_krb5_trace_cb] (0x4000): [3154] 1563962338.239561: PKINIT loading CA certs and CRLs from FILE
(Wed Jul 24 05:58:58 2019) [[sssd[krb5_child[3154]]]] [sss_child_krb5_trace_cb] (0x4000): [3154] 1563962338.239562: PKINIT client computed kdc-req-body checksum 9/1AD594B12511B664D86D1C218C55F5F89339479A
(Wed Jul 24 05:58:58 2019) [[sssd[krb5_child[3154]]]] [sss_child_krb5_trace_cb] (0x4000): [3154] 1563962338.239564: PKINIT client making DH request
```

and sssd_RZVIEW2.COM.log:
```
(Wed Jul 24 05:58:58 2019) [sssd[be[RZVIEW2.COM]]] [krb5_child_timeout] (0x0040): Timeout for child [3154] reached. In case KDC is distant or network is slow you may consider increasing value of krb5_auth_timeout.
(Wed Jul 24 05:58:58 2019) [sssd[be[RZVIEW2.COM]]] [krb5_auth_done] (0x0020): child timed out!
```

  --  this is definitely a problem.

Is it expected / are there reasons to have very slow auth process?
If so please try to increase krb5_auth_timeout and other relevant timeouts (may be pam_id_timeout should not be not less) and try again.

Comment 20 Alexey Tikhonov 2019-07-25 12:24:01 UTC
(In reply to Alexey Tikhonov from comment #19)
> krb5_child.log:
> ```
> (Wed Jul 24 05:58:41 2019) [[sssd[krb5_child[3151]]]] [main] (0x0400): Will
> perform pre-auth
> ...
> (Wed Jul 24 05:58:43 2019) [[sssd[krb5_child[3151]]]] [answer_pkinit]
> (0x4000): Setting pkinit_prompting.
> (Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]] [sss_krb5_prompter]
> (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1]
> EINVAL.
> (Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]] [sss_krb5_prompter]
> (0x4000): Prompt [0][rzview sc2                       PIN].
> (Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]] [sss_krb5_prompter]
> (0x0020): Cannot handle password prompts.
> (Wed Jul 24 05:58:44 2019) [[sssd[krb5_child[3151]]]]
> [sss_child_krb5_trace_cb] (0x4000): [3151] 1563962324.600170: PKINIT client
> has no configured identity; giving up
> ```
> 
> I am not sure if this ^^ is a problem.

It seems it is a problem: if preauth fails then PAM falls back to default auth method (password?). And this is not what you are trying to setup...

Comment 21 NingYu 2019-07-26 08:19:11 UTC
thanks your comments. I looks like this machine has domain issues. Smart card works after rejoining the domain.


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