*  (2022-01-24 16:11:50): [be[ipa.test]] [child_handler_setup] (0x2000): [RID#171] Signal handler set up for pid [4444]
   *  (2022-01-24 16:11:50): [be[ipa.test]] [write_pipe_handler] (0x0400): [RID#171] All data has been sent!
   *  (2022-01-24 16:11:56): [be[ipa.test]] [krb5_auth_done] (0x0020): [RID#171] child timed out!
  --  what is in the corresponding `krb5_child.log`?
(You might need to enable debug_level=9 in the domain section to get krb5_child.log populated.)

On Tue, Jan 25, 2022 at 5:30 PM Rob Crittenden <rcritten@fedoraproject.org> wrote:
> Am Mon, Jan 24, 2022 at 01:36:28PM -0500 schrieb Rob Crittenden:
> Hi,
> the PAM_PERM_DENIED error is returned from the backend. Please check the
> backend log and krb5_child.log. I agree that it looks a bit like a
> timeout issue since the default krb5_auth_timeout is 6s but I would
> expect a different return code in this case.
> It looks like currently PAM_PERM_DENIED is returned during
> authentication only if the KDC returns KRB5KDC_ERR_CLIENT_REVOKED, i.e.
> the account is locked or similar.

Looks like the backend is detected as offline.

Here is a hopefully not too-hacked representation from the backend log:
   *  (2022-01-24 16:11:50): [be[ipa.test]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2022-01-24 16:11:50): [be[ipa.test]] [dp_pam_handler_send] (0x0100): Got request with the following data
   *  (2022-01-24 16:11:50): [be[ipa.test]] [pam_print_data] (0x0100): [CID #2] command: SSS_PAM_AUTHENTICATE
   *  (2022-01-24 16:11:50): [be[ipa.test]] [pam_print_data] (0x0100): [CID #2] domain: ipa.test
   *  (2022-01-24 16:11:50): [be[ipa.test]] [pam_print_data] (0x0100): [CID #2] user: user19client003.ipa.test@ipa.test
   *  (2022-01-24 16:11:50): [be[ipa.test]] [pam_print_data] (0x0100): [CID #2] service: login
[snip but it's a password auth]
   *  (2022-01-24 16:11:50): [be[ipa.test]] [dp_attach_req] (0x0400): [RID#171] DP Request [PAM Authenticate #171]: REQ_TRACE: New request. [sssd.pam CID #2] Flags [0000].
   *  (2022-01-24 16:11:50): [be[ipa.test]] [dp_attach_req] (0x0400): [RID#171] Number of active DP request: 1
   *  (2022-01-24 16:11:50): [be[ipa.test]] [sss_domain_get_state] (0x1000): [RID#171] Domain ipa.test is Active
   *  (2022-01-24 16:11:50): [be[ipa.test]] [sss_domain_get_state] (0x1000): [RID#171] Domain ipa.test is Active
   *  (2022-01-24 16:11:50): [be[ipa.test]] [krb5_auth_queue_send] (0x1000): [RID#171] Wait queue of user [user19client003.ipa.test@ipa.test] is empty, running request [0x5614e40a64d0] immediately.
   *  (2022-01-24 16:11:50): [be[ipa.test]] [krb5_setup] (0x4000): [RID#171] No mapping for: user19client003.ipa.test@ipa.test
   *  (2022-01-24 16:11:50): [be[ipa.test]] [krb5_auth_prepare_ccache_name] (0x1000): [RID#171] No ccache file for user [user19client003.ipa.test@ipa.test] found.
   *  (2022-01-24 16:11:50): [be[ipa.test]] [fo_resolve_service_send] (0x0100): [RID#171] Trying to resolve service 'IPA'
   *  (2022-01-24 16:11:50): [be[ipa.test]] [get_server_status] (0x1000): [RID#171] Status of server 'server.ipa.test' is 'working'
   *  (2022-01-24 16:11:50): [be[ipa.test]] [get_port_status] (0x1000): [RID#171] Port status of port 0 for server 'server.ipa.test' is 'working'
   *  (2022-01-24 16:11:50): [be[ipa.test]] [fo_resolve_service_activate_timeout] (0x2000): [RID#171] Resolve timeout [dns_resolver_timeout] set to 6 seconds
   *  (2022-01-24 16:11:50): [be[ipa.test]] [get_server_status] (0x1000): [RID#171] Status of server 'server.ipa.test' is 'working'
   *  (2022-01-24 16:11:50): [be[ipa.test]] [be_resolve_server_process] (0x1000): [RID#171] Saving the first resolved server
   *  (2022-01-24 16:11:50): [be[ipa.test]] [be_resolve_server_process] (0x0200): [RID#171] Found address for server server.ipa.test: [] TTL 7200
   *  (2022-01-24 16:11:50): [be[ipa.test]] [ipa_resolve_callback] (0x0400): [RID#171] Constructed uri 'ldap://server.ipa.test'
   *  (2022-01-24 16:11:50): [be[ipa.test]] [krb5_add_krb5info_offline_callback] (0x4000): [RID#171] Removal callback already available for service [IPA].
   *  (2022-01-24 16:11:50): [be[ipa.test]] [unlink_dbg] (0x2000): [RID#171] File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_hY7Urp]
   *  (2022-01-24 16:11:50): [be[ipa.test]] [sss_domain_get_state] (0x1000): [RID#171] Domain ipa.test is Active
   *  (2022-01-24 16:11:50): [be[ipa.test]] [child_handler_setup] (0x2000): [RID#171] Setting up signal handler up for pid [4444]
   *  (2022-01-24 16:11:50): [be[ipa.test]] [child_handler_setup] (0x2000): [RID#171] Signal handler set up for pid [4444]
   *  (2022-01-24 16:11:50): [be[ipa.test]] [write_pipe_handler] (0x0400): [RID#171] All data has been sent!
   *  (2022-01-24 16:11:56): [be[ipa.test]] [krb5_auth_done] (0x0020): [RID#171] child timed out!
********************** BACKTRACE DUMP ENDS HERE *********************************

(2022-01-24 16:11:56): [be[ipa.test]] [fo_resolve_service_send] (0x0020): [RID#171] No available servers for service 'IPA'

and subsequent backtraces:

   *  (2022-01-24 16:11:56): [be[ipa.test]] [_be_fo_set_port_status] (0x8000): [RID#171] Setting status: PORT_NOT_WORKING. Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 862

and all the expected ports not available, etc. and no available servers for IPA (single server install).

The child is eventually killed leading to:

(2022-01-24 16:11:57): [be[ipa.test]] [krb5_auth_cache_creds] (0x0020): [RID#171] Offline authentication failed

Which makes sense since this is the first login for the user so there are no stored creds.

So if this is indeed a timeout, it is good for me. I'm explicitly trying to find the limit of how many users/clients can authenticate at more or less the same time. It seems like I've managed to push the server enough that it isn't responsive to the default sssd timeouts (and 6 seconds feels like forever if you're just trying to log in). The interesting bit is that the server isn't really stressing at all, using maybe 25% of CPU. So it must be something else that is restrictive: # of threads, connections, etc.

I'll preserve these client and server logs in case we want to do further analysis but I'll try decreasing the number of logins to continue my search for the sweet spot.
sssd-users mailing list -- sssd-users@lists.fedorahosted.org
To unsubscribe send an email to sssd-users-leave@lists.fedorahosted.org
Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.org
Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure