Hide Forgot
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 ~
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@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].
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?
(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@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.
(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.