Bug 1962550

Summary:

sss_pac_make_request fails on systems joined to Active Directory.

Product:

Red Hat Enterprise Linux 8

Reporter:

Arya Rajendran <arajendr>

Component:

sssd

Assignee:

Sumit Bose <sbose>

Status:

CLOSED ERRATA

QA Contact:

Dan Lavu <dlavu>

Severity:

unspecified

Docs Contact:

Priority:

unspecified

Version:

8.4

CC:

atikhono, dlavu, grajaiya, jhrozek, lslebodn, mescanfe, mzidek, pbrezina, sbose, sgoveas, tscherf

Target Milestone:

beta

Keywords:

Triaged

Target Release:

---

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

sync-to-jira

Fixed In Version:

sssd-2.5.1-1.el8

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2021-11-09 19:47:29 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
tar ball with a test build	none

Description Arya Rajendran 2021-05-20 09:16:34 UTC

Description of problem:

PAC failures are observed in krb5_child.log logs even after adding pac responder in sssd.conf.
~~~
(2021-05-12  7:50:54): [krb5_child[105403]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][14].
(2021-05-12  7:50:54): [krb5_child[105403]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [USER\@EXAMPLE.COM] might not be correct.
~~~

Version-Release number of selected component (if applicable):
Rhel 7.9
sssd-1.16.5-10.el7_9.7.x86_64

How reproducible:
Always in the customer environment

Actual results:

sss_pac_make_request fails

Expected results:

Succesful sss_pac_make_request

Additional info:

- keytab principal key matches with the kvno value returned from AD.

- Cleared sssd cache

- Logs: 

sssd.log:
(2021-05-12  7:50:35): [sssd] [client_registration] (0x0100): Received ID registration: (pac,1)
(2021-05-12  7:50:35): [sssd] [mark_service_as_started] (0x0200): Marking pac as started.

krb5_child.log:

(2021-05-12  7:50:54): [krb5_child[105403]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][14].
(2021-05-12  7:50:54): [krb5_child[105403]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [USER\@EXAMPLE.COM] might not be correct.

sssd_example.com.log:

(2021-05-12  7:50:54): [be[example.com]] [check_if_pac_is_available] (0x4000): No PAC available.

sssd_pac.log:

(2021-05-12  7:50:54): [pac] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[105403].
(2021-05-12  7:50:54): [pac] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x560a951a7af0][18]
(2021-05-12  7:50:54): [pac] [accept_fd_handler] (0x0400): Client connected!
(2021-05-12  7:50:54): [pac] [sss_cmd_get_version] (0x0200): Received client version [1].
(2021-05-12  7:50:54): [pac] [sss_cmd_get_version] (0x0200): Offered version [1].
(2021-05-12  7:50:54): [pac] [client_recv] (0x0400): Invalid data from client, closing connection!
(2021-05-12  7:50:54): [pac] [client_close_fn] (0x2000): Terminated client [0x560a951a7af0][18]
(2021-05-12  7:50:54): [pac] [get_client_cred] (0x4000): Client creds: euid[2768] egid[13620000] pid[105403].
(2021-05-12  7:50:54): [pac] [accept_fd_handler] (0x0020): Access denied for uid [2768]

Comment 5 Sumit Bose 2021-05-20 10:53:50 UTC

Hi,

so far I was not able to reproduce the issue. Can you ask to run

    strace -ff -o /tmp/sssd_be.trace -s 4096 -p $(pidof sssd_be)

as root in a terminal and try to authenticate from a different terminal. After the authentication attempt please stop strace with CRTL-C and attach the /tmp/sssd_be.trace* file (there should be more than one).

bye,
Sumit

Comment 13 Sumit Bose 2021-05-20 15:30:09 UTC

(In reply to Arya Rajendran from comment #11)
> (In reply to Sumit Bose from comment #5)
> > Hi,
> > 
> > so far I was not able to reproduce the issue. Can you ask to run
> > 
> >     strace -ff -o /tmp/sssd_be.trace -s 4096 -p $(pidof sssd_be)
> > 
> > as root in a terminal and try to authenticate from a different terminal.
> > After the authentication attempt please stop strace with CRTL-C and attach
> > the /tmp/sssd_be.trace* file (there should be more than one).
> > 
> > bye,
> > Sumit
> 
> Hi, 
> 
> They have shared strace with "-s 1" as strace captured user password. So the
> content of the inputs/outputs is truncated. 

Hi,

I really need the i/o data to understand why the PAC responder says "[client_recv] (0x0400): Invalid data from client, closing connection!".

Would it be possible to run

    strace -ff -o /tmp/sssd_be.trace -s 4096 -p $(pidof sssd_pac)

and do a login test? The PAC responder does not handle the password.

bye,
Sumit

> Thanks

Comment 15 Sumit Bose 2021-05-21 09:45:42 UTC

Created attachment 1785480 [details]
tar ball with a test build

Hi,

please find attached a tar ball with a test build which should fix the issue. Please let me know if it works.

bye,
Sumit

Comment 18 Sumit Bose 2021-05-25 08:43:20 UTC

Upstream ticket:
https://github.com/SSSD/sssd/issues/5650

Comment 21 Pavel Březina 2021-06-04 07:11:01 UTC

Pushed PR: https://github.com/SSSD/sssd/pull/5664

* `sssd-1-16`
    * afa7d965a62f7dfc9f9912aaec7ad3d905a32381 - responder/common/responder_packet: remove SSS_GSSAPI_SEC_CTX
    * 1cbfca01505733bb689d9f8e0e8c1ded7187b7ae - pac: allow larger PACs
    * 6b3671dbcfcc8d4e522bbc2a6d9c6d0bb6325fe3 - responder/common/responder_packet: reduce duplication of code that handles larger-than-normal packets
    * 17b041538ced0e95f6e98f112c261889998965f9 - responder/common/responder_packet: handle large service tickets
    * 2d136dc6820b6a6c7cf3adf57853b5bb3839aa5a - responder/common/responder_packet: get packet length only once

Comment 24 Alexey Tikhonov 2021-06-04 11:10:32 UTC

Pushed PR: https://github.com/SSSD/sssd/pull/5652

* `master`
    * b75ef442dd23f30d879e2876bbc19d13da1a62b8 - pac: allow larger PACs

Comment 27 Dan Lavu 2021-06-15 00:26:41 UTC

Tested and verified against sssd-2.5.1-1.el8.x86_64

sssd.conf
---------------------------------------------
[sssd]
debug_level = 9
domains = domain.com
config_file_version = 2
services = nss, pam, pac

[domain/domain.com]
debug_level = 9
ad_domain = domain.com
krb5_realm = DOMAIN.COM
realmd_tags = manages-system joined-with-adcli 
cache_credentials = True
id_provider = ad
krb5_store_password_if_offline = True
default_shell = /bin/bash
ldap_id_mapping = True
use_fully_qualified_names = True
fallback_homedir = /home/%u@%d
access_provider = ad
allowed_uids = root,administrator


[pac]
debug_level = 9


sssd.log
---------------------------------------------
(2021-06-14 20:22:49): [sssd] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pac]
(2021-06-14 20:22:49): [sssd] [sbus_dispatch] (0x4000): Dispatching.
(2021-06-14 20:22:49): [sssd] [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.GetConnectionUnixUser on /org/freedesktop/DBus
(2021-06-14 20:22:49): [sssd] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.GetConnectionUnixUser: Success
(2021-06-14 20:22:49): [sssd] [sbus_dispatch] (0x4000): Dispatching.
(2021-06-14 20:22:49): [sssd] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pac]
(2021-06-14 20:22:49): [sssd] [sbus_senders_add] (0x2000): Inserting identity of sender [sssd.pac]: 0
(2021-06-14 20:22:49): [sssd] [monitor_sbus_RegisterService] (0x0100): Received ID registration: (pac,1)
(2021-06-14 20:22:49): [sssd] [mark_service_as_started] (0x0200): Marking pac as started.


krb5_child.log 
---------------------------------------------
(2021-06-14 20:23:03): [krb5_child[2946]] [validate_tgt] (0x0400): TGT verified using key for [RHEL85$@DOMAIN.COM].
(2021-06-14 20:23:03): [krb5_child[2946]] [sss_child_krb5_trace_cb] (0x4000): [2946] 1623716583.602990: Retrieving Administrator -> RHEL85$@DOMAIN.COM from MEMORY:rd_req2 with result: 0/Success

(2021-06-14 20:23:03): [krb5_child[2946]] [sss_child_krb5_trace_cb] (0x4000): [2946] 1623716583.602991: Retrieving RHEL85$@DOMAIN.COM from MEMORY:/etc/krb5.keytab (vno 3, enctype aes256-cts) with result: 0/Success

(2021-06-14 20:23:03): [krb5_child[2946]] [sss_send_pac] (0x0400): PAC responder contacted. It might take a bit of time in case the cache is not up to date.
(2021-06-14 20:23:03): [krb5_child[2946]] [sss_child_krb5_trace_cb] (0x4000): [2946] 1623716583.602992: Destroying ccache MEMORY:rd_req2


sssd_pac.log
---------------------------------------------
(2021-06-14 20:23:03): [pac] [get_client_cred] (0x4000): Client [0x55e33729bb70][23] creds: euid[0] egid[0] pid[2946] cmd_line['/usr/libexec/sssd/krb5_child'].
(2021-06-14 20:23:03): [pac] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55e33729bb70][23]
(2021-06-14 20:23:03): [pac] [accept_fd_handler] (0x0400): Client [CID #1][cmd /usr/libexec/sssd/krb5_child][0x55e33729bb70][23] connected!
(2021-06-14 20:23:03): [pac] [sss_cmd_get_version] (0x0200): Received client version [1].
(2021-06-14 20:23:03): [pac] [sss_cmd_get_version] (0x0200): Offered version [1].
(2021-06-14 20:23:03): [pac] [sss_domain_get_state] (0x1000): Domain implicit_files is Active
(2021-06-14 20:23:03): [pac] [sss_domain_get_state] (0x1000): Domain domain.com is Active
(2021-06-14 20:23:03): [pac] [sss_domain_get_state] (0x1000): Domain domain.com is Active
(2021-06-14 20:23:03): [pac] [cache_req_set_plugin] (0x2000): CR #0: Setting "Object by SID" plugin
(2021-06-14 20:23:03): [pac] [cache_req_send] (0x0400): CR #0: REQ_TRACE: New request [CID #1] 'Object by SID'
(2021-06-14 20:23:03): [pac] [cache_req_object_by_sid_well_known] (0x4000): CR #0: SID [S-1-5-21-1852701752-3115886509-69707877-500] is not a Well-Known SID.
(2021-06-14 20:23:03): [pac] [cache_req_select_domains] (0x0400): CR #0: Performing a single domain search
(2021-06-14 20:23:03): [pac] [sss_domain_get_state] (0x1000): Domain implicit_files is Active
(2021-06-14 20:23:03): [pac] [sss_domain_get_state] (0x1000): Domain domain.com is Active
(2021-06-14 20:23:03): [pac] [cache_req_search_domains] (0x0400): CR #0: Search will check the cache and check the data provider
(2021-06-14 20:23:03): [pac] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain domain.com type POSIX is valid
(2021-06-14 20:23:03): [pac] [cache_req_set_domain] (0x0400): CR #0: Using domain [domain.com]
(2021-06-14 20:23:03): [pac] [cache_req_search_send] (0x0400): CR #0: Looking up SID:S-1-5-21-1852701752-3115886509-69707877-500
(2021-06-14 20:23:03): [pac] [cache_req_search_ncache] (0x0400): CR #0: Checking negative cache for [SID:S-1-5-21-1852701752-3115886509-69707877-500]
(2021-06-14 20:23:03): [pac] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/SID/S-1-5-21-1852701752-3115886509-69707877-500]
(2021-06-14 20:23:03): [pac] [cache_req_search_ncache] (0x0400): CR #0: [SID:S-1-5-21-1852701752-3115886509-69707877-500] is not present in negative cache
(2021-06-14 20:23:03): [pac] [cache_req_search_cache] (0x0400): CR #0: Looking up [SID:S-1-5-21-1852701752-3115886509-69707877-500] in cache
(2021-06-14 20:23:03): [pac] [cache_req_search_send] (0x0400): CR #0: Returning [SID:S-1-5-21-1852701752-3115886509-69707877-500] from cache
(2021-06-14 20:23:03): [pac] [cache_req_search_ncache_filter] (0x0400): CR #0: This request type does not support filtering result by negative cache
(2021-06-14 20:23:03): [pac] [cache_req_create_and_add_result] (0x0400): CR #0: Found 1 entries in domain domain.com
(2021-06-14 20:23:03): [pac] [cache_req_done] (0x0400): CR #0: Finished: Success
(2021-06-14 20:23:03): [pac] [sysdb_ldb_msg_difference] (0x2000): Added attr [pacBlob] to entry [name=Administrator,cn=users,cn=domain.com,cn=sysdb]
(2021-06-14 20:23:03): [pac] [sysdb_set_entry_attr] (0x0200): Entry [name=Administrator,cn=users,cn=domain.com,cn=sysdb] has set [cache, ts_cache] attrs.
(2021-06-14 20:23:04): [pac] [client_recv] (0x0200): Client disconnected!

Comment 37 errata-xmlrpc 2021-11-09 19:47:29 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (sssd bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:4435