Hi Sumit
I followed your instructions to the letter and managed to log on with a smart card twice.
Then on the third attempt it failed. This is what the krb5_child.log looks like:
(2021-05-22 21:39:08): [krb5_child[12908]] [main] (0x0400): krb5_child started.
(2021-05-22 21:39:08): [krb5_child[12908]] [unpack_buffer] (0x1000): total buffer size:
[208]
(2021-05-22 21:39:08): [krb5_child[12908]] [unpack_buffer] (0x0100): cmd [241 (auth)] uid
[57249832] gid [57200513] validate [true] enterprise principal [true] offline [false] UPN
[USERNAME(a)XXXXX.XXXXX.NET]
(2021-05-22 21:39:08): [krb5_child[12908]] [unpack_buffer] (0x0100): ccname: [KCM:]
old_ccname: [KCM:] keytab: [/etc/krb5.keytab]
(2021-05-22 21:39:08): [krb5_child[12908]] [check_use_fast] (0x0100): Not using FAST.
(2021-05-22 21:39:08): [krb5_child[12908]] [switch_creds] (0x0200): Switch user to
[57249832][57200513].
(2021-05-22 21:39:08): [krb5_child[12908]] [switch_creds] (0x0200): Switch user to
[0][0].
(2021-05-22 21:39:08): [krb5_child[12908]] [k5c_check_old_ccache] (0x4000): Ccache_file is
[KCM:] and is not active and TGT is valid.
(2021-05-22 21:39:08): [krb5_child[12908]] [k5c_precreate_ccache] (0x4000): Recreating
ccache
(2021-05-22 21:39:08): [krb5_child[12908]] [privileged_krb5_setup] (0x0080): Cannot open
the PAC responder socket
(2021-05-22 21:39:08): [krb5_child[12908]] [switch_creds] (0x0200): Switch user to
[0][0].
(2021-05-22 21:39:08): [krb5_child[12908]] [switch_creds] (0x0200): Already user [0].
(2021-05-22 21:39:08): [krb5_child[12908]] [main] (0x2000): Running as [0][0].
(2021-05-22 21:39:08): [krb5_child[12908]] [set_lifetime_options] (0x0100): No specific
renewable lifetime requested.
(2021-05-22 21:39:08): [krb5_child[12908]] [set_lifetime_options] (0x0100): No specific
lifetime requested.
(2021-05-22 21:39:08): [krb5_child[12908]] [set_canonicalize_option] (0x0100):
Canonicalization is set to [true]
(2021-05-22 21:39:08): [krb5_child[12908]] [main] (0x0400): Will perform auth
(2021-05-22 21:39:08): [krb5_child[12908]] [main] (0x0400): Will perform online auth
(2021-05-22 21:39:08): [krb5_child[12908]] [tgt_req_child] (0x1000): Attempting to get a
TGT
(2021-05-22 21:39:08): [krb5_child[12908]] [get_and_save_tgt] (0x4000): Found Smartcard
credentials, trying pkinit.
(2021-05-22 21:39:08): [krb5_child[12908]] [get_pkinit_identity] (0x4000): Got [IDPrime
(basic)][/usr/lib64/pkcs11/libiidp11.so].
(2021-05-22 21:39:08): [krb5_child[12908]] [get_pkinit_identity] (0x4000): Using pkinit
identity [PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:token=IDPrime
(basic):certid=C0538C6C20E35F51:certlabel=Letth Gary].
(2021-05-22 21:39:08): [krb5_child[12908]] [get_and_save_tgt] (0x0400): Attempting kinit
for realm [
XXXXX.XXXXX.NET]
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775336: Getting initial credentials for
USERNAME\@XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775338: Sending unauthenticated request
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775339: Sending request (236 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775340: Initiating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775341: Sending TCP request to stream 192.168.0.1:88
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775342: Received answer (207 bytes) from stream 192.168.0.1:88
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775343: Terminating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775344: Response was from master KDC
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775345: Received error from KDC: -1765328359/Additional pre-authentication
required
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775348: Preauthenticating using KDC method data
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775349: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15),
PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2)
(2021-05-22 21:39:08): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712348.775350: Selected etype info: etype aes256-cts, salt
"XXXXX.XXXXX.NETUSERNAME", params ""
(2021-05-22 21:39:09): [krb5_child[12908]] [sss_krb5_responder] (0x4000): Got question
[pkinit].
(2021-05-22 21:39:09): [krb5_child[12908]] [answer_pkinit] (0x4000): [0] Identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)] flags
[0].
(2021-05-22 21:39:09): [krb5_child[12908]] [answer_pkinit] (0x4000): Setting
pkinit_prompting.
(2021-05-22 21:39:09): [krb5_child[12908]] [pkinit_identity_matches] (0x4000): Found
[module_name=/usr/lib64/pkcs11/libiidp11.so] in identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)].
(2021-05-22 21:39:09): [krb5_child[12908]] [pkinit_identity_matches] (0x4000): Found
[token=IDPrime (basic)] in identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)].
(2021-05-22 21:39:09): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712349.768786: PKINIT loading CA certs and CRLs from FILE
(2021-05-22 21:39:09): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712349.768787: PKINIT client computed kdc-req-body checksum
9/861AA32FA35DD352DACB3D5768D2818B64B99735
(2021-05-22 21:39:09): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712349.768789: PKINIT client making DH request
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619245: Preauth module pkinit (16) (real) returned: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619246: Produced preauth for next request: PA-PK-AS-REQ (16)
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619247: Sending request (5547 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619248: Initiating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619249: Sending TCP request to stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619250: Received answer (4924 bytes) from stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619251: Terminating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619252: Response was from master KDC
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619253: Processing preauth types: PA-PK-AS-REP (17)
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619254: PKINIT client verified DH reply
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619255: PKINIT client config accepts KDC dNSName SAN
dc01.xxxxx.xxxxx.net
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619256: PKINIT client found dNSName SAN in KDC cert:
dc01.xxxxx.xxxxx.net
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619257: PKINIT client matched KDC hostname
dc01.xxxxx.xxxxx.net against dNSName
SAN; EKU check still required
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619258: PKINIT client skipping EKU check due to configuration
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619259: PKINIT client found acceptable EKU in KDC cert
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619260: PKINIT client used octetstring2key to compute reply key
aes256-cts/7D0E
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619261: Preauth module pkinit (17) (real) returned: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619262: Produced preauth for next request: (empty)
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619263: AS key determined by preauth: aes256-cts/7D0E
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619264: Decrypted AS reply; session key is: aes256-cts/A2ED
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619265: FAST negotiation: unavailable
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_krb5_expire_callback_func] (0x2000):
exp_time: [514796935]
(2021-05-22 21:39:10): [krb5_child[12908]] [validate_tgt] (0x2000): Found keytab entry
with the realm of the credential.
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619266: Retrieving COMPUTERNAME$(a)XXXXX.XXXXX.NET from MEMORY:/etc/krb5.keytab
(vno 0, enctype 0) with result: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619267: Resolving unique ccache of type MEMORY
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619268: Initializing MEMORY:4eV88Mr with default princ
USERNAME(a)XXXXX.XXXXX.NET
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619269: Storing USERNAME(a)XXXXX.XXXXX.NET ->
krbtgt/XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET in MEMORY:4eV88Mr
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619270: Getting credentials USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET using ccache MEMORY:4eV88Mr
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619271: Retrieving USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET
from MEMORY:4eV88Mr with result: -1765328243/Matching credential not found
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619272: Retrieving USERNAME(a)XXXXX.XXXXX.NET ->
krbtgt/XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET from MEMORY:4eV88Mr with result: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619273: Starting with TGT for client realm: USERNAME(a)XXXXX.XXXXX.NET ->
krbtgt/XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619274: Requesting tickets for COMPUTERNAME$(a)XXXXX.XXXXX.NET, referrals on
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619275: Generated subkey for TGS request: aes256-cts/258D
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619276: etypes requested in TGS request: aes256-cts, aes256-sha2,
camellia256-cts, aes128-cts, aes128-sha2, camellia128-cts, rc4-hmac
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619278: Encoding request body and padata into FAST request
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619279: Sending request (2445 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619280: Initiating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619281: Sending TCP request to stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619282: Received answer (2497 bytes) from stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619283: Terminating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619284: Response was from master KDC
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619285: Decoding FAST response
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619286: FAST reply key: aes256-cts/A0F1
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619287: TGS reply is for USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET with session key aes256-cts/26D3
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619288: TGS request result: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619289: Received creds for desired service COMPUTERNAME$(a)XXXXX.XXXXX.NET
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619290: Storing USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET in
MEMORY:4eV88Mr
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619291: Creating authenticator for USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET, seqnum 0, subkey (null), session key aes256-cts/26D3
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619293: Retrieving COMPUTERNAME$(a)XXXXX.XXXXX.NET from MEMORY:/etc/krb5.keytab
(vno 2, enctype aes256-cts) with result: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619294: Decrypted AP-REQ with specified server principal
COMPUTERNAME$(a)XXXXX.XXXXX.NET: aes256-cts/0FD8
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619295: AP-REQ ticket: USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET, session key aes256-cts/26D3
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619296: Negotiated enctype based on authenticator: aes256-cts
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619297: Initializing MEMORY:rd_req2 with default princ
USERNAME(a)XXXXX.XXXXX.NET
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619298: Storing USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET in
MEMORY:rd_req2
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619299: Destroying ccache MEMORY:4eV88Mr
(2021-05-22 21:39:10): [krb5_child[12908]] [validate_tgt] (0x0400): TGT verified using key
for [COMPUTERNAME$(a)XXXXX.XXXXX.NET].
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619300: Retrieving USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET
from MEMORY:rd_req2 with result: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619301: Retrieving COMPUTERNAME$(a)XXXXX.XXXXX.NET from MEMORY:/etc/krb5.keytab
(vno 2, enctype aes256-cts) with result: 0/Success
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_send_pac] (0x0040): sss_pac_make_request
failed [-1][2].
(2021-05-22 21:39:10): [krb5_child[12908]] [validate_tgt] (0x0040): sss_send_pac failed,
group membership for user with principal [USERNAME\@XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET] might
not be correct.
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_child_krb5_trace_cb] (0x4000): [12908]
1621712350.619302: Destroying ccache MEMORY:rd_req2
(2021-05-22 21:39:10): [krb5_child[12908]] [become_user] (0x0200): Trying to become user
[57249832][57200513].
(2021-05-22 21:39:10): [krb5_child[12908]] [get_and_save_tgt] (0x2000): Running as
[57249832][57200513].
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_get_ccache_name_for_principal] (0x4000):
Location: [KCM:]
(2021-05-22 21:39:10): [krb5_child[12908]] [sss_get_ccache_name_for_principal] (0x4000):
tmp_ccname: [KCM:57249832:57728]
(2021-05-22 21:39:10): [krb5_child[12908]] [create_ccache] (0x4000): Initializing ccache
of type [KCM]
(2021-05-22 21:39:10): [krb5_child[12908]] [create_ccache] (0x4000): CC supports switch
(2021-05-22 21:39:10): [krb5_child[12908]] [create_ccache] (0x4000): returning: 0
(2021-05-22 21:39:10): [krb5_child[12908]] [safe_remove_old_ccache_file] (0x0400): New and
old ccache file are the same, none will be deleted.
(2021-05-22 21:39:10): [krb5_child[12908]] [k5c_send_data] (0x0200): Received error code
0
(2021-05-22 21:39:10): [krb5_child[12908]] [pack_response_packet] (0x2000): response
packet size: [117]
(2021-05-22 21:39:10): [krb5_child[12908]] [k5c_send_data] (0x4000): Response sent.
(2021-05-22 21:39:10): [krb5_child[12908]] [main] (0x0400): krb5_child completed
successfully
(2021-05-22 21:41:01): [krb5_child[14076]] [main] (0x0400): krb5_child started.
(2021-05-22 21:41:01): [krb5_child[14076]] [unpack_buffer] (0x1000): total buffer size:
[208]
(2021-05-22 21:41:01): [krb5_child[14076]] [unpack_buffer] (0x0100): cmd [241 (auth)] uid
[57249832] gid [57200513] validate [true] enterprise principal [true] offline [false] UPN
[USERNAME(a)XXXXX.XXXXX.NET]
(2021-05-22 21:41:01): [krb5_child[14076]] [unpack_buffer] (0x0100): ccname: [KCM:]
old_ccname: [KCM:] keytab: [/etc/krb5.keytab]
(2021-05-22 21:41:01): [krb5_child[14076]] [check_use_fast] (0x0100): Not using FAST.
(2021-05-22 21:41:01): [krb5_child[14076]] [switch_creds] (0x0200): Switch user to
[57249832][57200513].
(2021-05-22 21:41:01): [krb5_child[14076]] [switch_creds] (0x0200): Switch user to
[0][0].
(2021-05-22 21:41:01): [krb5_child[14076]] [k5c_check_old_ccache] (0x4000): Ccache_file is
[KCM:] and is not active and TGT is valid.
(2021-05-22 21:41:01): [krb5_child[14076]] [k5c_precreate_ccache] (0x4000): Recreating
ccache
(2021-05-22 21:41:01): [krb5_child[14076]] [privileged_krb5_setup] (0x0080): Cannot open
the PAC responder socket
(2021-05-22 21:41:01): [krb5_child[14076]] [switch_creds] (0x0200): Switch user to
[0][0].
(2021-05-22 21:41:01): [krb5_child[14076]] [switch_creds] (0x0200): Already user [0].
(2021-05-22 21:41:01): [krb5_child[14076]] [main] (0x2000): Running as [0][0].
(2021-05-22 21:41:01): [krb5_child[14076]] [set_lifetime_options] (0x0100): No specific
renewable lifetime requested.
(2021-05-22 21:41:01): [krb5_child[14076]] [set_lifetime_options] (0x0100): No specific
lifetime requested.
(2021-05-22 21:41:01): [krb5_child[14076]] [set_canonicalize_option] (0x0100):
Canonicalization is set to [true]
(2021-05-22 21:41:01): [krb5_child[14076]] [main] (0x0400): Will perform auth
(2021-05-22 21:41:01): [krb5_child[14076]] [main] (0x0400): Will perform online auth
(2021-05-22 21:41:01): [krb5_child[14076]] [tgt_req_child] (0x1000): Attempting to get a
TGT
(2021-05-22 21:41:01): [krb5_child[14076]] [get_and_save_tgt] (0x4000): Found Smartcard
credentials, trying pkinit.
(2021-05-22 21:41:01): [krb5_child[14076]] [get_pkinit_identity] (0x4000): Got [IDPrime
(basic)][/usr/lib64/pkcs11/libiidp11.so].
(2021-05-22 21:41:01): [krb5_child[14076]] [get_pkinit_identity] (0x4000): Using pkinit
identity [PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:token=IDPrime
(basic):certid=C0538C6C20E35F51:certlabel=Letth Gary].
(2021-05-22 21:41:01): [krb5_child[14076]] [get_and_save_tgt] (0x0400): Attempting kinit
for realm [
XXXXX.XXXXX.NET]
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047593: Getting initial credentials for
USERNAME\@XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047595: Sending unauthenticated request
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047596: Sending request (236 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047597: Initiating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047598: Sending TCP request to stream 192.168.0.1:88
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047599: Received answer (207 bytes) from stream 192.168.0.1:88
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047600: Terminating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047601: Response was from master KDC
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047602: Received error from KDC: -1765328359/Additional pre-authentication
required
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047605: Preauthenticating using KDC method data
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047606: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15),
PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2)
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712461.047607: Selected etype info: etype aes256-cts, salt
"XXXXX.XXXXX.NETUSERNAME", params ""
(2021-05-22 21:41:01): [krb5_child[14076]] [sss_krb5_responder] (0x4000): Got question
[pkinit].
(2021-05-22 21:41:01): [krb5_child[14076]] [answer_pkinit] (0x4000): [0] Identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)] flags
[0].
(2021-05-22 21:41:01): [krb5_child[14076]] [answer_pkinit] (0x4000): Setting
pkinit_prompting.
(2021-05-22 21:41:01): [krb5_child[14076]] [pkinit_identity_matches] (0x4000): Found
[module_name=/usr/lib64/pkcs11/libiidp11.so] in identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)].
(2021-05-22 21:41:01): [krb5_child[14076]] [pkinit_identity_matches] (0x4000): Found
[token=IDPrime (basic)] in identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)].
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113658: PKINIT loading CA certs and CRLs from FILE
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113659: PKINIT client computed kdc-req-body checksum
9/7A29DFAFC36D5337CCEB5A5B130F568C75C79506
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113661: PKINIT client making DH request
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113662: Preauth module pkinit (16) (real) returned: 0/Success
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113663: Produced preauth for next request: PA-PK-AS-REQ (16)
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113664: Sending request (5547 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113665: Initiating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113666: Sending TCP request to stream 192.168.0.1:88
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113667: Received answer (4924 bytes) from stream 192.168.0.1:88
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113668: Terminating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113669: Response was from master KDC
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113670: Processing preauth types: PA-PK-AS-REP (17)
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113671: PKINIT client verified DH reply
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113672: PKINIT client config accepts KDC dNSName SAN
dc01.xxxxx.xxxxx.net
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113673: PKINIT client found dNSName SAN in KDC cert:
dc01.xxxxx.xxxxx.net
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113674: PKINIT client matched KDC hostname
dc01.xxxxx.xxxxx.net against dNSName
SAN; EKU check still required
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113675: PKINIT client skipping EKU check due to configuration
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113676: PKINIT client found acceptable EKU in KDC cert
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113677: PKINIT client used octetstring2key to compute reply key
aes256-cts/EA76
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113678: Preauth module pkinit (17) (real) returned: 0/Success
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113679: Produced preauth for next request: (empty)
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113680: AS key determined by preauth: aes256-cts/EA76
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113681: Decrypted AS reply; session key is: aes256-cts/F057
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113682: FAST negotiation: unavailable
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_krb5_expire_callback_func] (0x2000):
exp_time: [514796823]
(2021-05-22 21:41:02): [krb5_child[14076]] [validate_tgt] (0x2000): Found keytab entry
with the realm of the credential.
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113683: Retrieving COMPUTERNAME$(a)XXXXX.XXXXX.NET from MEMORY:/etc/krb5.keytab
(vno 0, enctype 0) with result: 0/Success
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113684: Resolving unique ccache of type MEMORY
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113685: Initializing MEMORY:Rhk7ok0 with default princ
USERNAME(a)XXXXX.XXXXX.NET
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113686: Storing USERNAME(a)XXXXX.XXXXX.NET ->
krbtgt/XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET in MEMORY:Rhk7ok0
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113687: Getting credentials USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET using ccache MEMORY:Rhk7ok0
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113688: Retrieving USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET
from MEMORY:Rhk7ok0 with result: -1765328243/Matching credential not found
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113689: Retrieving USERNAME(a)XXXXX.XXXXX.NET ->
krbtgt/XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET from MEMORY:Rhk7ok0 with result: 0/Success
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113690: Starting with TGT for client realm: USERNAME(a)XXXXX.XXXXX.NET ->
krbtgt/XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113691: Requesting tickets for COMPUTERNAME$(a)XXXXX.XXXXX.NET, referrals on
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113692: Generated subkey for TGS request: aes256-cts/9265
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113693: etypes requested in TGS request: aes256-cts, aes256-sha2,
camellia256-cts, aes128-cts, aes128-sha2, camellia128-cts, rc4-hmac
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113695: Encoding request body and padata into FAST request
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113696: Sending request (2445 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113697: Initiating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:41:02): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712462.113698: Sending TCP request to stream 192.168.0.1:88
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010634: Received answer (2497 bytes) from stream 192.168.0.1:88
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010635: Terminating TCP connection to stream 192.168.0.1:88
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010636: Response was from master KDC
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010637: Decoding FAST response
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010638: FAST reply key: aes256-cts/4627
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010639: TGS reply is for USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET with session key aes256-cts/AAF1
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010640: TGS request result: 0/Success
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010641: Received creds for desired service COMPUTERNAME$(a)XXXXX.XXXXX.NET
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010642: Storing USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET in
MEMORY:Rhk7ok0
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010643: Creating authenticator for USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET, seqnum 0, subkey (null), session key aes256-cts/AAF1
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010645: Retrieving COMPUTERNAME$(a)XXXXX.XXXXX.NET from MEMORY:/etc/krb5.keytab
(vno 2, enctype aes256-cts) with result: 0/Success
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010646: Decrypted AP-REQ with specified server principal
COMPUTERNAME$(a)XXXXX.XXXXX.NET: aes256-cts/0FD8
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010647: AP-REQ ticket: USERNAME(a)XXXXX.XXXXX.NET ->
COMPUTERNAME$(a)XXXXX.XXXXX.NET, session key aes256-cts/AAF1
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010648: Negotiated enctype based on authenticator: aes256-cts
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010649: Initializing MEMORY:rd_req2 with default princ
USERNAME(a)XXXXX.XXXXX.NET
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010650: Storing USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET in
MEMORY:rd_req2
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010651: Destroying ccache MEMORY:Rhk7ok0
(2021-05-22 21:41:03): [krb5_child[14076]] [validate_tgt] (0x0400): TGT verified using key
for [COMPUTERNAME$(a)XXXXX.XXXXX.NET].
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010652: Retrieving USERNAME(a)XXXXX.XXXXX.NET -> COMPUTERNAME$(a)XXXXX.XXXXX.NET
from MEMORY:rd_req2 with result: 0/Success
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010653: Retrieving COMPUTERNAME$(a)XXXXX.XXXXX.NET from MEMORY:/etc/krb5.keytab
(vno 2, enctype aes256-cts) with result: 0/Success
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_send_pac] (0x0040): sss_pac_make_request
failed [-1][2].
(2021-05-22 21:41:03): [krb5_child[14076]] [validate_tgt] (0x0040): sss_send_pac failed,
group membership for user with principal [USERNAME\@XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET] might
not be correct.
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_child_krb5_trace_cb] (0x4000): [14076]
1621712463.010654: Destroying ccache MEMORY:rd_req2
(2021-05-22 21:41:03): [krb5_child[14076]] [become_user] (0x0200): Trying to become user
[57249832][57200513].
(2021-05-22 21:41:03): [krb5_child[14076]] [get_and_save_tgt] (0x2000): Running as
[57249832][57200513].
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_get_ccache_name_for_principal] (0x4000):
Location: [KCM:]
(2021-05-22 21:41:03): [krb5_child[14076]] [sss_get_ccache_name_for_principal] (0x4000):
tmp_ccname: [KCM:57249832:57728]
(2021-05-22 21:41:03): [krb5_child[14076]] [create_ccache] (0x4000): Initializing ccache
of type [KCM]
(2021-05-22 21:41:03): [krb5_child[14076]] [create_ccache] (0x4000): CC supports switch
(2021-05-22 21:41:03): [krb5_child[14076]] [create_ccache] (0x4000): returning: 0
(2021-05-22 21:41:03): [krb5_child[14076]] [safe_remove_old_ccache_file] (0x0400): New and
old ccache file are the same, none will be deleted.
(2021-05-22 21:41:03): [krb5_child[14076]] [k5c_send_data] (0x0200): Received error code
0
(2021-05-22 21:41:03): [krb5_child[14076]] [pack_response_packet] (0x2000): response
packet size: [117]
(2021-05-22 21:41:03): [krb5_child[14076]] [k5c_send_data] (0x4000): Response sent.
(2021-05-22 21:41:03): [krb5_child[14076]] [main] (0x0400): krb5_child completed
successfully
(2021-05-22 22:01:51): [krb5_child[21961]] [main] (0x0400): krb5_child started.
(2021-05-22 22:01:51): [krb5_child[21961]] [unpack_buffer] (0x1000): total buffer size:
[208]
(2021-05-22 22:01:51): [krb5_child[21961]] [unpack_buffer] (0x0100): cmd [241 (auth)] uid
[57249832] gid [57200513] validate [true] enterprise principal [true] offline [false] UPN
[USERNAME(a)XXXXX.XXXXX.NET]
(2021-05-22 22:01:51): [krb5_child[21961]] [unpack_buffer] (0x0100): ccname: [KCM:]
old_ccname: [KCM:] keytab: [/etc/krb5.keytab]
(2021-05-22 22:01:51): [krb5_child[21961]] [check_use_fast] (0x0100): Not using FAST.
(2021-05-22 22:01:51): [krb5_child[21961]] [switch_creds] (0x0200): Switch user to
[57249832][57200513].
(2021-05-22 22:01:51): [krb5_child[21961]] [switch_creds] (0x0200): Switch user to
[0][0].
(2021-05-22 22:01:51): [krb5_child[21961]] [k5c_check_old_ccache] (0x4000): Ccache_file is
[KCM:] and is not active and TGT is valid.
(2021-05-22 22:01:51): [krb5_child[21961]] [k5c_precreate_ccache] (0x4000): Recreating
ccache
(2021-05-22 22:01:51): [krb5_child[21961]] [privileged_krb5_setup] (0x0080): Cannot open
the PAC responder socket
(2021-05-22 22:01:51): [krb5_child[21961]] [switch_creds] (0x0200): Switch user to
[0][0].
(2021-05-22 22:01:51): [krb5_child[21961]] [switch_creds] (0x0200): Already user [0].
(2021-05-22 22:01:51): [krb5_child[21961]] [main] (0x2000): Running as [0][0].
(2021-05-22 22:01:51): [krb5_child[21961]] [set_lifetime_options] (0x0100): No specific
renewable lifetime requested.
(2021-05-22 22:01:51): [krb5_child[21961]] [set_lifetime_options] (0x0100): No specific
lifetime requested.
(2021-05-22 22:01:51): [krb5_child[21961]] [set_canonicalize_option] (0x0100):
Canonicalization is set to [true]
(2021-05-22 22:01:51): [krb5_child[21961]] [main] (0x0400): Will perform auth
(2021-05-22 22:01:51): [krb5_child[21961]] [main] (0x0400): Will perform online auth
(2021-05-22 22:01:51): [krb5_child[21961]] [tgt_req_child] (0x1000): Attempting to get a
TGT
(2021-05-22 22:01:51): [krb5_child[21961]] [get_and_save_tgt] (0x4000): Found Smartcard
credentials, trying pkinit.
(2021-05-22 22:01:51): [krb5_child[21961]] [get_pkinit_identity] (0x4000): Got [IDPrime
(basic)][/usr/lib64/pkcs11/libiidp11.so].
(2021-05-22 22:01:51): [krb5_child[21961]] [get_pkinit_identity] (0x4000): Using pkinit
identity [PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:token=IDPrime
(basic):certid=C0538C6C20E35F51:certlabel=Letth Gary].
(2021-05-22 22:01:51): [krb5_child[21961]] [get_and_save_tgt] (0x0400): Attempting kinit
for realm [
XXXXX.XXXXX.NET]
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008243: Getting initial credentials for
USERNAME\@XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008245: Sending unauthenticated request
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008246: Sending request (236 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008247: Initiating TCP connection to stream 192.168.0.2:88
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008248: Sending TCP request to stream 192.168.0.2:88
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008249: Received answer (207 bytes) from stream 192.168.0.2:88
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008250: Terminating TCP connection to stream 192.168.0.2:88
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008251: Response was from master KDC
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008252: Received error from KDC: -1765328359/Additional pre-authentication
required
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008255: Preauthenticating using KDC method data
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008256: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15),
PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2)
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713711.008257: Selected etype info: etype aes256-cts, salt
"XXXXX.XXXXX.NETUSERNAME", params ""
(2021-05-22 22:01:51): [krb5_child[21961]] [sss_krb5_responder] (0x4000): Got question
[pkinit].
(2021-05-22 22:01:51): [krb5_child[21961]] [answer_pkinit] (0x4000): [0] Identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)] flags
[0].
(2021-05-22 22:01:51): [krb5_child[21961]] [answer_pkinit] (0x4000): Setting
pkinit_prompting.
(2021-05-22 22:01:51): [krb5_child[21961]] [pkinit_identity_matches] (0x4000): Found
[module_name=/usr/lib64/pkcs11/libiidp11.so] in identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)].
(2021-05-22 22:01:51): [krb5_child[21961]] [pkinit_identity_matches] (0x4000): Found
[token=IDPrime (basic)] in identity
[PKCS11:module_name=/usr/lib64/pkcs11/libiidp11.so:slotid=1:token=IDPrime (basic)].
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123177: PKINIT loading CA certs and CRLs from FILE
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123178: PKINIT client computed kdc-req-body checksum
9/332F3229C5A54EBDD04BD0B31DA11BB162BE5DA9
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123180: PKINIT client making DH request
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123181: Preauth module pkinit (16) (real) returned: 0/Success
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123182: Produced preauth for next request: PA-PK-AS-REQ (16)
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123183: Sending request (5547 bytes) to
XXXXX.XXXXX.NET
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123184: Initiating TCP connection to stream 192.168.0.2:88
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123185: Sending TCP request to stream 192.168.0.2:88
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123186: Received answer (4732 bytes) from stream 192.168.0.2:88
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123187: Terminating TCP connection to stream 192.168.0.2:88
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123188: Response was from master KDC
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123189: Processing preauth types: PA-PK-AS-REP (17)
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123190: PKINIT OpenSSL error: Failed to verify received certificate (depth 0):
unable to get local issuer certificate
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123191: PKINIT client could not verify DH reply
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123192: Preauth module pkinit (17) (real) returned: -1765328314/Failed to
verify received certificate (depth 0): unable to get local issuer certificate
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123193: Produced preauth for next request: (empty)
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_krb5_responder] (0x4000): Got question
[password].
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_child_krb5_trace_cb] (0x4000): [21961]
1621713712.123194: Getting AS key, salt "XXXXX.XXXXX.NETUSERNAME", params
""
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter
name [(null)] banner [(null)] num_prompts [1] EINVAL.
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_krb5_prompter] (0x4000): Prompt
[0][Password for USERNAME\@XXXXX.XXXXX.NET(a)XXXXX.XXXXX.NET].
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_krb5_prompter] (0x0200): Prompter
interface isn't used for password prompts by SSSD.
(2021-05-22 22:01:52): [krb5_child[21961]] [sss_krb5_get_init_creds_password] (0x0020):
1643: [-1765328254][Cannot read password]
(2021-05-22 22:01:52): [krb5_child[21961]] [get_and_save_tgt] (0x0020): 1720:
[-1765328254][Cannot read password]
(2021-05-22 22:01:52): [krb5_child[21961]] [map_krb5_error] (0x0020): 1849:
[-1765328254][Cannot read password]
(2021-05-22 22:01:52): [krb5_child[21961]] [k5c_send_data] (0x0200): Received error code
1432158219
(2021-05-22 22:01:52): [krb5_child[21961]] [pack_response_packet] (0x2000): response
packet size: [4]
(2021-05-22 22:01:52): [krb5_child[21961]] [k5c_send_data] (0x4000): Response sent.
(2021-05-22 22:01:52): [krb5_child[21961]] [main] (0x0400): krb5_child completed
successfully