There is no entry in the syslogs of pcscd whatsoever. It is installed though. p11_child
--pre ... does read the certificate from the yubikey.
I missed that krb5_child is called twice upon a single login attempt. Comparing the log of
krb5_child between 1.15.2 and 1.16.1 shows that the tokentype is different:
SSS_AUTHTOK_TYPE_SC_PIN in 1.15.2, SSS_AUTHTOK_TYPE_PASSWORD in 1.16.1.
I am prompted for a password in 1.16.1.
The krb5-pkinit package is installed. kinit utilzes the yubikey.
The following is krb5_child.log for a failed login attempt. I have inserted trace-output
about cmd and tokentype in answer_pkinit.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [main] (0x0400): krb5_child
started.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [unpack_buffer] (0x1000): total
buffer size: [146]
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [unpack_buffer] (0x0100): cmd [249]
uid [3034] gid [3001] validate [false] enterprise principal [false] offline [false] UPN
[user@DOMAIN]
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [unpack_buffer] (0x0100): ccname:
[FILE:/tmp/krb5cc_3034_XXXXXX] old_ccname: [FILE:/tmp/krb5cc_3034_XXXXXX] keytab:
[/etc/krb5.keytab]
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [check_use_fast] (0x0100): Not
using FAST.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [privileged_krb5_setup] (0x0080):
Cannot open the PAC responder socket
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [become_user] (0x0200): Trying to
become user [3034][3001].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [main] (0x2000): Running as
[3034][3001].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [become_user] (0x0200): Trying to
become user [3034][3001].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [become_user] (0x0200): Already
user [3034].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [k5c_setup] (0x2000): Running as
[3034][3001].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [set_lifetime_options] (0x0100): No
specific renewable lifetime requested.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [set_lifetime_options] (0x0100): No
specific lifetime requested.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [set_canonicalize_option] (0x0100):
Canonicalization is set to [false]
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [main] (0x0400): Will perform
pre-auth
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [tgt_req_child] (0x1000):
Attempting to get a TGT
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [get_and_save_tgt] (0x0400):
Attempting kinit for realm [DOMAIN]
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570173: Getting initial credentials for user@DOMAIN
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570175: Sending unauthenticated request
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570176: Sending request (174 bytes) to DOMAIN
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570177: Sending initial UDP request to dgram 10.36.125.234:88
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570178: Received answer (364 bytes) from dgram 10.36.125.234:88
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570179: Response was from master KDC
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570180: Received error from KDC: -1765328359/Additional
pre-authentication required
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570183: Preauthenticating using KDC method data
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570184: Processing preauth types: 16, 15, 14, 136, 19, 147, 2, 133
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570185: Selected etype info: etype aes256-cts, salt
"DOMAINuser", params ""
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570186: Received cookie: MIT
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_krb5_responder] (0x4000): Got
question [pkinit].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [answer_pkinit] (0x4000): [0]
Identity [PKCS11:module_name=/usr/lib/x86_64-linux-gnu/opensc-pkcs11.so:slotid=0:token=PIV
Card Holder pin (PIV_II)] flags [0].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [answer_pkinit] (0x4000): Setting
pkinit_prompting.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [answer_pkinit] (0x4000): cmd =
249
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [answer_pkinit] (0x4000): authtok =
0
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570187: Preauth module pkinit (147) (info) returned: 0/Success
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_krb5_prompter] (0x4000):
sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_krb5_prompter] (0x4000):
Prompt [0][PIV Card Holder pin (PIV_II) PIN].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_krb5_prompter] (0x0020):
Cannot handle password prompts.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570188: PKINIT client has no configured identity; giving up
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570189: Preauth module pkinit (16) (real) returned:
-1765328360/Preauthentication failed
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570190: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570191: Preauth module pkinit (15) (real) returned:
-1765328360/Preauthentication failed
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570192: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570193: Preauth module pkinit (14) (real) returned:
-1765328360/Preauthentication failed
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_krb5_prompter] (0x4000):
sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_krb5_prompter] (0x4000):
Prompt [0][Password for user@DOMAIN].
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_krb5_prompter] (0x0020):
Cannot handle password prompts.
(Fri Dec 7 17:27:18 2018) [[sssd[krb5_child[19899]]]] [sss_child_krb5_trace_cb] (0x4000):
[19899] 1544200038.570194: Preauth module encrypted_timestamp (2) (real) returned:
-1765328254/Cannot read password
(Fri Dec 7 17:27:19 2018) [[sssd[krb5_child[19899]]]] [get_and_save_tgt] (0x0400):
krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(Fri Dec 7 17:27:19 2018) [[sssd[krb5_child[19899]]]] [k5c_send_data] (0x0200): Received
error code 0
(Fri Dec 7 17:27:19 2018) [[sssd[krb5_child[19899]]]] [pack_response_packet] (0x2000):
response packet size: [12]
(Fri Dec 7 17:27:19 2018) [[sssd[krb5_child[19899]]]] [k5c_send_data] (0x4000): Response
sent.
(Fri Dec 7 17:27:19 2018) [[sssd[krb5_child[19899]]]] [main] (0x0400): krb5_child
completed successfully
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [main] (0x0400): krb5_child
started.
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [unpack_buffer] (0x1000): total
buffer size: [154]
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [unpack_buffer] (0x0100): cmd [241]
uid [3034] gid [3001] validate [false] enterprise principal [false] offline [false] UPN
[user@DOMAIN]
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [unpack_buffer] (0x0100): ccname:
[FILE:/tmp/krb5cc_3034_XXXXXX] old_ccname: [FILE:/tmp/krb5cc_3034_XXXXXX] keytab:
[/etc/krb5.keytab]
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [check_use_fast] (0x0100): Not
using FAST.
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [old_ccache_valid] (0x0400): Saved
ccache FILE:/tmp/krb5cc_3034_XXXXXX doesn't exist, ignoring
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [k5c_check_old_ccache] (0x4000):
Ccache_file is [FILE:/tmp/krb5cc_3034_XXXXXX] and is not active and TGT is not valid.
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [k5c_precreate_ccache] (0x4000):
Recreating ccache
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [privileged_krb5_setup] (0x0080):
Cannot open the PAC responder socket
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [become_user] (0x0200): Trying to
become user [3034][3001].
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [main] (0x2000): Running as
[3034][3001].
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [become_user] (0x0200): Trying to
become user [3034][3001].
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [become_user] (0x0200): Already
user [3034].
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [k5c_setup] (0x2000): Running as
[3034][3001].
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [set_lifetime_options] (0x0100): No
specific renewable lifetime requested.
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [set_lifetime_options] (0x0100): No
specific lifetime requested.
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [set_canonicalize_option] (0x0100):
Canonicalization is set to [false]
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [main] (0x0400): Will perform
online auth
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [tgt_req_child] (0x1000):
Attempting to get a TGT
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [get_and_save_tgt] (0x0400):
Attempting kinit for realm [DOMAIN]
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663098: Getting initial credentials for user@DOMAIN
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663100: Sending unauthenticated request
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663101: Sending request (174 bytes) to DOMAIN
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663102: Sending initial UDP request to dgram 10.36.125.234:88
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663103: Received answer (364 bytes) from dgram 10.36.125.234:88
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663104: Response was from master KDC
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663105: Received error from KDC: -1765328359/Additional
pre-authentication required
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663108: Preauthenticating using KDC method data
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663109: Processing preauth types: 16, 15, 14, 136, 19, 147, 2, 133
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663110: Selected etype info: etype aes256-cts, salt
"DOMAINuser", params ""
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663111: Received cookie: MIT
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_krb5_responder] (0x4000): Got
question [pkinit].
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [answer_pkinit] (0x4000): [0]
Identity [PKCS11:module_name=/usr/lib/x86_64-linux-gnu/opensc-pkcs11.so:slotid=0:token=PIV
Card Holder pin (PIV_II)] flags [0].
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [answer_pkinit] (0x4000): Setting
pkinit_prompting.
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [answer_pkinit] (0x4000): cmd =
241
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [answer_pkinit] (0x4000): authtok =
1
(Fri Dec 7 17:27:23 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200043.663112: Preauth module pkinit (147) (info) returned: 0/Success
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_krb5_prompter] (0x4000):
sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_krb5_prompter] (0x4000):
Prompt [0][PIV Card Holder pin (PIV_II) PIN].
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_krb5_prompter] (0x0020):
Cannot handle password prompts.
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200044.136917: PKINIT client has no configured identity; giving up
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200044.136918: Preauth module pkinit (16) (real) returned:
-1765328360/Preauthentication failed
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200044.136919: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200044.136920: Preauth module pkinit (15) (real) returned:
-1765328360/Preauthentication failed
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200044.136921: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200044.136922: Preauth module pkinit (14) (real) returned:
-1765328360/Preauthentication failed
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_krb5_prompter] (0x4000):
sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_krb5_prompter] (0x4000):
Prompt [0][Password for user@DOMAIN].
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_krb5_prompter] (0x0020):
Cannot handle password prompts.
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [sss_child_krb5_trace_cb] (0x4000):
[19902] 1544200044.136923: Preauth module encrypted_timestamp (2) (real) returned:
-1765328254/Cannot read password
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [get_and_save_tgt] (0x0020): 1702:
[-1765328174][Pre-authentication failed: Preauthentication failed]
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [map_krb5_error] (0x0020): 1815:
[-1765328174][Pre-authentication failed: Preauthentication failed]
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [k5c_send_data] (0x0200): Received
error code 1432158221
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [pack_response_packet] (0x2000):
response packet size: [4]
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [k5c_send_data] (0x4000): Response
sent.
(Fri Dec 7 17:27:24 2018) [[sssd[krb5_child[19902]]]] [main] (0x0400): krb5_child
completed successfully