Thanks Jakub,
ldapsearch now completes successfully, but when users tries to authenticate, they still get access denied. We have confirmed that user does exist in the groups listed under access filter & both id and getent passwd return correct user data.
Each time user tries to log in,we get the following under krb5_child.log ( Debug level 3)
(Wed Apr 5 11:39:42 2017) [[sssd[krb5_child[11141]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
(Wed Apr 5 11:39:42 2017) [[sssd[krb5_child[11141]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][2].
(Wed Apr 5 11:39:42 2017) [[sssd[krb5_child[11141]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [first.last\@XYZ.LOCAL@XYZ.LOCAL] might not be correct.
(Wed Apr 5 11:39:42 2017) [[sssd[krb5_child[11141]]]] [sss_unique_file_ex] (0x0040): mkstemp("/tmp/krb5cc_1616401130_1o13tv") failed [13]: Permission denied!
(Wed Apr 5 11:39:42 2017) [[sssd[krb5_child[11141]]]] [handle_randomized] (0x0020): mkstemp("/tmp/krb5cc_1616401130_1o13tv") failed [13]: Permission denied!
(Wed Apr 5 11:39:42 2017) [[sssd[krb5_child[11141]]]] [create_ccache] (0x0020): handle_randomized failed: 13
(Wed Apr 5 11:39:42 2017) [[sssd[krb5_child[11141]]]] [map_krb5_error] (0x0020): 1301: [13][Permission denied]
Same log with Debug level set to 9:
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [main] (0x0400): krb5_child started.
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [unpack_buffer] (0x1000): total buffer size: [141]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [unpack_buffer] (0x0100): cmd [241] uid [xxxxxxxxxx] gid [yyyyyyyyyy] validate [true] enterprise principal [true] offline [false] UPN [first.last@XYZ.LOCAL]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [unpack_buffer] (0x2000): No old ccache
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [unpack_buffer] (0x0100): ccname: [FILE:/tmp/krb5cc_xxxxxxxxxx_XXXXXX] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [check_use_fast] (0x0100): Not using FAST.
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [become_user] (0x0200): Trying to become user [xxxxxxxxxx][yyyyyyyyyy].
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [main] (0x2000): Running as [xxxxxxxxxx][yyyyyyyyyy].
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [k5c_setup] (0x2000): Running as [xxxxxxxxxx][yyyyyyyyyy].
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment.
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [main] (0x0400): Will perform online auth
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [XYZ.LOCAL]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.810727: Getting initial credentials for first.last\@XYZ.LOCAL@XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.810806: Sending request (225 bytes) to XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.810936: Sending initial UDP request to dgram
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.811646: Received answer from dgram
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.811694: Response was from master KDC
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.811716: Received error from KDC: -1765328359/Additional pre-authentication required
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.811748: Processing preauth types: 16, 15, 19, 2
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.811763: Selected etype info: etype aes256-cts, salt "XYZ.LOCALfirst.last", params ""
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.819089: AS key obtained for encrypted timestamp: aes256-cts/2DA7
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.819143: Encrypted timestamp (for 1491392737.819101): plain 301AA011180F32303137303430353131343533375AA10502030C7F9D, encrypted 6DF95051B1B8FC33CB5F2CF23D4915C373FD528D0D570D3C439F38C5E17F36FDAA031546B06D47748D0996FC0BAD103BA1DEB49E84AE73A1
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.819155: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.819161: Produced preauth for next request: 2
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.819174: Sending request (305 bytes) to XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.819226: Sending initial UDP request to dgram
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.820166: Received answer from dgram
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.820256: Response was from master KDC
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.820271: Received error from KDC: -1765328332/Response too big for UDP, retry with TCP
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.820278: Request or response is too big for UDP; retrying with TCP
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.820284: Sending request (305 bytes) to XYZ.LOCAL (tcp only)
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.820311: Initiating TCP connection to stream
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.820537: Sending TCP request to stream
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821449: Received answer from stream
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821526: Response was from master KDC
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821547: Processing preauth types: 19
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821555: Selected etype info: etype aes256-cts, salt "XYZ.LOCALfirst.last", params ""
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821561: Produced preauth for next request: (empty)
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821569: AS key determined by preauth: aes256-cts/2DA7
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821603: Decrypted AS reply; session key is: aes256-cts/2A55
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821619: FAST negotiation: unavailable
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [3559012]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [validate_tgt] (0x2000): Found keytab entry with the realm of the credential.
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821678: Retrieving host/hostname.xyz.local@XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821685: Resolving unique ccache of type MEMORY
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821698: Initializing MEMORY:M2bO4Sd with default princ first.last@XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821706: Removing first.last@XYZ.LOCAL -> krbtgt/XYZ.LOCAL@XYZ.LOCAL from MEMORY:M2bO4Sd
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821713: Storing first.last@XYZ.LOCAL -> krbtgt/XYZ.LOCAL@XYZ.LOCAL in MEMORY:M2bO4Sd
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821728: Getting credentials first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL using ccache MEMORY:M2bO4Sd
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821747: Retrieving first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL from MEMORY:M2bO4Sd with result: -1765328243/Matching credential not found
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821775: Retrieving first.last@XYZ.LOCAL -> krbtgt/XYZ.LOCAL@XYZ.LOCAL from MEMORY:M2bO4Sd with result: 0/Success
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821784: Found cached TGT for service realm: first.last@XYZ.LOCAL -> krbtgt/XYZ.LOCAL@XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821791: Requesting tickets for host/hostname.xyz.local@XYZ.LOCAL, referrals on
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821815: Generated subkey for TGS request: aes256-cts/AB86
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821826: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821901: Sending request (1553 bytes) to XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.821950: Initiating TCP connection to stream
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.822167: Sending TCP request to stream
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823154: Received answer from stream
10.105.11.10:88(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823260: Response was from master KDC
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823300: TGS reply is for first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL with session key rc4-hmac/81A7
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823318: TGS request result: 0/Success
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823328: Received creds for desired service host/hostname.xyz.local@XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823335: Removing first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL from MEMORY:M2bO4Sd
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823342: Storing first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL in MEMORY:M2bO4Sd
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823366: Creating authenticator for first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL, seqnum 0, subkey (null, session key rc4-hmac/81A7
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823410: Retrieving host/hostname.xyz.local@XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 2, enctype rc4-hmac) with result: 0/Success
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823466: Decrypted AP-REQ with specified server principal host/hostname.xyz.local@XYZ.LOCAL: rc4-hmac/4965
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823478: AP-REQ ticket: first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL, session key rc4-hmac/81A7
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823609: Negotiated enctype based on authenticator: rc4-hmac
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823625: Initializing MEMORY:rd_req2 with default princ first.last@XYZ.LOCAL
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823635: Removing first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL from MEMORY:rd_req2
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823642: Storing first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL in MEMORY:rd_req2
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823654: Destroying ccache MEMORY:M2bO4Sd
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [validate_tgt] (0x0400): TGT verified using key for [host/hostname.xyz.local@XYZ.LOCAL].
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823690: Retrieving first.last@XYZ.LOCAL -> host/hostname.xyz.local@XYZ.LOCAL from MEMORY:rd_req2 with result: 0/Success
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823733: Retrieving host/hostname.xyz.local@XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 2, enctype rc4-hmac) with result: 0/Success
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][2].
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [first.last\@XYZ.LOCAL@XYZ.LOCAL] might not be correct.
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_child_krb5_trace_cb] (0x4000): [11215] 1491392737.823772: Destroying ccache MEMORY:rd_req2
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_get_ccache_name_for_principal] (0x4000): Location: [FILE:/tmp/krb5cc_xxxxxxxxxx_XXXXXX]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_get_ccache_name_for_principal] (0x2000): krb5_cc_cache_match failed: [-1765328243][Can't find client principal first.last@XYZ.LOCAL in cache collection]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [sss_unique_file_ex] (0x0040): mkstemp("/tmp/krb5cc_xxxxxxxxxx_C2Mqqg") failed [13]: Permission denied!
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [handle_randomized] (0x0020): mkstemp("/tmp/krb5cc_xxxxxxxxxx_C2Mqqg") failed [13]: Permission denied!
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [create_ccache] (0x0020): handle_randomized failed: 13
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [map_krb5_error] (0x0020): 1301: [13][Permission denied](Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [k5c_send_data] (0x0200): Received error code 1432158209
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [pack_response_packet] (0x2000): response packet size: [20]
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [k5c_send_data] (0x4000): Response sent.
(Wed Apr 5 11:45:37 2017) [[sssd[krb5_child[11215]]]] [main] (0x0400): krb5_child completed successfully
Thanks,
~ Abhi