Bug 1729928
| Summary: | Failed to enable Smartcard authentication on Redhat 8 | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Linux 8 | Reporter: | NingYu <yun> | ||||||||||
| Component: | sssd | Assignee: | SSSD Maintainers <sssd-maint> | ||||||||||
| Status: | CLOSED NOTABUG | QA Contact: | sssd-qe <sssd-qe> | ||||||||||
| Severity: | urgent | Docs Contact: | |||||||||||
| Priority: | unspecified | ||||||||||||
| Version: | 8.4 | CC: | atikhono, grajaiya, jhrozek, lslebodn, mzidek, pbrezina, tscherf | ||||||||||
| Target Milestone: | rc | ||||||||||||
| Target Release: | 8.0 | ||||||||||||
| Hardware: | x86_64 | ||||||||||||
| OS: | Linux | ||||||||||||
| Whiteboard: | |||||||||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||||||||
| Doc Text: | Story Points: | --- | |||||||||||
| Clone Of: | Environment: | ||||||||||||
| Last Closed: | 2019-07-26 08:19:43 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: | |||||||||||||
| Attachments: |
|
||||||||||||
|
Description
NingYu
2019-07-15 10:48:26 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. Created attachment 1591004 [details]
sssd logs
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 hi do you have any update on this issue? 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? hi, thanks for your comments, it's only typo. we use "with-smartcard" as the parameter. 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. 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. (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. Created attachment 1592556 [details]
sssd logs
the date output: Mon Jul 22 06:35:59 EDT 2019 and note that, we are testing rhel8 in a vmware workstation virtual machine. 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. 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]
(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].
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 (Tue Jul 23 05:46:38 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: Checking negative cache for [CERT:kEphgU83nE] (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] 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] 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] 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] 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? (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. 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. 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.
(In reply to NingYu from comment #18) > My card user is mapping to a domain user. Is this - rzview-sc2 - 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. (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... thanks your comments. I looks like this machine has domain issues. Smart card works after rejoining the domain. |