sssd don't restart properly after being killed by watchdog

Recently we have a strange behavior, I hope somebody could find the solution. Thank you for your help in advance.

We using sssd plugged to LDAP on our ssh server.

Server is installed on

Distributor ID: Debian Description: Debian GNU/Linux 11 (bullseye) Release: 11 Codename: bullseye

Here are the version of sssd packages :

ii  sssd                               2.4.1-2                        
ii  sssd-ad                            2.4.1-2                      
ii  sssd-ad-common                     2.4.1-2              
ii  sssd-common                        2.4.1-2                
ii  sssd-dbus                          2.4.1-2                    
ii  sssd-ipa                           2.4.1-2                      
ii  sssd-krb5                          2.4.1-2                     
ii  sssd-krb5-common                   2.4.1-2             
ii  sssd-ldap                          2.4.1-2                     
ii  sssd-proxy                         2.4.1-2                    
ii  sssd-tools                         2.4.1-2

Here is sssd.conf :

[sssd]
#services = nss, pam
config_file_version = 2
domains = domain
timeout = 15

[nss]
# Ensure that certain users are not authenticated from network accounts
filter_users = root,lightdm,nslcd,dnsmasq,dbus,avahi,avahi-autoipd,backup,beagleindex,bin,daemon,games,gdm,gnats,haldaemon,hplip,irc,ivman,klog,libuuid,list,lp,mail,man,messagebus,mysql,news,ntp,openldap,polkituser,proxy,pulse,puppet,saned,sshd,sync,sys,syslog,uucp,vde2-net,www-data
filter_groups = root

[domain/domain]
debug_level = 5
id_provider = ldap
access_provider = ldap
auth_provider = ldap
autofs_provider = ldap

ldap_schema = rfc2307

ldap_uri = ldaps://ldap.domain/ , ldaps://ldap-master.domain/
ldap_search_base = o=domain,dc=xxx,dc=xx
ldap_id_use_start_tls = True
cache_credentials = False
ldap_group_member = memberUid

ldap_access_filter = (objectClass=posixAccount)

ldap_tls_cacertdir = /etc/ssl/certs
#ldap_tls_cacert = /etc/ssl/certs/mytlsca.pem # Replace with the correct file name
ldap_tls_reqcert = allow

# Enables listing users and groups with getent
enumerate = True

Globally it works perfectly, but sometimes sssd process is killed by watchdog and then it can't start up again.

1) The reason for sssd to be killed by watchdog is probably explained by server's load. This load by itself is also strange thing, but probably not linked with sssd.

sssd.log (with debug_level=5)

(2022-06-14  0:31:43): [sssd] [svc_child_info] (0x0020): Child [24079] ('domain':'%BE_domain') was terminated by own WATCHDOG
(2022-06-14  0:32:25): [sssd] [svc_child_info] (0x0020): Child [88706] ('domain':'%BE_domain') was terminated by own WATCHDOG

2) Then the sssd service tried to restart, but failed partially

I see these lines in sssd_pam and sssd_nss logs :

sssd_pam.log

(2022-06-14  0:31:31): [pam] [server_setup] (0x0040): Starting with debug level = 0x0070
(2022-06-14  0:31:43): [pam] [sbus_dbus_connect_address] (0x0020): Unable to register to unix:path=/var/lib/sss/pipes/private/sbus-dp_domain [org.freedesktop.DBus.Error.NoReply]: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
(2022-06-14  0:31:43): [pam] [sss_dp_init] (0x0010): Failed to connect to backend server.
(2022-06-14  0:31:43): [pam] [sss_process_init] (0x0010): fatal error setting up backend connector
(2022-06-14  0:31:43): [pam] [pam_process_init] (0x0010): sss_process_init() failed
(2022-06-14  0:31:43): [pam] [server_setup] (0x0040): Starting with debug level = 0x0070
(2022-06-14  0:31:43): [pam] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_domain: Connection refused
(2022-06-14  0:31:43): [pam] [sss_dp_init] (0x0010): Failed to connect to backend server.
(2022-06-14  0:31:43): [pam] [sss_process_init] (0x0010): fatal error setting up backend connector
(2022-06-14  0:31:43): [pam] [pam_process_init] (0x0010): sss_process_init() failed

sssd_nss.log

(2022-06-14  0:31:44): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_domain: Connection refused
(2022-06-14  0:31:44): [nss] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-14  0:31:47): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_domain: Connection refused
(2022-06-14  0:31:47): [nss] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-14  0:32:12): [nss] [server_setup] (0x0040): Starting with debug level = 0x0070
(2022-06-14  0:32:25): [nss] [sbus_dbus_connect_address] (0x0020): Unable to register to unix:path=/var/lib/sss/pipes/private/sbus-dp_domain [org.freedesktop.DBus.Error.NoReply]: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
(2022-06-14  0:32:25): [nss] [sss_dp_init] (0x0010): Failed to connect to backend server.
(2022-06-14  0:32:25): [nss] [sss_process_init] (0x0010): fatal error setting up backend connector
(2022-06-14  0:32:25): [nss] [nss_process_init] (0x0010): sss_process_init() failed

I said "partially" as sssd. service has active status by itself, but it doesn't work properly and no authentication is possible.

sssd_pam.log

(2022-06-14  8:31:06): [pam] [cache_req_common_process_dp_reply] (0x0040): CR #1: Could not get account info [1432158311]: Unknown service
(2022-06-14  8:31:56): [pam] [cache_req_common_process_dp_reply] (0x0040): CR #3: Could not get account info [1432158311]: Unknown service

3) The reason why sssd doesn't work is probably caused by services sssd-pam and sssd-nss that failed to restart.

journalctl -u sssd-nss.service

Jun 14 00:32:11 ssh systemd[1]: sssd-nss.service: Main process exited, code=exited, status=70/SOFTWARE
Jun 14 00:32:11 ssh systemd[1]: sssd-nss.service: Failed with result 'exit-code'.
Jun 14 00:32:11 ssh systemd[1]: sssd-nss.service: Scheduled restart job, restart counter is at 1.
Jun 14 00:32:11 ssh systemd[1]: Stopped SSSD NSS Service responder.
Jun 14 00:32:11 ssh systemd[1]: Started SSSD NSS Service responder.
Jun 14 00:32:12 ssh sssd_nss[88732]: Starting up
Jun 14 00:32:25 ssh systemd[1]: sssd-nss.service: Main process exited, code=exited, status=3/NOTIMPLEMENTED
Jun 14 00:32:25 ssh systemd[1]: sssd-nss.service: Failed with result 'exit-code'.
Jun 14 00:32:26 ssh systemd[1]: sssd-nss.service: Scheduled restart job, restart counter is at 2.
Jun 14 00:32:26 ssh systemd[1]: Stopped SSSD NSS Service responder.
Jun 14 00:32:26 ssh systemd[1]: Started SSSD NSS Service responder.
Jun 14 00:32:26 ssh sssd_nss[88739]: Starting up
Jun 14 00:35:07 ssh systemd[1]: sssd-nss.service: Main process exited, code=exited, status=70/SOFTWARE
Jun 14 00:35:07 ssh systemd[1]: sssd-nss.service: Failed with result 'exit-code'.
Jun 14 00:35:07 ssh systemd[1]: sssd-nss.service: Scheduled restart job, restart counter is at 3.
Jun 14 00:35:07 ssh systemd[1]: Stopped SSSD NSS Service responder.
Jun 14 00:35:07 ssh systemd[1]: Started SSSD NSS Service responder.
Jun 14 00:35:07 ssh sssd_nss[88795]: Starting up
[skip]
Jun 14 00:36:20 ssh systemd[1]: Started SSSD NSS Service responder.
Jun 14 00:36:21 ssh systemd[1]: sssd-nss.service: Main process exited, code=exited, status=3/NOTIMPLEMENTED
Jun 14 00:36:21 ssh systemd[1]: sssd-nss.service: Failed with result 'exit-code'.
Jun 14 00:36:21 ssh systemd[1]: sssd-nss.service: Scheduled restart job, restart counter is at 12.
Jun 14 00:36:21 ssh systemd[1]: Stopped SSSD NSS Service responder.
Jun 14 00:36:21 ssh systemd[1]: sssd-nss.service: Start request repeated too quickly.
Jun 14 00:36:21 ssh systemd[1]: sssd-nss.service: Failed with result 'exit-code'.
Jun 14 00:36:21 ssh systemd[1]: Failed to start SSSD NSS Service responder.

journalctl -u sssd-nss.socket

Jun 14 00:36:21 ssh systemd[1]: sssd-nss.socket: Failed with result 'service-start-limit-hit'.

journalctl -u sssd-pam.service

Jun 14 00:30:50 ssh sssd_pam[88640]: Starting up
Jun 14 00:31:31 ssh systemd[1]: sssd-pam.service: Main process exited, code=exited, status=70/SOFTWARE
Jun 14 00:31:31 ssh systemd[1]: sssd-pam.service: Failed with result 'exit-code'.
Jun 14 00:31:31 ssh systemd[1]: sssd-pam.service: Scheduled restart job, restart counter is at 1.
Jun 14 00:31:31 ssh systemd[1]: Stopped SSSD PAM Service responder.
Jun 14 00:31:31 ssh systemd[1]: Starting SSSD PAM Service responder...
Jun 14 00:31:31 ssh systemd[1]: Started SSSD PAM Service responder.
Jun 14 00:31:43 ssh systemd[1]: sssd-pam.service: Main process exited, code=exited, status=3/NOTIMPLEMENTED
Jun 14 00:31:43 ssh systemd[1]: sssd-pam.service: Failed with result 'exit-code'.
Jun 14 00:31:43 ssh systemd[1]: sssd-pam.service: Scheduled restart job, restart counter is at 2.
Jun 14 00:31:43 ssh systemd[1]: Stopped SSSD PAM Service responder.
Jun 14 00:31:43 ssh systemd[1]: Starting SSSD PAM Service responder...
Jun 14 00:31:43 ssh systemd[1]: Started SSSD PAM Service responder.
Jun 14 00:31:43 ssh systemd[1]: sssd-pam.service: Main process exited, code=exited, status=3/NOTIMPLEMENTED
Jun 14 00:31:43 ssh systemd[1]: sssd-pam.service: Failed with result 'exit-code'.
Jun 14 00:31:43 ssh systemd[1]: sssd-pam.service: Scheduled restart job, restart counter is at 3.
Jun 14 00:31:43 ssh systemd[1]: Stopped SSSD PAM Service responder.
[skip]
Jun 14 00:36:20 ssh systemd[1]: sssd-pam.service: Start request repeated too quickly.
Jun 14 00:36:20 ssh systemd[1]: sssd-pam.service: Failed with result 'exit-code'.
Jun 14 00:36:20 ssh systemd[1]: Failed to start SSSD PAM Service responder.

journalctl -u sssd-pam.socket

Jun 14 00:31:44 ssh systemd[1]: sssd-pam.socket: Failed with result 'service-start-limit-hit'.
Jun 14 00:32:11 ssh systemd[1]: Starting SSSD PAM Service responder socket.
Jun 14 00:32:12 ssh systemd[1]: Listening on SSSD PAM Service responder socket.
Jun 14 00:36:20 ssh systemd[1]: sssd-pam.socket: Failed with result 'service-start-limit-hit'.

So, this is pretty serious as it happens often enough and ssh server become useless until we restart sssd service. Restarting sssd service solves the problem, but I hope there is some better solution.

Here some additional details/thoughts :

I used some old conf file as template for sssd conf for this server. There was "service" setting in this conf in the sssd part : [sssd] services = nss, pam

As I understand this option is not necessary now. So I comment this line. The problem described above was already present, and commenting this line didn't solve it. But still I'd like to mention this change.

I added timeout = 15 option into sssd part of config, but it didn't help neither.
There is an option "RestartSec" for systemd. I'm wondering may be set this option for sssd-nss and sssd-pam services could change something (may be the problem that sssd-nss restart too quickly) ?

Hi,

(2022-06-14 0:31:43): [sssd] [svc_child_info] (0x0020): Child [24079] ('domain':'%BE_domain') was terminated by own WATCHDOG

could you please check what operation is blocking in sssd_$domain.log at this moment?

(2022-06-14 0:31:43): [pam] [sss_dp_init] (0x0010): Failed to connect to backend server.

sssd_pam/nss was unable to connect to sssdbe[$domain]. Could you please check sssd$domain.log - why it doesn't start properly?

I added timeout = 15 option into sssd part of config, but it didn't help neither. This is section specific option. If you want to give sssd_be[$domain] more chances to finish its slow operation then please increase timeout in the [$domain] section.

I just realized timestamps are the same - 2022-06-14 0:31:43 - so this is the same event.

I just realized timestamps are the same - 2022-06-14 0:31:43 - so this is the same event.

Yes, all logs that I posted linked to the same event happened this night. I just put two lines from sssd_pam.log at 08:31 to show that happen when some user tried to connect.

Here logs from sssd_$domain.log at 2022-06-14 0:31:43 Just before (at 0:31:07) it was logs for normal user connect, I put only three lines of the end of connection.

(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88687
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:31:43): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0x03f0
(2022-06-14  0:31:43): [be[$domain]] [be_res_get_opts] (0x0100): Lookup order: ipv4_first
(2022-06-14  0:31:43): [be[$domain]] [recreate_ares_channel] (0x0100): Initializing new c-ares channel
(2022-06-14  0:31:43): [be[$domain]] [sysdb_domain_init_internal] (0x0200): DB File for $domain: /var/lib/sss/db/cache_$domain.ldb
(2022-06-14  0:31:43): [be[$domain]] [sysdb_domain_init_internal] (0x0200): Timestamp file for $domain: /var/lib/sss/db/timestamps_$domain.ldb
(2022-06-14  0:31:54): [be[$domain]] [sss_names_init_from_args] (0x0100): Using re [(?P<name>[^@]+)@?(?P<domain>[^@]*$)].
(2022-06-14  0:31:54): [be[$domain]] [sss_fqnames_init] (0x0100): Using fq format [%1$s@%2$s].
(2022-06-14  0:31:54): [be[$domain]] [sbus_server_new_connection] (0x0200): Adding connection 0x5645edda8230.
(2022-06-14  0:31:54): [be[$domain]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x5645eddab9e0]
(2022-06-14  0:31:54): [be[$domain]] [sbus_signal_handler] (0x0200): We do not listen to this signal!
(2022-06-14  0:31:54): [be[$domain]] [sbus_signal_handler] (0x0200): We do not listen to this signal!
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [id]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [auth]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [access]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [chpass]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [sudo]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [autofs]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [selinux]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [hostid]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [subdomains]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [session]
(2022-06-14  0:31:54): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [resolver]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [DEFAULT][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [USER][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [GROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [NETGROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [HOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [SERVICE][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPHOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPNETWORK][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:31:54): [be[$domain]] [krb5_try_kdcip] (0x0100): No KDC found in configuration, trying legacy option
(2022-06-14  0:31:54): [be[$domain]] [get_sdap_service] (0x0100): Service name for discovery set to ldap
(2022-06-14  0:31:54): [be[$domain]] [sysdb_idmap_get_mappings] (0x0080): Could not locate ID mappings: [No such file or directory]
(2022-06-14  0:32:25): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0x03f0
(2022-06-14  0:32:25): [be[$domain]] [be_res_get_opts] (0x0100): Lookup order: ipv4_first
(2022-06-14  0:32:25): [be[$domain]] [recreate_ares_channel] (0x0100): Initializing new c-ares channel
(2022-06-14  0:32:25): [be[$domain]] [sysdb_domain_init_internal] (0x0200): DB File for $domain: /var/lib/sss/db/cache_$domain.ldb
(2022-06-14  0:32:25): [be[$domain]] [sysdb_domain_init_internal] (0x0200): Timestamp file for $domain: /var/lib/sss/db/timestamps_$domain.ldb
(2022-06-14  0:32:25): [be[$domain]] [sss_names_init_from_args] (0x0100): Using re [(?P<name>[^@]+)@?(?P<domain>[^@]*$)].
(2022-06-14  0:32:25): [be[$domain]] [sss_fqnames_init] (0x0100): Using fq format [%1$s@%2$s].
(2022-06-14  0:32:25): [be[$domain]] [sbus_server_new_connection] (0x0200): Adding connection 0x55cd1ae4a160.
(2022-06-14  0:32:25): [be[$domain]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x55cd1ae4d9e0]
(2022-06-14  0:32:25): [be[$domain]] [sbus_signal_handler] (0x0200): We do not listen to this signal!
(2022-06-14  0:32:25): [be[$domain]] [sbus_signal_handler] (0x0200): We do not listen to this signal!
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [id]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [auth]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [access]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [chpass]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [sudo]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [autofs]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [selinux]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [hostid]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [subdomains]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [session]
(2022-06-14  0:32:25): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [resolver]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [DEFAULT][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [USER][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [GROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [NETGROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [HOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [SERVICE][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPHOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPNETWORK][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:25): [be[$domain]] [krb5_try_kdcip] (0x0100): No KDC found in configuration, trying legacy option
(2022-06-14  0:32:25): [be[$domain]] [get_sdap_service] (0x0100): Service name for discovery set to ldap
(2022-06-14  0:32:25): [be[$domain]] [sysdb_idmap_get_mappings] (0x0080): Could not locate ID mappings: [No such file or directory]
(2022-06-14  0:32:51): [be[$domain]] [ldap_get_sudo_options] (0x0200): Option ldap_sudo_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-14  0:32:51): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [SUDO][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:51): [be[$domain]] [ldap_get_autofs_options] (0x0200): Option ldap_autofs_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-14  0:32:51): [be[$domain]] [ldap_rfc2307_autofs_defaults] (0x0010): Unable to read from confdb [2]: No such file or directory
(2022-06-14  0:32:51): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [AUTOFS][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-14  0:32:51): [be[$domain]] [dp_target_init] (0x0100): Target [selinux] is not supported by module [ldap].
(2022-06-14  0:32:51): [be[$domain]] [dp_target_init] (0x0100): Target [subdomains] is not supported by module [ldap].
(2022-06-14  0:32:51): [be[$domain]] [dp_target_init] (0x0100): Target [session] is not supported by module [ldap].
(2022-06-14  0:32:51): [be[$domain]] [become_user] (0x0200): Trying to become user [0][0].
(2022-06-14  0:32:51): [be[$domain]] [become_user] (0x0200): Already user [0].
(2022-06-14  0:32:51): [be[$domain]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
(2022-06-14  0:32:51): [be[$domain]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'ldap.domain' in files
(2022-06-14  0:32:51): [be[$domain]] [set_server_common_status] (0x0100): Marking server 'ldap.domain' as 'resolving name'
(2022-06-14  0:32:51): [be[$domain]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'ldap.domain' in files
(2022-06-14  0:32:51): [be[$domain]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
(2022-06-14  0:32:51): [be[$domain]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'ldap.domain' in DNS
(2022-06-14  0:32:51): [be[$domain]] [sbus_server_new_connection] (0x0200): Adding connection 0x55cd1ae7eb40.
(2022-06-14  0:32:51): [be[$domain]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x55cd1ae7c930]
(2022-06-14  0:32:51): [be[$domain]] [sss_monitor_service_init_done] (0x0100): Got id ack and version (1) from Monitor
(2022-06-14  0:32:51): [be[$domain]] [set_server_common_status] (0x0100): Marking server 'ldap.domain' as 'name resolved'
(2022-06-14  0:32:51): [be[$domain]] [be_resolve_server_process] (0x0200): Found address for server ldap.domain: [$ip_ldap] TTL 600
(2022-06-14  0:32:51): [be[$domain]] [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is supported by this server!
(2022-06-14  0:32:51): [be[$domain]] [sdap_get_server_opts_from_rootdse] (0x0200): Will use modification timestamp as usn!
(2022-06-14  0:32:51): [be[$domain]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
(2022-06-14  0:32:51): [be[$domain]] [fo_set_port_status] (0x0100): Marking port 636 of server 'ldap.domain' as 'working'
(2022-06-14  0:32:51): [be[$domain]] [set_server_common_status] (0x0100): Marking server 'ldap.domain' as 'working'
(2022-06-14  0:32:51): [be[$domain]] [be_run_online_cb] (0x0080): Going online. Running callbacks.
(2022-06-14  0:32:51): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user1@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:32:51): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user2@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
[skip : a lot of users here]
(2022-06-14  0:32:51): [be[$domain]] [enum_users_done] (0x0100): Users higher USN value: [20220610135144Z]
(2022-06-14  0:32:51): [be[$domain]] [be_ptask_enable] (0x0080): Task [SUDO Smart Refresh]: already enabled
(2022-06-14  0:32:51): [be[$domain]] [dp_client_register] (0x0100): Added Frontend client [nss]
(2022-06-14  0:32:51): [be[$domain]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x55cd1ae7c930]
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sdap_process_group_send] (0x0200): No Members. Done!
(2022-06-14  0:32:51): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=userNN@$domain,cn=groups,cn=$domain,cn=sysdb] has set [cache, ts_cache] attrs.
(2022-06-14  0:32:51): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=userNN1@$domain,cn=groups,cn=$domain,cn=sysdb] has set [cache, ts_cache] attrs.

Just skip a lot of similar lines in the middle where _sysdb_set_entryattr set [ts_cache] attrs. I tried to seek out something in this log, but didn't find any relevant.

(2022-06-14 0:31:07): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88687 (2022-06-14 0:31:07): [be[$domain]] [pam_print_data] (0x0100): logon name: not set (2022-06-14 0:31:07): [be[$domain]] [pam_print_data] (0x0100): flags: 0 -- watchdog kicks in here (2022-06-14 0:31:43): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0x03f0 -- "Starting with debug level" -- sssd_be was restarted

Just before (at 0:31:07) it was logs for normal user connect

Did it really succeed? What is in the log before pam_print_data? Unfortunately we don't see all the details with debug_level = 5

Btw, this delay:

(2022-06-14  0:31:43): [be[$domain]] [sysdb_domain_init_internal] (0x0200): Timestamp file for $domain: /var/lib/sss/db/timestamps_$domain.ldb
(2022-06-14  0:31:54): [be[$domain]] [sss_names_init_from_args] (0x0100): Using re [(?P<name>[^@]+)@?(?P<domain>[^@]*$)].

is also suspicious.

After first line is printed in sysdb_domain_init_internal() and second line is printed in sss_names_init(), there are:

sysdb_domain_cache_connect()
sysdb_timestamp_cache_connect()
sysdb_master_domain_update()

What filesystem and kind of drive do you use for /var/lib/sss/db/? How big are cache files there?

Just before (at 0:31:07) it was logs for normal user connect

Did it really succeed? What is in the log before pam_print_data? Unfortunately we don't see all the details with debug_level = 5

Hmmm.... I'm not sure for 100%.

I get my opinion that it was ok based on ssh (auth) log :

auth.log

Jun 14 00:30:50 ssh sshd[79742]: Received disconnect from $ip_user1 port 58767:11: disconnected by user
Jun 14 00:30:58 ssh sshd[79742]: Disconnected from user user1 $ip_user1 port 58767
Jun 14 00:30:58 ssh sshd[79736]: pam_unix(sshd:session): session closed for user user1
Jun 14 00:30:58 ssh sshd[88641]: Accepted publickey for user1 from $ip_user1 port 58805 ssh2: ED25519 SHA256:l7DBwBv7I042Klm1rBAn8cb8a9cldJ0PoA2f558SuRg
Jun 14 00:30:58 ssh sshd[88641]: pam_unix(sshd:session): session opened for user user1(uid=XXXX) by (uid=0)
Jun 14 00:30:58 ssh systemd-logind[715]: Session 141 logged out. Waiting for processes to exit.
Jun 14 00:30:58 ssh systemd-logind[715]: Removed session 141.
Jun 14 00:30:58 ssh systemd-logind[715]: New session 143 of user user1.
Jun 14 00:31:05 ssh sshd[88660]: Accepted publickey for user2 from $ip_user2 port 58796 ssh2: RSA SHA256:RLHo9mM9qyQMCiuGA1Vo49j0pogflNmO5FiIpcv/yTY
Jun 14 00:31:05 ssh sshd[88660]: pam_unix(sshd:session): session opened for user user2(uid=XXX) by (uid=0)
Jun 14 00:31:05 ssh systemd-logind[715]: New session 144 of user user2.
Jun 14 00:31:05 ssh systemd: pam_unix(systemd-user:session): session opened for user user2(uid=XXX) by (uid=0)
Jun 14 00:31:07 ssh sshd[88681]: Received disconnect from $ip_user2 port 58796:11: disconnected by user
Jun 14 00:31:07 ssh sshd[88681]: Disconnected from user user2 $ip_user2 port 58796
Jun 14 00:31:07 ssh sshd[88660]: pam_unix(sshd:session): session closed for user user2
Jun 14 00:31:07 ssh systemd-logind[715]: Session 144 logged out. Waiting for processes to exit.
Jun 14 00:31:07 ssh systemd-logind[715]: Removed session 144.
Jun 14 00:31:07 ssh sshd[88687]: Accepted publickey for user2 from $ip_user2 port 58797 ssh2: RSA SHA256:RLHo9mM9qyQMCiuGA1Vo49j0pogflNmO5FiIpcv/yTY
Jun 14 00:31:07 ssh sshd[88687]: pam_unix(sshd:session): session opened for user user2(uid=XXX) by (uid=0)
Jun 14 00:31:07 ssh systemd-logind[715]: New session 146 of user user2.
Jun 14 00:31:18 ssh sshd[88693]: Received disconnect from $ip_user2 port 58797:11: disconnected by user
Jun 14 00:31:51 ssh sshd[88693]: Disconnected from user user2 $ip_user2 port 58797
Jun 14 00:31:51 ssh sshd[88687]: pam_unix(sshd:session): session closed for user user2

Here are the lines from sssd_$domain.log before 0:31:43

(2022-06-14  0:29:50): [be[$domain]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getDomains: Error [1432158215]: DP target is not configured
(2022-06-14  0:29:50): [be[$domain]] [dp_get_account_info_send] (0x0200): Got request for [0x1][BE_REQ_USER][idnumber=1255]
(2022-06-14  0:29:50): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user1@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:30:50): [be[$domain]] [sbus_server_new_connection] (0x0200): Adding connection 0x558b7df7d760.
(2022-06-14  0:30:50): [be[$domain]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x558b7dfc7d60]
(2022-06-14  0:30:50): [be[$domain]] [dp_client_register] (0x0100): Added Frontend client [pam]
(2022-06-14  0:30:50): [be[$domain]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x558b7dfc7d60]
(2022-06-14  0:30:50): [be[$domain]] [dp_find_method] (0x0100): Target [subdomains] is not initialized
(2022-06-14  0:30:50): [be[$domain]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getDomains: Error [1432158215]: DP target is not configured
(2022-06-14  0:30:50): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_CLOSE_SESSION
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): user: user1@$domain
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user1
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 79736
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:30:50): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:30:51): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): user: user1@$domain
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user1
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88641
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:30:51): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user1@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:30:51): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_OPEN_SESSION
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): user: user1@$domain
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user1
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88641
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:30:51): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:31:05): [be[$domain]] [dp_get_account_info_send] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=user2@$domain]
(2022-06-14  0:31:05): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user2@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:31:05): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user2@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:31:05): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): user: user2@$domain
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user2
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88660
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:31:05): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user2@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:31:05): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_OPEN_SESSION
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): user: user2@$domain
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user2
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88660
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:31:05): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): user: user2@$domain
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): service: systemd-user
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): tty: 
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): rhost: 
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88663
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:31:05): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:31:05): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user2@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:31:07): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_CLOSE_SESSION
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): user: user2@$domain
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user2
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88660
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:31:07): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): user: user2@$domain
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user2
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88687
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): flags: 0
(2022-06-14  0:31:07): [be[$domain]] [sysdb_set_entry_attr] (0x0200): Entry [name=user2@$domain,cn=users,cn=$domain,cn=sysdb] has set [ts_cache] attrs.
(2022-06-14  0:31:07): [be[$domain]] [dp_pam_handler_send] (0x0100): Got request with the following data
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): command: SSS_PAM_OPEN_SESSION
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): domain: $domain
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): user: user2@$domain
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): service: sshd
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): tty: ssh
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): ruser: 
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): rhost: $ip_user2
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): priv: 1
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): cli_pid: 88687
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): logon name: not set
(2022-06-14  0:31:07): [be[$domain]] [pam_print_data] (0x0100): flags: 0

I'll restart sssd with debug_level = 9 but we have to wait until this problem happens again.

About sssd db files : /var is on LVM on xfs filesystem :

/dev/mapper/vg-var on /var type xfs (rw,relatime,attr2,inode64,logbufs=8,logbsize=32k,noquota)

Files don't seem to be huge, but I don't know how big it should be :

-rw-------  1 root root 2.5M Jun 14 17:19 cache_$domain.ldb
-rw-------  1 root root 1.3M Jun 13 13:56 config.ldb
-rw-------  1 root root 1.3M Mar 21 16:22 sssd.ldb
-rw-------  1 root root 3.8M Jun 14 16:04 timestamps_$domain.ldb

A little piece of information : ssh server is VM turning on Proxmox cluster. Cluster was recently migrated to Proxmox 7.2. In theory this problem could be related with this migration : our ssh server was running a lot time without any problem, and recently, after the migration, we have this problem 4 times in last 8 days. But I am not convinced about it, I'd like to found some more reliable proof linked Proxmox with this sssd problem.

I restarted sssd with debug_level = 9

And today at night we had another WATCHDOG killing, but this time it was slightly different. The service has restarted by itself. But, strange thing, it seems to me that this restart took a lot of time (may be I'm wrong on my log analyze?).

sssd.log

(2022-06-16  0:38:26): [sssd] [svc_child_info] (0x0020): Child [576] ('$domain':'%BE_$domain') was terminated by own WATCHDOG
(2022-06-16  0:40:06): [sssd] [svc_child_info] (0x0020): Child [187985] ('$domain':'%BE_$domain') was terminated by own WATCHDOG
(2022-06-16  0:40:37): [sssd] [svc_child_info] (0x0020): Child [188014] ('$domain':'%BE_$domain') was terminated by own WATCHDOG

sssd_nss.log

(2022-06-16  0:34:31): [nss] [orderly_shutdown] (0x0040): Shutting down (status = 0)(2022-06-16  0:36:40): [nss] [server_setup] (0x0040): Starting with debug level = 0x0070
(2022-06-16  0:38:23): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_$domain: Connection refused
(2022-06-16  0:38:24): [nss] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-16  0:38:27): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_$domain: Connection refused
(2022-06-16  0:38:27): [nss] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-16  0:38:37): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_$domain: Connection refused
(2022-06-16  0:38:37): [nss] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-16  0:38:37): [nss] [sbus_reconnect] (0x0020): Unable to reconnect: maximum retries exceeded.
(2022-06-16  0:38:37): [nss] [sss_dp_on_reconnect] (0x0010): Could not reconnect to $domain provider.
(2022-06-16  0:43:20): [nss] [cache_req_common_process_dp_reply] (0x0040): CR #6: Could not get account info [1432158212]: SSSD is offline
(2022-06-16  0:43:20): [nss] [cache_req_common_process_dp_reply] (0x0040): CR #7: Could not get account info [1432158212]: SSSD is offline
[skip a lot of similar "CR...SSSD is offline" lines]
(2022-06-16  1:29:02): [nss] [cache_req_common_process_dp_reply] (0x0040): CR #60: Could not get account info [1432158212]: SSSD is offline
(2022-06-16  1:34:10): [nss] [orderly_shutdown] (0x0040): Shutting down (status = 0)(2022-06-16  1:35:07): [nss] [server_setup] (0x0040): Starting with debug level = 0x0070

sssd_pam.log

(2022-06-16  0:29:48): [pam] [orderly_shutdown] (0x0040): Shutting down (status = 0)(2022-06-16  0:36:55): [pam] [server_setup] (0x0040): Starting with debug level = 0x0070
(2022-06-16  0:36:55): [pam] [sss_certmap_init] (0x0040): sss_certmap initialized.
(2022-06-16  0:38:23): [pam] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_$domain: Connection refused
(2022-06-16  0:38:23): [pam] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-16  0:38:26): [pam] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_$domain: Connection refused
(2022-06-16  0:38:26): [pam] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-16  0:38:36): [pam] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_$domain: Connection refused
(2022-06-16  0:38:36): [pam] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2022-06-16  0:38:36): [pam] [sbus_reconnect] (0x0020): Unable to reconnect: maximum retries exceeded.
(2022-06-16  0:38:36): [pam] [sss_dp_on_reconnect] (0x0010): Could not reconnect to $domain provider.
(2022-06-16  0:43:20): [pam] [cache_req_common_process_dp_reply] (0x0040): CR #9: Could not get account info [1432158212]: SSSD is offline
[skip similar "[cache_req_common_process_dp_reply] ... SSSD is offline" lines]
(2022-06-16  0:56:00): [pam] [pam_dp_send_req_done] (0x0020): PAM handler failed [1432158212]: SSSD is offline
(2022-06-16  0:56:19): [pam] [cache_req_common_process_dp_reply] (0x0040): CR #25: Could not get account info [1432158212]: SSSD is offline
[skip similar "[cache_req_common_process_dp_reply] ... SSSD is offline" lines]
(2022-06-16  1:11:39): [pam] [pam_dp_send_req_done] (0x0020): PAM handler failed [1432158212]: SSSD is offline
(2022-06-16  1:11:39): [pam] [pam_dp_send_req_done] (0x0020): PAM handler failed [1432158212]: SSSD is offline
(2022-06-16  1:13:43): [pam] [cache_req_common_process_dp_reply] (0x0040): CR #42: Could not get account info [1432158212]: SSSD is offline
[skip similar "[cache_req_common_process_dp_reply] ... SSSD is offline" lines]
2022-06-16  1:34:25): [pam] [orderly_shutdown] (0x0040): Shutting down (status = 0)(2022-06-16  1:46:03): [pam] [server_setup] (0x0040): Starting with debug level = 0x0070
(2022-06-16  1:46:03): [pam] [sss_certmap_init] (0x0040): sss_certmap initialized.

So it seems to me that sssd was killed by WATCHDOG at 0:38 and 0:40. It tried to restart but it didn't work until 1:34 when suddenly it starts to work.

Am I right in my analyze ? Could we explain that happened ? Is it normal or not ?

With new debug_level I have a lot of lines in sssd_domain.log. Is it interesting to post them all ? Should I search for particular pattern ? Or for specific timestamp ?

I already noticed one detail. I see some messages at 0:38 for nss and pam, but there is nothing for this timestamp in sssd_domain.log. Just nothing. There are line for 0:37 and then it restarts at 0:39. Not a big deal probably, but I was a little surprised.

What is in sssd.log at 1:34:10 (when responders were shut down - 'orderly_shutdown')?

What operation was running in sssd_$domain.log before watchdog - i.e. before 0:38:26, 0:40:06 and 0:40:37? Is this SSS_PAM_OPEN_SESSION again?

Could you please grep "Starting with debug level" in sssd_$domain.log?

I see some messages at 0:38 for nss and pam, but there is nothing for this timestamp in sssd_domain.log. Just nothing. There are line for 0:37 and then it restarts at 0:39.

This is "expected" - stuck process (a target for watchdog) can't write to the log.

What is in sssd.log at 1:34:10 (when responders were shut down - 'orderly_shutdown')?

Surpisingly nothing.

Here are the sssd.log

(2022-06-16  0:38:26): [sssd] [svc_child_info] (0x0020): Child [576] ('$domain':'%BE_$domain') was terminated by own WATCHDOG
(2022-06-16  0:40:06): [sssd] [svc_child_info] (0x0020): Child [187985] ('$domain':'%BE_$domain') was terminated by own WATCHDOG
(2022-06-16  0:40:37): [sssd] [svc_child_info] (0x0020): Child [188014] ('$domain':'%BE_$domain') was terminated by own WATCHDOG
(2022-06-17  0:32:03): [sssd] [svc_child_info] (0x0020): Child [188020] ('$domain':'%BE_$domain') was terminated by own WATCHDOG

The next line after 0:40 is at 0:32 this night (17.06). This night it was killed again and this time it didn't restart properly : systemctl status sssd indicate active, but systemctl status sssd-nss was failed and authentication didn't work until I restart sssd service.

Here are the lines for grep ""Starting with debug level"

(2022-06-16  0:39:35): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-16  0:40:06): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-16  0:40:37): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:32:27): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:33:00): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:33:31): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:34:13): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:34:48): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:36:17): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:37:01): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:38:03): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0

Here are the lines before 0:38 (at 0:37:59 and little before, I could get more if necessary) :

(2022-06-16  0:37:47): [be[$domain]] [sbus_dispatch] (0x4000): Dispatching.
(2022-06-16  0:37:51): [be[$domain]] [sdap_id_conn_data_expire_handler] (0x0080): connection is about to expire, releasing it
(2022-06-16  0:37:51): [be[$domain]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
(2022-06-16  0:37:51): [be[$domain]] [sdap_handle_release] (0x2000): Trace: sh[0x555eb5025af0], connected[1], ops[(nil)], ldap[0x555eb4f2b540], destructor_lock[0], release_memory[0]
(2022-06-16  0:37:51): [be[$domain]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
(2022-06-16  0:37:59): [be[$domain]] [be_ptask_execute] (0x0400): Task [SUDO Smart Refresh]: executing task, timeout 900 seconds
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_smart_refresh_send] (0x0400): Issuing a smart refresh of sudo rules (USN >= 00000101000000Z)
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_step] (0x4000): beginning to connect
(2022-06-16  0:37:59): [be[$domain]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
(2022-06-16  0:37:59): [be[$domain]] [get_server_status] (0x1000): Status of server 'ldap.domain' is 'working'
(2022-06-16  0:37:59): [be[$domain]] [get_server_status] (0x0100): Hostname resolution expired, resetting the server status of 'ldap.domain'
(2022-06-16  0:37:59): [be[$domain]] [set_server_common_status] (0x0100): Marking server 'ldap.domain' as 'name not resolved'
(2022-06-16  0:37:59): [be[$domain]] [get_port_status] (0x1000): Port status of port 636 for server 'ldap.domain' is 'working'
(2022-06-16  0:37:59): [be[$domain]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(2022-06-16  0:37:59): [be[$domain]] [get_server_status] (0x1000): Status of server 'ldap.domain' is 'name not resolved'
(2022-06-16  0:37:59): [be[$domain]] [resolv_is_address] (0x4000): [ldap.domain] does not look like an IP address
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_step] (0x2000): Querying files
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'ldap.domain' in files
(2022-06-16  0:37:59): [be[$domain]] [set_server_common_status] (0x0100): Marking server 'ldap.domain' as 'resolving name'
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_step] (0x2000): Querying files
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'ldap.domain' in files
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_step] (0x2000): Querying DNS
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'ldap.domain' in DNS
(2022-06-16  0:37:59): [be[$domain]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 3 seconds
(2022-06-16  0:37:59): [be[$domain]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
(2022-06-16  0:37:59): [be[$domain]] [be_ptask_execute] (0x0400): Task [Enumeration [resolver] of $domain]: executing task, timeout 300 seconds
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_step] (0x4000): waiting for connection to complete
(2022-06-16  0:37:59): [be[$domain]] [be_ptask_execute] (0x0400): Task [Enumeration [id] of $domain]: executing task, timeout 300 seconds
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_step] (0x4000): waiting for connection to complete
(2022-06-16  0:37:59): [be[$domain]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
(2022-06-16  0:37:59): [be[$domain]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
(2022-06-16  0:37:59): [be[$domain]] [request_watch_destructor] (0x0400): Deleting request watch
(2022-06-16  0:37:59): [be[$domain]] [set_server_common_status] (0x0100): Marking server 'ldap.domain' as 'name resolved'
(2022-06-16  0:37:59): [be[$domain]] [be_resolve_server_process] (0x1000): Saving the first resolved server
(2022-06-16  0:37:59): [be[$domain]] [be_resolve_server_process] (0x0200): Found address for server ldap.domain: [$ip_ldap] TTL 600
(2022-06-16  0:37:59): [be[$domain]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ldap.domain/'
(2022-06-16  0:37:59): [be[$domain]] [decide_tls_usage] (0x2000): [ldaps://ldap.domain/] is a secure channel. No need to run START_TLS
(2022-06-16  0:37:59): [be[$domain]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [20] for the connection.
(2022-06-16  0:37:59): [be[$domain]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting
(2022-06-16  0:37:59): [be[$domain]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ldap.domain:636/??base] with fd [20].
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_rootdse_send] (0x4000): Getting rootdse
(2022-06-16  0:37:59): [be[$domain]] [sdap_print_server] (0x2000): Searching $ip_ldap:636
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_add] (0x2000): New operation 1 timeout 6
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: sh[0x555eb4d051a0], connected[1], ops[0x555eb4cf71d0], ldap[0x555eb4e9dac0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_entry] (0x1000): OriginalDN: [].
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedFeatures]
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
(2022-06-16  0:37:59): [be[$domain]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: sh[0x555eb4d051a0], connected[1], ops[0x555eb4cf71d0], ldap[0x555eb4e9dac0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_destructor] (0x2000): Operation 1 finished
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_rootdse_done] (0x2000): Got rootdse
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is supported by this server!
(2022-06-16  0:37:59): [be[$domain]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
(2022-06-16  0:37:59): [be[$domain]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1655333579
(2022-06-16  0:37:59): [be[$domain]] [sdap_cli_auth_step] (0x1000): No authentication requested or SASL auth forced off
(2022-06-16  0:37:59): [be[$domain]] [sdap_cli_connect_recv] (0x0400): Connection established.
(2022-06-16  0:37:59): [be[$domain]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: ../src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2113
(2022-06-16  0:37:59): [be[$domain]] [fo_set_port_status] (0x0100): Marking port 636 of server 'ldap.domain' as 'working'
(2022-06-16  0:37:59): [be[$domain]] [set_server_common_status] (0x0100): Marking server 'ldap.domain' as 'working'
(2022-06-16  0:37:59): [be[$domain]] [fo_set_port_status] (0x0400): Marking port 636 of duplicate server 'ldap.domain' as 'working'
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_done] (0x2000): Old USN: 0, New USN: 0
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_refresh_connect_done] (0x0400): SUDO LDAP connection successful
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_load_sudoers_send] (0x0400): About to fetch sudo rules
(2022-06-16  0:37:59): [be[$domain]] [sdap_search_bases_ex_next_base] (0x0400): Issuing LDAP lookup with base [o=domain,dc=xxx,dc=xx]
(2022-06-16  0:37:59): [be[$domain]] [sdap_print_server] (0x2000): Searching $ip_ldap:636
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(&(objectClass=sudoRole)(modifyTimestamp>=00000101000000Z))(|(&(!(sudoHost=*))(cn=defaults))(sudoHost=ALL)(sudoHost=ssh)(sudoHost=ssh.domain)(sudoHost=$ip_ssh)(sudoHost=$network_mask/cidr)(sudoHost=XXX)(sudoHost=fe80::/64)(sudoHost=+*)))][o=domain,dc=xxx,dc=xx].
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoCommand]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoHost]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoUser]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOption]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAs]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsUser]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsGroup]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotBefore]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotAfter]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOrder]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 2
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_add] (0x2000): New operation 2 timeout 6
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_done] (0x4000): notify connected to op #2
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_iphost_next_base] (0x0400): Searching for IP host with base [o=domain,dc=xxx,dc=xx]
(2022-06-16  0:37:59): [be[$domain]] [sdap_print_server] (0x2000): Searching $ip_ldap:636
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipHost)(cn=*)(ipHostNumber=*))][o=domain,dc=xxx,dc=xx].
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipHostNumber]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 3
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_add] (0x2000): New operation 3 timeout 6
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_done] (0x4000): notify connected to op #3
(2022-06-16  0:37:59): [be[$domain]] [sdap_search_user_next_base] (0x0400): Searching for users with base [o=domain,dc=xxx,dc=xx]
(2022-06-16  0:37:59): [be[$domain]] [sdap_print_server] (0x2000): Searching $ip_ldap:636
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=posixAccount)(uid=*)(uidNumber=*)(gidNumber=*)(modifyTimestamp>=20220615083334Z)(!(modifyTimestamp=20220615083334Z)))][o=domain,dc=xxx,dc=xx].
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [rhost]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sshPublicKey]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 4
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_add] (0x2000): New operation 4 timeout 60
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 3 notifies
(2022-06-16  0:37:59): [be[$domain]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: sh[0x555eb4d051a0], connected[1], ops[0x555eb4f8cd80], ldap[0x555eb4e9dac0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: sh[0x555eb4d051a0], connected[1], ops[0x555eb4f8cd80], ldap[0x555eb4e9dac0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_op_finished] (0x2000): Total count [0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_destructor] (0x2000): Operation 2 finished
(2022-06-16  0:37:59): [be[$domain]] [sdap_search_bases_ex_done] (0x0400): Receiving data from base [o=domain,dc=xxx,dc=xx]
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_load_sudoers_done] (0x0200): Received 0 sudo rules
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_done] (0x4000): releasing operation connection
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_refresh_done] (0x0400): Received 0 rules
(2022-06-16  0:37:59): [be[$domain]] [sysdb_sudo_purge_byrules] (0x0400): About to remove rules from sudo cache
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_refresh_done] (0x0400): Sudoers is successfully stored in cache
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_set_usn] (0x0200): SUDO higher USN value: [00000101000000Z]
(2022-06-16  0:37:59): [be[$domain]] [sdap_sudo_smart_refresh_done] (0x0400): Successful smart refresh of sudo rules
(2022-06-16  0:37:59): [be[$domain]] [be_ptask_done] (0x0400): Task [SUDO Smart Refresh]: finished successfully
(2022-06-16  0:37:59): [be[$domain]] [be_ptask_schedule] (0x0400): Task [SUDO Smart Refresh]: scheduling task 900 seconds from last execution time [1655333579]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: sh[0x555eb4d051a0], connected[1], ops[0x555eb4f8cd80], ldap[0x555eb4e9dac0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_op_finished] (0x2000): Total count [0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_destructor] (0x2000): Operation 3 finished
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_iphost_process] (0x0400): Search for IP hosts returned 0 results.
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_done] (0x4000): releasing operation connection
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_ipnetwork_next_base] (0x0400): Searching for IP network with base [o=domain,dc=xxx,dc=xx]
(2022-06-16  0:37:59): [be[$domain]] [sdap_print_server] (0x2000): Searching $ip_ldap:636
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipNetwork)(cn=*)(ipNetworkNumber=*))][o=domain,dc=xxx,dc=xx].
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipNetworkNumber]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_add] (0x2000): New operation 5 timeout 6
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: sh[0x555eb4d051a0], connected[1], ops[0x555eb501aa40], ldap[0x555eb4e9dac0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_result] (0x2000): Trace: sh[0x555eb4d051a0], connected[1], ops[0x555eb501aa40], ldap[0x555eb4e9dac0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_generic_op_finished] (0x2000): Total count [0]
(2022-06-16  0:37:59): [be[$domain]] [sdap_op_destructor] (0x2000): Operation 5 finished
(2022-06-16  0:37:59): [be[$domain]] [sdap_get_ipnetwork_process] (0x0400): Search for IP networks returned 0 results.
(2022-06-16  0:37:59): [be[$domain]] [sdap_id_op_done] (0x4000): releasing operation connection

before 0:40:06

(2022-06-16  0:39:35): [be[$domain]] [dp_load_module] (0x0400): About to load module [ldap].
(2022-06-16  0:39:35): [be[$domain]] [dp_module_open_lib] (0x1000): Loading module [ldap] with path [/usr/lib/x86_64-linux-gnu/sssd/libsss_ldap.so]
(2022-06-16  0:39:47): [be[$domain]] [dp_module_run_constructor] (0x0400): Executing module [ldap] constructor.
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_uri has value ldaps://ldap.domain/ , ldaps://ldap-master.domain/
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_backup_uri has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_search_base has value o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_default_bind_dn has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_default_authtok_type has value password
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_default_authtok has no binary value.
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_search_timeout has value 6
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_network_timeout has value 6
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_opt_timeout has value 8
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_reqcert has value allow
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_search_base has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_search_scope has value sub
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_search_filter has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_extra_attrs has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_search_base has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_search_scope has value sub
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_search_filter has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_host_search_base has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_service_search_base has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_search_base has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_full_refresh_interval has value 21600
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_smart_refresh_interval has value 900
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_use_host_filter is TRUE
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_hostnames has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_ip has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_include_netgroups is TRUE
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_include_regexp is FALSE
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_autofs_search_base has no value 
(2022-06-16  0:39:47): [be[$domain]] [dp_get_options] (0x0400): Option ldap_autofs_map_master_name has value auto.master
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_iphost_search_base has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_ipnetwork_search_base has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_schema has value rfc2307
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_pwmodify_mode has value exop
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_offline_timeout has value 60
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_force_upper_case_realm is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_enumeration_refresh_timeout has value 300
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_purge_cache_timeout has value 0
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cacert has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cacertdir has value /etc/ssl/certs
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cert has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_key has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cipher_suite has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_id_use_start_tls is TRUE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_id_mapping is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_mech has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_authid has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_realm has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_minssf has value -1
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_maxssf has value -1
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_krb5_keytab has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_krb5_init_creds is TRUE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option krb5_server has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option krb5_backup_server has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option krb5_realm has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option krb5_canonicalize is TRUE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option krb5_use_kdcinfo is TRUE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option krb5_kdcinfo_lookahead has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_pwd_policy has value none
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_referrals is TRUE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option account_cache_expiration has value 0
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_dns_service_name has value ldap
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_krb5_ticket_lifetime has value 86400
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_access_filter has value (objectClass=posixAccount)
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_netgroup_search_base has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_nesting_level has value 2
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_deref has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_account_expire_policy has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_access_order has value filter
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_uri has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_backup_uri has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_dns_service_name has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_update_last_change is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_enumeration_search_timeout has value 60
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_auth_disable_tls_never_use_in_production is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_page_size has value 1000
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_deref_threshold has value 10
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_canonicalize is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_connection_expire_timeout has value 900
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_connection_expire_offset has value 0
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_disable_paging is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_range_min has value 200000
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_range_max has value 2000200000
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_range_size has value 200000
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_autorid_compat is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_default_domain has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_default_domain_sid has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_helper_table_size has value 10
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_use_tokengroups is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_rfc2307_fallback_to_local_users is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_disable_range_retrieval is FALSE
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_min_id has value 0
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_max_id has value 0
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_pwdlockout_dn has no value 
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option wildcard_limit has value 1000
(2022-06-16  0:39:49): [be[$domain]] [dp_get_options] (0x0400): Option ldap_library_debug_level has value 0
(2022-06-16  0:39:49): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_user_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:49): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_group_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:49): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_netgroup_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:49): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_host_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:49): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_service_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:49): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_iphost_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:49): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_ipnetwork_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [DEFAULT][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [USER][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [GROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [NETGROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [HOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [SERVICE][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPHOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPNETWORK][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_entry_usn has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_rootdse_last_usn has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_object_class has value posixAccount
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_name has value uid
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_pwd has value userPassword
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_uid_number has value uidNumber
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_gid_number has value gidNumber
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_gecos has value gecos
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_home_directory has value homeDirectory
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shell has value loginShell
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_principal has value krbPrincipalName
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_fullname has value cn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_member_of has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_uuid has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_objectsid has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_primary_group has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_modify_timestamp has value modifyTimestamp
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_entry_usn has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_last_change has value shadowLastChange
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_min has value shadowMin
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_max has value shadowMax
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_warning has value shadowWarning
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_inactive has value shadowInactive
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_expire has value shadowExpire
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_flag has value shadowFlag
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_krb_last_pwd_change has value krbLastPwdChange
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_krb_password_expiration has value krbPasswordExpiration
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_pwd_attribute has value pwdAttribute
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_authorized_service has value authorizedService
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_ad_account_expires has value accountExpires
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_ad_user_account_control has value userAccountControl
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ns_account_lock has value nsAccountLock
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_authorized_host has value host
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_authorized_rhost has value rhost
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_nds_login_disabled has value loginDisabled
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_nds_login_expiration_time has value loginExpirationTime
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_nds_login_allowed_time_map has value loginAllowedTimeMap
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_ssh_public_key has value sshPublicKey
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_auth_type has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_certificate has value userCertificate;binary
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_email has value mail
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_object_class has value posixGroup
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_object_class_alt has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_name has value cn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_pwd has value userPassword
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_gid_number has value gidNumber
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_member has value memberUid
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_uuid has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_objectsid has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_modify_timestamp has value modifyTimestamp
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_entry_usn has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_type has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_external_member has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_object_class has value nisNetgroup
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_name has value cn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_member has value memberNisNetgroup
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_triple has value nisNetgroupTriple
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_modify_timestamp has value modifyTimestamp
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_object_class has value ipHost
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_name has value cn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_fqdn has value fqdn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_serverhostname has value serverHostname
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_member_of has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_ssh_public_key has value sshPublicKey
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_uuid has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_object_class has value ipService
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_name has value cn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_port has value ipServicePort
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_proto has value ipServiceProtocol
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_entry_usn has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_object_class has value ipHost
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_name has value cn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_number has value ipHostNumber
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_entry_usn has no value 
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_object_class has value ipNetwork
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_name has value cn
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_number has value ipNetworkNumber
(2022-06-16  0:39:49): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_entry_usn has no value 
(2022-06-16  0:39:49): [be[$domain]] [krb5_try_kdcip] (0x0100): No KDC found in configuration, trying legacy option
(2022-06-16  0:39:49): [be[$domain]] [get_sdap_service] (0x0100): Service name for discovery set to ldap
(2022-06-16  0:39:49): [be[$domain]] [fo_new_service] (0x0400): Creating new service 'LDAP'
(2022-06-16  0:39:49): [be[$domain]] [_sdap_urls_init] (0x0400): Added URI ldaps://ldap.domain/
(2022-06-16  0:39:49): [be[$domain]] [fo_add_server_to_list] (0x0400): Inserted primary server 'ldap.domain:636' to service 'LDAP'
(2022-06-16  0:39:49): [be[$domain]] [_sdap_urls_init] (0x0400): Added URI ldaps://ldap-master.domain/
(2022-06-16  0:39:49): [be[$domain]] [fo_add_server_to_list] (0x0400): Inserted primary server 'ldap-master.domain:636' to service 'LDAP'

before 0:40:37

(2022-06-16  0:40:09): [be[$domain]] [sbus_server_socket_listen] (0x0400): D-BUS Server listening on unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain.188014,guid=291e59a5fad3fbf3178aadb262aa5fc9
(2022-06-16  0:40:09): [be[$domain]] [sbus_server_symlink_create] (0x1000): Symlinking the dbus path /var/lib/sss/pipes/private/sbus-dp_$domain.188014 to a link /var/lib/sss/pipes/private/sbus-dp_$domain
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /*
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /*
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus on path /org/freedesktop/DBus
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_add] (0x2000): Created a enabled R/- watch on 15
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /*
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /*
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_add] (0x2000): Created a enabled -/W watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled R/- watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled R/- watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled -/W watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_server_new_connection] (0x0200): Adding connection 0x555b34d21160.
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /*
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /*
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_add] (0x2000): Created a disabled -/W watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled R/- watch on 17
(2022-06-16  0:40:09): [be[$domain]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x555b34d249e0]
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled R/- watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled -/W watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled R/- watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled -/W watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled R/- watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled -/W watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled R/- watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled -/W watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled R/- watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled -/W watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled R/- watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled -/W watch on 17
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled R/- watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled -/W watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to enabled R/- watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_watch_toggle] (0x4000): Toggle to disabled -/W watch on 16
(2022-06-16  0:40:09): [be[$domain]] [sbus_dispatch] (0x4000): Dispatching.
(2022-06-16  0:40:09): [be[$domain]] [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.Hello on /org/freedesktop/DBus
(2022-06-16  0:40:09): [be[$domain]] [sbus_server_bus_hello] (0x4000): Assigning unique name :1.1 to connection 0x555b34d21690
(2022-06-16  0:40:09): [be[$domain]] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.Hello: Success
(2022-06-16  0:40:09): [be[$domain]] [sbus_dispatch] (0x4000): Dispatching.
(2022-06-16  0:40:09): [be[$domain]] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameAcquired on /org/freedesktop/DBus
(2022-06-16  0:40:09): [be[$domain]] [sbus_signal_handler] (0x0200): We do not listen to this signal!
(2022-06-16  0:40:09): [be[$domain]] [sbus_dispatch] (0x4000): Dispatching.
(2022-06-16  0:40:09): [be[$domain]] [sbus_dispatch] (0x4000): Dispatching.
(2022-06-16  0:40:09): [be[$domain]] [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.RequestName on /org/freedesktop/DBus
(2022-06-16  0:40:09): [be[$domain]] [sbus_server_bus_request_name] (0x0400): Requesting name: sssd.domain_$domain
(2022-06-16  0:40:09): [be[$domain]] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.RequestName: Success
(2022-06-16  0:40:09): [be[$domain]] [sbus_dispatch] (0x4000): Dispatching.
(2022-06-16  0:40:09): [be[$domain]] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameAcquired on /org/freedesktop/DBus
(2022-06-16  0:40:09): [be[$domain]] [sbus_signal_handler] (0x0200): We do not listen to this signal!
(2022-06-16  0:40:09): [be[$domain]] [sbus_dispatch] (0x4000): Dispatching.
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_listen] (0x0400): Registering signal listener org.freedesktop.DBus.NameOwnerChanged on path /org/freedesktop/DBus
(2022-06-16  0:40:09): [be[$domain]] [sbus_router_listen] (0x0400): Registering signal listener org.freedesktop.DBus.NameAcquired on path /org/freedesktop/DBus
(2022-06-16  0:40:09): [be[$domain]] [sbus_connect_private_done] (0x0400): Connected to unix:path=/var/lib/sss/pipes/private/sbus-dp_$domain bus as sssd.domain_$domain
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [id]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [auth]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [access]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [chpass]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [sudo]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [autofs]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [selinux]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [hostid]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [subdomains]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [session]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_configuration] (0x0100): Using [ldap] provider for [resolver]
(2022-06-16  0:40:09): [be[$domain]] [dp_target_init] (0x0400): Initializing target [id] with module [ldap]
(2022-06-16  0:40:09): [be[$domain]] [dp_load_module] (0x0400): About to load module [ldap].
(2022-06-16  0:40:09): [be[$domain]] [dp_module_open_lib] (0x1000): Loading module [ldap] with path [/usr/lib/x86_64-linux-gnu/sssd/libsss_ldap.so]
(2022-06-16  0:40:09): [be[$domain]] [dp_module_run_constructor] (0x0400): Executing module [ldap] constructor.
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_uri has value ldaps://ldap.domain/ , ldaps://ldap-master.domain/
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_backup_uri has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_search_base has value o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_default_bind_dn has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_default_authtok_type has value password
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_default_authtok has no binary value.
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_search_timeout has value 6
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_network_timeout has value 6
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_opt_timeout has value 8
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_reqcert has value allow
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_search_scope has value sub
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_search_filter has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_user_extra_attrs has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_search_scope has value sub
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_search_filter has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_host_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_service_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_full_refresh_interval has value 21600
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_smart_refresh_interval has value 900
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_use_host_filter is TRUE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_hostnames has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_ip has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_include_netgroups is TRUE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sudo_include_regexp is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_autofs_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_autofs_map_master_name has value auto.master
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_iphost_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_ipnetwork_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_schema has value rfc2307
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_pwmodify_mode has value exop
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_offline_timeout has value 60
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_force_upper_case_realm is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_enumeration_refresh_timeout has value 300
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_purge_cache_timeout has value 0
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cacert has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cacertdir has value /etc/ssl/certs
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cert has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_key has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_tls_cipher_suite has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_id_use_start_tls is TRUE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_id_mapping is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_mech has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_authid has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_realm has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_minssf has value -1
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_maxssf has value -1
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_krb5_keytab has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_krb5_init_creds is TRUE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option krb5_server has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option krb5_backup_server has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option krb5_realm has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option krb5_canonicalize is TRUE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option krb5_use_kdcinfo is TRUE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option krb5_kdcinfo_lookahead has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_pwd_policy has value none
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_referrals is TRUE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option account_cache_expiration has value 0
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_dns_service_name has value ldap
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_krb5_ticket_lifetime has value 86400
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_access_filter has value (objectClass=posixAccount)
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_netgroup_search_base has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_group_nesting_level has value 2
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_deref has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_account_expire_policy has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_access_order has value filter
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_uri has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_backup_uri has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_dns_service_name has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_chpass_update_last_change is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_enumeration_search_timeout has value 60
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_auth_disable_tls_never_use_in_production is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_page_size has value 1000
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_deref_threshold has value 10
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_sasl_canonicalize is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_connection_expire_timeout has value 900
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_connection_expire_offset has value 0
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_disable_paging is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_range_min has value 200000
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_range_max has value 2000200000
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_range_size has value 200000
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_autorid_compat is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_default_domain has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_default_domain_sid has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_idmap_helper_table_size has value 10
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_use_tokengroups is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_rfc2307_fallback_to_local_users is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_disable_range_retrieval is FALSE
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_min_id has value 0
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_max_id has value 0
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_pwdlockout_dn has no value 
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option wildcard_limit has value 1000
(2022-06-16  0:40:09): [be[$domain]] [dp_get_options] (0x0400): Option ldap_library_debug_level has value 0
(2022-06-16  0:40:09): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_user_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_group_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_netgroup_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_host_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_service_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_iphost_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [ldap_get_options] (0x0400): Option ldap_ipnetwork_search_base set to o=domain,dc=xxx,dc=xx
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [DEFAULT][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [USER][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [GROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [NETGROUP][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [HOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [SERVICE][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPHOST][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [common_parse_search_base] (0x0100): Search base added: [IPNETWORK][o=domain,dc=xxx,dc=xx][SUBTREE][]
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_entry_usn has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_rootdse_last_usn has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_object_class has value posixAccount
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_name has value uid
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_pwd has value userPassword
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_uid_number has value uidNumber
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_gid_number has value gidNumber
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_gecos has value gecos
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_home_directory has value homeDirectory
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shell has value loginShell
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_principal has value krbPrincipalName
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_fullname has value cn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_member_of has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_uuid has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_objectsid has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_primary_group has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_modify_timestamp has value modifyTimestamp
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_entry_usn has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_last_change has value shadowLastChange
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_min has value shadowMin
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_max has value shadowMax
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_warning has value shadowWarning
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_inactive has value shadowInactive
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_expire has value shadowExpire
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_shadow_flag has value shadowFlag
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_krb_last_pwd_change has value krbLastPwdChange
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_krb_password_expiration has value krbPasswordExpiration
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_pwd_attribute has value pwdAttribute
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_authorized_service has value authorizedService
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_ad_account_expires has value accountExpires
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_ad_user_account_control has value userAccountControl
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ns_account_lock has value nsAccountLock
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_authorized_host has value host
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_authorized_rhost has value rhost
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_nds_login_disabled has value loginDisabled
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_nds_login_expiration_time has value loginExpirationTime
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_nds_login_allowed_time_map has value loginAllowedTimeMap
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_ssh_public_key has value sshPublicKey
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_auth_type has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_certificate has value userCertificate;binary
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_user_email has value mail
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_object_class has value posixGroup
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_object_class_alt has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_name has value cn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_pwd has value userPassword
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_gid_number has value gidNumber
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_member has value memberUid
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_uuid has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_objectsid has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_modify_timestamp has value modifyTimestamp
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_entry_usn has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_type has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_group_external_member has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_object_class has value nisNetgroup
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_name has value cn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_member has value memberNisNetgroup
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_triple has value nisNetgroupTriple
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_netgroup_modify_timestamp has value modifyTimestamp
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_object_class has value ipHost
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_name has value cn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_fqdn has value fqdn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_serverhostname has value serverHostname
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_member_of has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_ssh_public_key has value sshPublicKey
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_host_uuid has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_object_class has value ipService
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_name has value cn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_port has value ipServicePort
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_proto has value ipServiceProtocol
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_service_entry_usn has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_object_class has value ipHost
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_name has value cn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_number has value ipHostNumber
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_iphost_entry_usn has no value 
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_object_class has value ipNetwork
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_name has value cn
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_number has value ipNetworkNumber
(2022-06-16  0:40:09): [be[$domain]] [sdap_get_map] (0x0400): Option ldap_ipnetwork_entry_usn has no value 
(2022-06-16  0:40:09): [be[$domain]] [krb5_try_kdcip] (0x0100): No KDC found in configuration, trying legacy option
(2022-06-16  0:40:09): [be[$domain]] [get_sdap_service] (0x0100): Service name for discovery set to ldap
(2022-06-16  0:40:09): [be[$domain]] [fo_new_service] (0x0400): Creating new service 'LDAP'
(2022-06-16  0:40:09): [be[$domain]] [_sdap_urls_init] (0x0400): Added URI ldaps://ldap.domain/
(2022-06-16  0:40:09): [be[$domain]] [fo_add_server_to_list] (0x0400): Inserted primary server 'ldap.domain:636' to service 'LDAP'
(2022-06-16  0:40:09): [be[$domain]] [_sdap_urls_init] (0x0400): Added URI ldaps://ldap-master.domain/
(2022-06-16  0:40:09): [be[$domain]] [fo_add_server_to_list] (0x0400): Inserted primary server 'ldap-master.domain:636' to service 'LDAP'
(2022-06-16  0:40:20): [be[$domain]] [sysdb_idmap_get_mappings] (0x4000): cn=id_mappings,cn=$domain,cn=sysdb
(2022-06-16  0:40:20): [be[$domain]] [sysdb_idmap_get_mappings] (0x0080): Could not locate ID mappings: [No such file or directory]
(2022-06-16  0:40:20): [be[$domain]] [sdap_id_setup_tasks] (0x0400): Setting up enumeration for $domain
(2022-06-16  0:40:20): [be[$domain]] [be_ptask_create] (0x0400): Periodic task [Enumeration [id] of $domain] was created
(2022-06-16  0:40:20): [be[$domain]] [be_ptask_schedule] (0x0400): Task [Enumeration [id] of $domain]: scheduling task 10 seconds from now [1655332830]
(2022-06-16  0:40:20): [be[$domain]] [be_fo_set_srv_lookup_plugin] (0x0400): Trying to set SRV lookup plugin to DNS
(2022-06-16  0:40:20): [be[$domain]] [be_fo_set_srv_lookup_plugin] (0x0400): SRV lookup plugin is now DNS
(2022-06-16  0:40:20): [be[$domain]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't handle this DN type, skipping
(2022-06-16  0:40:20): [be[$domain]] [sysdb_delete_recursive_with_filter] (0x4000): Found [1] items to delete.
(2022-06-16  0:40:20): [be[$domain]] [sysdb_delete_recursive_with_filter] (0x4000): Trying to delete [cn=certmap,cn=sysdb].

In the logs that I posted there are not SSS_PAM_OPEN_SESSION messages. These messages should be printed only when user try to connect, am I right ?

There were two parts of log with SSS_PAM_OPENSESSION messages at (2022-06-16 0:36:55) and (2022-06-16 0:37:36) so it was before first watchdog at (2022-06-16 0:38:26)_ and users are connected succesfully. The next SSS_PAM_OPENSESSION was at (2022-06-16 2:01:16)_ : after sssd became functional.

What is in sssd.log at 1:34:10 (when responders were shut down - 'orderly_shutdown')?

Surpisingly nothing. ... The next line after 0:40 is at 0:32 this night (17.06). This night it was killed again and this time it didn't restart properly : systemctl status sssd indicate active, but systemctl status sssd-nss was failed and authentication didn't work until I restart sssd service.

I just realized you have #services = nss, pam in your sssd.conf, i.e. you rely on systemd-activated sssd_nss / sssd_pam, that's why there is nothing in sssd.log

(2022-06-16  0:39:35): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-16  0:40:06): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-16  0:40:37): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:32:27): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:33:00): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:33:31): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:34:13): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:34:48): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:36:17): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:37:01): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0
(2022-06-17  0:38:03): [be[$domain]] [server_setup] (0x0040): Starting with debug level = 0xf7f0

So when something wrong happens => sssd_be process is stuck => terminated by watchdog => sssd restarts it, but it takes several attempts. I see no common pattern in messages before process in terminated. Hence I think reason is outside of sssd or maybe it is in something very generic, like system read()/write() to cache files. You don't have timeout specified in [domain] section of sssd.conf. By default it is 10. Process should be self-terminated when it doesn't process 3 pings, so between 21 and 30 seconds. In the logs there is:

0:37:59 -> 0:38:26 -- 27 seconds
0:39:49 -> 0:40:06 -- 17 seconds
0:40:20 -> 0:40:37 -- 17 seconds That's weird process is self terminated in 17 seconds.

You could try to increase timeout in the [domain] (and perhaps other) section and see if this help. Try, for example, 30.

Other option could be to modify /etc/systemd/system/multi-user.target.wants/sssd.service to run it and processes it forks under strace and log strace output to file in order to determine what exactly sssd_be is doing when it's terminated by a signal.

Ok, thank you for your help.

I just realized you have #services = nss, pam in your sssd.conf, i.e. you rely on systemd-activated sssd_nss / sssd_pam, that's why there is nothing in sssd.log

Yes I spoke about it in y first messages. It was uncommented before, but it seems that it better to comment this line now. Could you confirm it ?

I also put "timeout = 15" into global [sssd] section? I thought it will be also active for [domain], but if it's not : it's a good idea. I will put some timeout into domain section as well.

I have also some new details about this issue.

1) Actually we almost know the main reason for this problem : the peak of load that cause sssd killing is explained by Proxmox backup sessions. We did some arrangements to change backup planning etc.

So we solved partially the problem, at least our sssd don't stop each day.

2) But it seems to me that there is still a little problem about functioning of sssd. Or at least there are some things that I don't understand.

a) sssd_be process is stuck because of high load (cause by Proxmox in our case or another reason) ; b) So sssd try to restart... and fail. An for the moment I don't understand why it fail ? As I understand, the timeout option is [domain] section is useful to prevent sssd_be from being killed. Am I right ?

But could we do something about restarting process ?

3) Another strange thing (for me) about this restarting problem : when this problem happens the status of sssd service is still active, but authentication doesn't work. If at least the sssd service were stopped or failed : we could detect the problem using monitoring system.

4) The question I asked in my first message. There is an option "RestartSec" for systemd services.

Could this option be useful for our case ? May be if we restart sssd more slowly we could have more chances that it will restart successfully ?

I just realized you have #services = nss, pam in your sssd.conf, i.e. you rely on systemd-activated sssd_nss / sssd_pam, that's why there is nothing in sssd.log

Yes I spoke about it in y first messages. It was uncommented before, but it seems that it better to comment this line now. Could you confirm it ?

Frankly, it's not often I see sssd_nss and sssd_pam are used as a systemd-activated service. Usually this is only sssd_kcm. sssd_nss is required for every name<->id resolution (getpw*(), getgr*(), etc) so, imo, it doesn't make much sense to not have it running permanently (and currently the simplest way to achieve this is to let main SSSD process - sssd - run it via sssd.conf)

I also put "timeout = 15" into global [sssd] section? I thought it will be also active for [domain], but if it's not : it's a good idea. I will put some timeout into domain section as well.

This is per service/domain option - see man sssd.conf ("Options usable in SERVICE and DOMAIN sections")

a) sssd_be process is stuck because of high load (cause by Proxmox in our case or another reason) ; b) So sssd try to restart... and fail. An for the moment I don't understand why it fail ?

I guess because machine is still under high load and some basic operations sssd_be performs at startup (like updating configs) are stuck? I don't recall right now, but perhaps there is a counter / limit on restart attempts.

As I understand, the timeout option is [domain] section is useful to prevent sssd_be from being killed. Am I right ?

If you identified root cause correctly, then setting this timeout large enough (2*timeout > period of high load) should help.

3. Another strange thing (for me) about this restarting problem : when this problem happens the status of sssd service is still active, but authentication doesn't work.

The reason is that systemd only see "main" ("umbrella") process - sssd. This process - sssd - acts as yet another one mini-systemd and manages service and domain processes (if configured). sssd doesn't propagate status of processes it manages to systemd.

Actually there is a long standing idea to get rid of this "main" sssd process and to rely on systemd entirely. Not implemented yet.

4. The question I asked in my first message.
   There is an option "RestartSec" for systemd services.
Could this option be useful for our case ? May be if we restart sssd more slowly we could have more chances that it will restart successfully ?

No, it doesn't affect the way sssd restarts sssd_be. And there is no way to configure systemd to manage sssd_be (as opposed to services - sssd_nss, sssd_pam, etc)

Thank you very much. It's more clear for me now.

I still have a little question about declaring service in "sssd" section.

In the past I always use this option. But on the actual server I noticed that there is a error during the boot complained about this option/line is activated (despite of this message, once the boot was finished sssd works well).

I have some look in man and found "The services' list is optional on platforms where systemd is supported, as they will either be socket or D-Bus activated when needed."

So I decided that it doesn't need anymore. Once commented the boot error message is gone.

In any case, it change nothing to the original problem (difficult for sssd to restart). It occurs in the both cases.

P.S.: Tomorrow, I could give the exact boot error message.

We have had a similar issue with CentOS Stream 8 when sssd LDAP child was killed by watchdog during high load but was not properly restarted, so basically ssh to the server was broken and did not restore by itself until sssd restart via systemd.

Child [854] (‘LDAP’:‘%BE_LDAP’) was terminated by own WATCHDOG. Consult corresponding logs to figure out the reason.

[be[LDAP]] [server_setup] (0x3f7c0): Starting with debug level = 0x0070

That's it in the logs so far. I understand that probably the server was too busy to start be[LDAP] properly, however I'm wondering why manual restart with systemctl restart sssd helped.

Could you please tell me if it's possible to configure the number of child restart attempts or timeouts between the restarts or restart the whole process after some timeout when the child is unresponsive?

update: probably reconnection_retries is what I'm looking for?

I understand that probably the server was too busy to start be[LDAP] properly, however I'm wondering why manual restart with systemctl restart sssd helped.

Sorry, impossible to tell without logs with debug_level=9. In your quote even timestamps are cut off so order is unclear.

With a debug level high enough, one could:

check sssd_$domain.log around timestamp of was terminated by own WATCHDOG message in sssd.log to see what it was busy with
check sssd.logto see why restart attempts failed
check sssd_nss.log and sssd_pam.log if responders reconnected to the backend (sssd_be)

I understand that probably the server was too busy to start be[LDAP] properly, however I'm wondering why manual restart with systemctl restart sssd helped.

Sorry, impossible to tell without logs with debug_level=9. In your quote even timestamps are cut off so order is unclear.

With a debug level high enough, one could:

check sssd_$domain.log around timestamp of was terminated by own WATCHDOG message in sssd.log to see what it was busy with

check sssd.logto see why restart attempts failed

check sssd_nss.log and sssd_pam.log if responders reconnected to the backend (sssd_be)

Sorry, I just wanted to mention fast that we had something smilar. I'm back with some logs:

sssd.log:

   *  (2023-01-20 13:17:15): [sssd] [mt_svc_exit_handler] (0x1000): SIGCHLD handler of service nss called
   *  (2023-01-20 13:17:18): [sssd] [svc_child_info] (0x0020): Child [877] ('nss':'nss') was terminated by own WATCHDOG
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:17:35): [sssd] [svc_child_info] (0x0020): Child [854] ('LDAP':'%BE_LDAP') was terminated by own WATCHDOG
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:17:51): [sssd] [svc_child_info] (0x0040): Child [2586699] ('nss':'nss') exited with code [3]
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2023-01-20 13:17:36): [sssd] [sbus_dispatch_reconnect] (0x0400): Connection lost. Terminating active requests.
   *  (2023-01-20 13:17:36): [sssd] [sbus_dispatch_reconnect] (0x4000): Remote client terminated the connection. Releasing data...
   *  (2023-01-20 13:17:36): [sssd] [sbus_connection_free] (0x4000): Connection 0x56252d2b3d30 will be freed during next loop!
   *  (2023-01-20 13:17:36): [sssd] [mt_svc_restart] (0x0400): Scheduling service nss for restart 1
   *  (2023-01-20 13:17:42): [sssd] [get_service_config] (0x0100): Formed command '/usr/libexec/sssd/sssd_nss --uid 0 --gid 0 --logger=files' for service 'nss'
   *  (2023-01-20 13:17:42): [sssd] [start_service] (0x0100): Queueing service nss for startup
   *  (2023-01-20 13:17:42): [sssd] [mt_svc_restart] (0x0400): Scheduling service LDAP for restart 1
   *  (2023-01-20 13:17:43): [sssd] [get_provider_config] (0x0100): Formed command '/usr/libexec/sssd/sssd_be --domain LDAP --uid 0 --gid 0 --logger=files' for provider '%BE_LDAP'
   *  (2023-01-20 13:17:43): [sssd] [start_service] (0x0100): Queueing service LDAP for startup
   *  (2023-01-20 13:17:43): [sssd] [sbus_watch_toggle] (0x4000): Toggle to enabled -/W watch on 23
   *  (2023-01-20 13:17:43): [sssd] [sbus_dispatch_reconnect] (0x0400): Connection lost. Terminating active requests.
   *  (2023-01-20 13:17:43): [sssd] [sbus_dispatch_reconnect] (0x4000): Remote client terminated the connection. Releasing data...
   *  (2023-01-20 13:17:43): [sssd] [sbus_connection_free] (0x4000): Connection 0x56252d276790 will be freed during next loop!
   *  (2023-01-20 13:17:43): [sssd] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:43): [sssd] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:43): [sssd] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:43): [sssd] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:43): [sssd] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:43): [sssd] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:43): [sssd] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:43): [sssd] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:43): [sssd] [sbus_name_owner_changed] (0x4000): Name of owner sssd.nss has changed from [sssd.nss] to []
   *  (2023-01-20 13:17:43): [sssd] [sbus_senders_delete] (0x2000): Removing identity of sender [sssd.nss]
   *  (2023-01-20 13:17:43): [sssd] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:17:43): [sssd] [sbus_name_owner_changed] (0x4000): Name of owner :1.6 has changed from [:1.6] to []
   *  (2023-01-20 13:17:43): [sssd] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:17:43): [sssd] [sbus_name_owner_changed] (0x4000): Name of owner sssd.domain_LDAP has changed from [sssd.domain_LDAP] to []
   *  (2023-01-20 13:17:43): [sssd] [sbus_senders_delete] (0x2000): Removing identity of sender [sssd.domain_LDAP]
   *  (2023-01-20 13:17:43): [sssd] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:17:43): [sssd] [sbus_name_owner_changed] (0x4000): Name of owner :1.3 has changed from [:1.3] to []
   *  (2023-01-20 13:17:43): [sssd] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:17:51): [sssd] [mt_svc_exit_handler] (0x1000): SIGCHLD handler of service nss called
   *  (2023-01-20 13:17:51): [sssd] [svc_child_info] (0x0040): Child [2586699] ('nss':'nss') exited with code [3]
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:27:26): [sssd] [monitor_quit_signal] (0x3f7c0): Monitor received Terminated: terminating children
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Returned with: 0
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Terminating [nss][2586802]
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Child [nss] exited gracefully
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Terminating [LDAP][2586700]
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Child [LDAP] terminated with a signal
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Terminating [ssh][879]
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Child [ssh] exited gracefully
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Terminating [pam][878]
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Child [pam] exited gracefully
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Terminating [implicit_files][853]
(2023-01-20 13:27:26): [sssd] [monitor_quit] (0x3f7c0): Child [implicit_files] exited gracefully
(2023-01-20 13:27:26): [sssd] [server_setup] (0x3f7c0): Starting with debug level = 0x0070
(2023-01-21  3:22:01): [sssd] [monitor_hup] (0x3f7c0): Monitor received SIGHUP

sssd_LDAP.log:

(2023-01-20 13:17:52): [be[LDAP]] [server_setup] (0x3f7c0): Starting with debug level = 0x0070
(2023-01-20 13:27:26): [be[LDAP]] [orderly_shutdown] (0x3f7c0): SIGTERM: killing children
(2023-01-20 13:27:26): [be[LDAP]] [orderly_shutdown] (0x3f7c0): Shutting down (status = 0)(2023-01-20 13:27:26): [be[LDAP]] [server_setup] (0x3f7c0): Starting with debug level = 0x0070

sssd_nss.log:

(2023-01-20 13:17:51): [nss] [server_setup] (0x3f7c0): Starting with debug level = 0x0070
(2023-01-20 13:17:51): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_LDAP [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_LDAP: Connection refused
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  [nss] [become_user] (0x0200): Trying to become user [0][0].
   *  [nss] [become_user] (0x0200): Already user [0].
   *  [nss] [sss_set_sssd_user_eid] (0x0080): Failed to set egid to 993: Operation not permitted
   *  [nss] [ldb] (0x0400): server_sort:Unable to register control with rootdse!
   *  (2023-01-20 13:17:51): [nss] [server_setup] (0x0400): CONFDB: /var/lib/sss/db/config.ldb
   *  (2023-01-20 13:17:51): [nss] [confdb_init_domain_provider_and_enum] (0x0400): No enumeration for [implicit_files]!
   *  (2023-01-20 13:17:51): [nss] [confdb_init_domain_provider_and_enum] (0x0400): Please note that when enumeration is disabled `getent passwd` does not return all users by design. See sssd.conf man page for more detailed information
   *  (2023-01-20 13:17:51): [nss] [confdb_init_domain_pwd_expire] (0x1000): pwd_expiration_warning is -1
   *  (2023-01-20 13:17:51): [nss] [confdb_init_domain_provider_and_enum] (0x0400): No enumeration for [LDAP]!
   *  (2023-01-20 13:17:51): [nss] [confdb_init_domain_provider_and_enum] (0x0400): Please note that when enumeration is disabled `getent passwd` does not return all users by design. See sssd.conf man page for more detailed information
   *  (2023-01-20 13:17:51): [nss] [confdb_init_domain_pwd_expire] (0x1000): pwd_expiration_warning is -1
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /bin/sh in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /bin/bash in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /usr/bin/sh in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /usr/bin/bash in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /bin/csh in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /bin/tcsh in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /usr/bin/csh in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_get_etc_shells] (0x0400): Found shell /usr/bin/tcsh in /etc/shells
   *  (2023-01-20 13:17:51): [nss] [sss_names_init_from_args] (0x0100): Using re [(?P<name>[^@]+)@?(?P<domain>[^@]*$)].
   *  (2023-01-20 13:17:51): [nss] [sss_fqnames_init] (0x0100): Using fq format [%1$s@%2$s].
   *  (2023-01-20 13:17:51): [nss] [sbus_dbus_connect_address] (0x0400): Connected to unix:path=/var/lib/sss/pipes/private/sbus-dp_implicit_files bus as sssd.nss
   *  (2023-01-20 13:17:51): [nss] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /
   *  (2023-01-20 13:17:51): [nss] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Introspectable on path /*
   *  (2023-01-20 13:17:51): [nss] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /
   *  (2023-01-20 13:17:51): [nss] [sbus_router_add_path] (0x0400): Registering interface org.freedesktop.DBus.Properties on path /*
   *  (2023-01-20 13:17:51): [nss] [sbus_watch_add] (0x2000): Created a disabled -/W watch on 12
   *  (2023-01-20 13:17:51): [nss] [sbus_watch_toggle] (0x4000): Toggle to enabled R/- watch on 12
   *  (2023-01-20 13:17:51): [nss] [sbus_router_listen] (0x0400): Registering signal listener org.freedesktop.DBus.NameOwnerChanged on path /org/freedesktop/DBus
   *  (2023-01-20 13:17:51): [nss] [sbus_router_listen] (0x0400): Registering signal listener org.freedesktop.DBus.NameAcquired on path /org/freedesktop/DBus
   *  (2023-01-20 13:17:51): [nss] [sbus_router_add_path] (0x0400): Registering interface sssd.Responder.Domain on path /sssd
   *  (2023-01-20 13:17:51): [nss] [sbus_router_add_path] (0x0400): Registering interface sssd.Responder.NegativeCache on path /sssd
   *  (2023-01-20 13:17:51): [nss] [sss_domain_get_state] (0x1000): Domain LDAP is Active
   *  (2023-01-20 13:17:51): [nss] [sss_names_init_from_args] (0x0100): Using re [(?P<name>[^@]+)@?(?P<domain>[^@]*$)].
   *  (2023-01-20 13:17:51): [nss] [sss_fqnames_init] (0x0100): Using fq format [%1$s@%2$s].
   *  (2023-01-20 13:17:51): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_LDAP [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_LDAP: Connection refused
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:17:51): [nss] [sss_dp_init] (0x0010): Failed to connect to backend server.
(2023-01-20 13:17:51): [nss] [sss_process_init] (0x0010): fatal error setting up backend connector
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2023-01-20 13:17:51): [nss] [sss_dp_init] (0x0010): Failed to connect to backend server.
   *  (2023-01-20 13:17:51): [nss] [sss_process_init] (0x0010): fatal error setting up backend connector
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:17:51): [nss] [nss_process_init] (0x0010): sss_process_init() failed
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2023-01-20 13:17:51): [nss] [sss_responder_ctx_destructor] (0x0400): Responder is being shut down
   *  (2023-01-20 13:17:51): [nss] [nss_process_init] (0x0010): sss_process_init() failed
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:17:58): [nss] [server_setup] (0x3f7c0): Starting with debug level = 0x0070
(2023-01-20 13:27:26): [nss] [orderly_shutdown] (0x3f7c0): SIGTERM: killing children
(2023-01-20 13:27:26): [nss] [orderly_shutdown] (0x3f7c0): Shutting down (status = 0)(2023-01-20 13:27:26): [nss] [server_setup] (0x3f7c0): Starting with debug level = 0x0070

sssd_pam.log:

   *  (2023-01-20 13:16:04): [pam] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x558094157850][26]
   *  (2023-01-20 13:16:21): [pam] [client_idle_handler] (0x2000): Terminating idle client [0x5580940af780][25]
   *  (2023-01-20 13:16:21): [pam] [client_close_fn] (0x2000): Terminated client [0x5580940af780][25]
   *  (2023-01-20 13:16:37): [pam] [client_idle_handler] (0x2000): Terminating idle client [0x558094157850][26]
   *  (2023-01-20 13:16:49): [pam] [client_close_fn] (0x2000): Terminated client [0x558094157850][26]
   *  (2023-01-20 13:17:30): [pam] [sbus_dispatch_reconnect] (0x0400): Connection lost. Terminating active requests.
   *  (2023-01-20 13:17:32): [pam] [sbus_reconnect_attempt] (0x0080): Making reconnection attempt 1 to [unix:path=/var/lib/sss/pipes/private/sbus-dp_LDAP]
   *  (2023-01-20 13:17:36): [pam] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_LDAP [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_LDAP: Connection refused
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:17:36): [pam] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
(2023-01-20 13:17:41): [pam] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_LDAP [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_LDAP: Connection refused
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:17:41): [pam] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:17:51): [pam] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_LDAP [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_LDAP: Connection refused
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:17:51): [pam] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:17:51): [pam] [sbus_reconnect] (0x0020): Unable to reconnect: maximum retries exceeded.
(2023-01-20 13:17:51): [pam] [sss_dp_on_reconnect] (0x0010): Could not reconnect to LDAP provider.
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2023-01-20 13:17:51): [pam] [sbus_reconnect] (0x0020): Unable to reconnect: maximum retries exceeded.
   *  (2023-01-20 13:17:51): [pam] [sss_dp_on_reconnect] (0x0010): Could not reconnect to LDAP provider.
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:18:04): [pam] [pam_dp_send_req_done] (0x0020): [CID#351] PAM handler failed [1432158212]: SSSD is offline
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2023-01-20 13:17:51): [pam] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:51): [pam] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:51): [pam] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:51): [pam] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:51): [pam] [sbus_name_owner_changed] (0x4000): Name of owner sssd.nss has changed from [sssd.nss] to []
   *  (2023-01-20 13:17:51): [pam] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:17:51): [pam] [sbus_name_owner_changed] (0x4000): Name of owner :1.5 has changed from [:1.5] to []
   *  (2023-01-20 13:17:51): [pam] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:17:58): [pam] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:58): [pam] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:58): [pam] [sbus_name_owner_changed] (0x4000): Name of owner :1.6 has changed from [] to [:1.6]
   *  (2023-01-20 13:17:58): [pam] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:17:58): [pam] [sbus_dispatch] (0x4000): Dispatching.
   *  (2023-01-20 13:17:58): [pam] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2023-01-20 13:17:59): [pam] [sbus_name_owner_changed] (0x4000): Name of owner sssd.nss has changed from [] to [sssd.nss]
   *  (2023-01-20 13:17:59): [pam] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2023-01-20 13:18:03): [pam] [get_client_cred] (0x4000): Client [0x5580940e1ae0][15] creds: euid[0] egid[0] pid[2586690] cmd_line['sshd: someuser [priv]'].
   *  (2023-01-20 13:18:04): [pam] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x5580940e1ae0][15]
   *  (2023-01-20 13:18:04): [pam] [accept_fd_handler] (0x0400): [CID#351] Client [cmd sshd: someuser [priv]][uid 0][0x5580940e1ae0][15] connected to privileged pipe!
   *  (2023-01-20 13:18:04): [pam] [sss_cmd_get_version] (0x0200): [CID#351] Received client version [3].
   *  (2023-01-20 13:18:04): [pam] [sss_cmd_get_version] (0x0200): [CID#351] Offered version [3].
   *  (2023-01-20 13:18:04): [pam] [pam_cmd_acct_mgmt] (0x0100): [CID#351] entering pam_cmd_acct_mgmt
   *  (2023-01-20 13:18:04): [pam] [sss_domain_get_state] (0x1000): [CID#351] Domain LDAP is Active
   *  (2023-01-20 13:18:04): [pam] [sss_parse_name_for_domains] (0x0200): [CID#351] name 'someuser' matched without domain, user is someuser
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] command: SSS_PAM_ACCT_MGMT
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] domain: not set
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] user: someuser
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] service: sshd
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] tty: ssh
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] ruser: not set
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] rhost: 1.2.3.4
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] authtok type: 0 (No authentication token available)
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] newauthtok type: 0 (No authentication token available)
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] priv: 1
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] cli_pid: 2586690
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] child_pid: 0
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] logon name: someuser
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] flags: 0
   *  (2023-01-20 13:18:04): [pam] [cache_req_set_plugin] (0x2000): [CID#351] CR #666: Setting "Initgroups by name" plugin
   *  (2023-01-20 13:18:04): [pam] [cache_req_send] (0x0400): [CID#351] CR #666: REQ_TRACE: New request [CID #351] 'Initgroups by name'
   *  (2023-01-20 13:18:04): [pam] [cache_req_process_input] (0x0400): [CID#351] CR #666: Parsing input name [someuser]
   *  (2023-01-20 13:18:04): [pam] [sss_domain_get_state] (0x1000): [CID#351] Domain LDAP is Active
   *  (2023-01-20 13:18:04): [pam] [sss_parse_name_for_domains] (0x0200): [CID#351] name 'someuser' matched without domain, user is someuser
   *  (2023-01-20 13:18:04): [pam] [cache_req_set_name] (0x0400): [CID#351] CR #666: Setting name [someuser]
   *  (2023-01-20 13:18:04): [pam] [cache_req_select_domains] (0x0400): [CID#351] CR #666: Performing a multi-domain search
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_domains] (0x0400): [CID#351] CR #666: Search will check the cache and bypass the data provider
   *  (2023-01-20 13:18:04): [pam] [cache_req_validate_domain_type] (0x2000): [CID#351] Request type POSIX-only for domain implicit_files type POSIX is valid
   *  (2023-01-20 13:18:04): [pam] [cache_req_set_domain] (0x0400): [CID#351] CR #666: Using domain [implicit_files]
   *  (2023-01-20 13:18:04): [pam] [cache_req_prepare_domain_data] (0x0400): [CID#351] CR #666: Preparing input data for domain [implicit_files] rules
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_send] (0x0400): [CID#351] CR #666: Looking up someuser@implicit_files
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_ncache] (0x0400): [CID#351] CR #666: Checking negative cache for [someuser@implicit_files]
   *  (2023-01-20 13:18:04): [pam] [sss_ncache_check_str] (0x2000): [CID#351] Checking negative cache for [NCE/USER/implicit_files/someuser@implicit_files]
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_ncache] (0x0400): [CID#351] CR #666: [someuser@implicit_files] is not present in negative cache
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_cache] (0x0400): [CID#351] CR #666: Looking up [someuser@implicit_files] in cache
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_cache] (0x0400): [CID#351] CR #666: Object [someuser@implicit_files] was not found in cache
   *  (2023-01-20 13:18:04): [pam] [cache_req_validate_domain_type] (0x2000): [CID#351] Request type POSIX-only for domain LDAP type POSIX is valid
   *  (2023-01-20 13:18:04): [pam] [cache_req_set_domain] (0x0400): [CID#351] CR #666: Using domain [LDAP]
   *  (2023-01-20 13:18:04): [pam] [cache_req_prepare_domain_data] (0x0400): [CID#351] CR #666: Preparing input data for domain [LDAP] rules
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_send] (0x0400): [CID#351] CR #666: Looking up someuser@ldap
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_ncache] (0x0400): [CID#351] CR #666: Checking negative cache for [someuser@ldap]
   *  (2023-01-20 13:18:04): [pam] [sss_ncache_check_str] (0x2000): [CID#351] Checking negative cache for [NCE/USER/LDAP/someuser@ldap]
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_ncache] (0x0400): [CID#351] CR #666: [someuser@ldap] is not present in negative cache
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_cache] (0x0400): [CID#351] CR #666: Looking up [someuser@ldap] in cache
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_send] (0x0400): [CID#351] CR #666: Returning [someuser@ldap] from cache
   *  (2023-01-20 13:18:04): [pam] [cache_req_search_ncache_filter] (0x0400): [CID#351] CR #666: This request type does not support filtering result by negative cache
   *  (2023-01-20 13:18:04): [pam] [cache_req_create_and_add_result] (0x0400): [CID#351] CR #666: Found 51 entries in domain LDAP
   *  (2023-01-20 13:18:04): [pam] [cache_req_done] (0x0400): [CID#351] CR #666: Finished: Success
   *  (2023-01-20 13:18:04): [pam] [pam_check_user_search_next] (0x4000): [CID#351] PAM initgroups scheme [no_session].
   *  (2023-01-20 13:18:04): [pam] [pam_check_user_search_next] (0x4000): [CID#351] Found a session for uid 10007.
   *  (2023-01-20 13:18:04): [pam] [pam_initgr_check_timeout] (0x4000): [CID#351] User [someuser] not found in PAM cache.
   *  (2023-01-20 13:18:04): [pam] [pam_check_user_search_next] (0x4000): [CID#351] No new initgroups needed because:
   *  (2023-01-20 13:18:04): [pam] [pam_check_user_search_next] (0x4000): [CID#351] there is a active session for user [someuser].
   *  (2023-01-20 13:18:04): [pam] [pd_set_primary_name] (0x0400): [CID#351] User's primary name is someuser@ldap
   *  (2023-01-20 13:18:04): [pam] [pam_initgr_check_timeout] (0x4000): [CID#351] User [someuser] not found in PAM cache.
   *  (2023-01-20 13:18:04): [pam] [pam_initgr_cache_set] (0x2000): [CID#351] [someuser] added to PAM initgroup cache
   *  (2023-01-20 13:18:04): [pam] [pam_dp_send_req] (0x0100): [CID#351] Sending request with the following data:
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] command: SSS_PAM_ACCT_MGMT
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] domain: LDAP
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] user: someuser@ldap
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] service: sshd
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] tty: ssh
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] ruser: not set
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] rhost: 1.2.3.4
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] authtok type: 0 (No authentication token available)
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] newauthtok type: 0 (No authentication token available)
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] priv: 1
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] cli_pid: 2586690
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] child_pid: 0
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] logon name: someuser
   *  (2023-01-20 13:18:04): [pam] [pam_print_data] (0x0100): [CID#351] flags: 0
   *  (2023-01-20 13:18:04): [pam] [pam_dom_forwarder] (0x0100): [CID#351] pam_dp_send_req returned 0
   *  (2023-01-20 13:18:04): [pam] [pam_dp_send_req_done] (0x0020): [CID#351] PAM handler failed [1432158212]: SSSD is offline
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-01-20 13:18:27): [pam] [pam_dp_send_req_done] (0x0020): [CID#352] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:19:02): [pam] [pam_dp_send_req_done] (0x0020): [CID#353] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:19:12): [pam] [pam_dp_send_req_done] (0x0020): [CID#353] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:20:17): [pam] [pam_dp_send_req_done] (0x0020): [CID#354] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:20:19): [pam] [pam_dp_send_req_done] (0x0020): [CID#355] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:20:21): [pam] [pam_dp_send_req_done] (0x0020): [CID#356] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:20:41): [pam] [pam_dp_send_req_done] (0x0020): [CID#357] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:21:04): [pam] [pam_dp_send_req_done] (0x0020): [CID#358] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:21:06): [pam] [pam_dp_send_req_done] (0x0020): [CID#359] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:21:16): [pam] [pam_dp_send_req_done] (0x0020): [CID#360] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:22:24): [pam] [pam_dp_send_req_done] (0x0020): [CID#361] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:22:25): [pam] [pam_dp_send_req_done] (0x0020): [CID#362] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:22:34): [pam] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#363] CR #680: Could not get account info [1432158212]: SSSD is offline
(2023-01-20 13:22:34): [pam] [pam_dp_send_req_done] (0x0020): [CID#363] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:23:33): [pam] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#364] CR #682: Could not get account info [1432158212]: SSSD is offline
(2023-01-20 13:23:33): [pam] [pam_dp_send_req_done] (0x0020): [CID#364] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:24:42): [pam] [pam_dp_send_req_done] (0x0020): [CID#365] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:26:06): [pam] [pam_dp_send_req_done] (0x0020): [CID#366] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:26:41): [pam] [pam_dp_send_req_done] (0x0020): [CID#367] PAM handler failed [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2023-01-20 13:27:26): [pam] [orderly_shutdown] (0x3f7c0): SIGTERM: killing children
(2023-01-20 13:27:26): [pam] [orderly_shutdown] (0x3f7c0): Shutting down (status = 0)(2023-01-20 13:27:26): [pam] [server_setup] (0x3f7c0): Starting with debug level = 0x0070

13:27:26 is the time when we manually restarted sssd

Unfortunately, default log level isn't enough in this case.

Unfortunately, default log level isn't enough in this case.

Ok, I see, I just thought maybe it could give us a clue. Maybe we try to reproduce it with debug lvl 9. Thanks!

Exact same problem here. Network gets flaky while backup seems to overload the connection. I'll try to increase reconnection_retries in sssd section and timeout in domain section.

Editing sssd.conf:

[sssd]
...
reconnection_retries = 10080

[domain/ad.YOUR_COMPANY.com]
...
timeout = 60

fixes the problem.

This will retry connection to the provider for one week otherwise the WATCHDOG will kill it with its defaults and destroys the auth backend.

  timeout (integer)
    Timeout in seconds between heartbeats for this service. This is used to ensure that the process is alive and capable of answering requests.

    Default: 10
reconnection_retries (integer)
    Number of times services should attempt to reconnect in the event of a Data Provider crash or restart before they give up

    Default: 3

the main problem is that this configured default is incompatible with the default sssd.service unit because:

Restart=on-abnormal

(for me on fedora and redhat flavors)

will leave the stopped service in dead state.

This problem should be quiet common since a overloaded connection e.g. backups could easily trigger this behavior.

Hi everybody, in my company we have the same problems on Oracle Linux 8. I spent a lot of time looking for the problem In my case it works if you increase the oom_score_adj in the PID file directly to the JAVA application and decrease the level for the sssd daemon. Probably like this. Simply add it to your "hour cron" job

for pid in /sbin/pidof sssd; do echo -900 > /proc/$pid/oom_score_adj; done for pid in /sbin/pidof java; do echo 500 > /proc/$pid/oom_score_adj; done

In the event that java again fills the memory and an OOM occurs. The system will automatically terminate JAVA as the first process and sssd will continue to run.

Am I missing something? "was terminated by own WATCHDOG" does not point in any way to the OOM Killer and you will definitely see OOM Killer messages in your kernel logs since this is part of the kernel. Messages like "killed process" in your dmesg.

This method looks error prone to. Imagine your java applications will run out of memory faster than your one hour interval leaving it with Score 0 and some other application gets killed instead. If you really need this use systemd edit sssd.service and set "OOMScoreAdjust=" accordingly. https://www.freedesktop.org/software/systemd/man/systemd.exec.html

The best method would be to find the source for this bad memory management and really fix the problem.

Back to topic:

./src/confdb/confdb.h:#define CONFDB_SERVICE_RECON_RETRIES "reconnection_retries"

is defined in sssd config blog.

Than in ./src/responder/common/responder_common.c:

ret = confdb_get_int(rctx->cdb, rctx->confdb_service_path,
                          CONFDB_SERVICE_RECON_RETRIES, 3, &max_retries);

later in ./src/sbus/connection/sbus_reconnect.c

conn->reconnect->retry.max = max_retries;

and finally in the same file

if (reconnect->retry.current > reconnect->retry.max) {
         DEBUG(SSSDBG_CRIT_FAILURE,
               "Unable to reconnect: maximum retries exceeded.\n");
         sbus_reconnect_notify(conn, SBUS_RECONNECT_EXCEEDED_RETRIES);
         return;
     }

Log files accordingly

(2023-03-25  3:24:11): [nss] [sbus_reconnect_attempt] (0x0020): Unable to connect to D-Bus
   *  ... skipping repetitive backtrace ...
(2023-03-25  3:24:11): [nss] [sbus_reconnect] (0x0020): Unable to reconnect: maximum retries exceeded.
(2023-03-25  3:24:11): [nss] [sss_dp_on_reconnect] (0x0010): Could not reconnect to ad.COMPANY.com provider.
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2023-03-25  3:24:11): [nss] [sbus_reconnect] (0x0020): Unable to reconnect: maximum retries exceeded.
   *  (2023-03-25  3:24:11): [nss] [sss_dp_on_reconnect] (0x0010): Could not reconnect to ad.COMPANY.com provider.
********************** BACKTRACE DUMP ENDS HERE *********************************

(2023-03-25  3:24:56): [nss] [orderly_shutdown] (0x3f7c0): SIGTERM: killing children
(2023-03-25  3:24:56): [nss] [orderly_shutdown] (0x3f7c0): Shutting down (status = 0)

Kills the process with exit 0 so for systemd everything is fine and it does not really want to restart the service because the watchdog returned 0 after 3 default attempts. This seams to be default behavior for SSSD. Editing the configs accordingly is up to the user.

Am I missing something?

Se either

Fix Network so the sssd always has connection to the backend
Set some higher values for reconnection_retries and timeout
fix the systemd unit to detect (somehow the exit 0) killed process and restart it

I've done some digging here, and we have Before=systemd-user-sessions.service to ensure that SSSD stops after systemd-user-sessions to prevent the system from hanging on shutdown per ea0a71921ea396f5cc0e9e20d9a2aafc681b3eb9. This is better documented in the linked RedHat issue - or at least to my mind the "before permitting user sessions" isn't particularly relevant.

This in turn introduced a problem where the system would not finish booting in the event that sssd failed to start (e.g. due to a misconfiguration), which was addressed in a049ac715a79ddfad0d67d48fc5c60408cf62127 by changing Restart=on-failure to Restart=on-abnormal (as well as StartLimit* properties) so that in the event that sssd fails to start and returns a non-zero status code, it enters the failed state and the startup can continue.

In this issue, we see that in the event that sssd's child processes are not responding (e.g. due to I/O issues on virtualized hardware), it will kill itself and exit with a non-zero status; however because it now has Restart=on-abnormal the service will not restart. I've seen the suggestions earlier in this thread about increasing retries and timeouts, however this is problematic in the event that the service actually needs to restart.

I suspect that the Restart=on-abnormal is not correct, and should be reverted to one of either on-failure or even always, as it's my understanding that the StartLimit* properties should be sufficient to prevent the unbootable system scenario, something like:

[Unit]
Before=systemd-user-sessions.service
StartLimitIntervalSec=15
StartLimitBurst=5

[Service]
Restart=always

Ideally you want to set the start limit so that the limit is triggered by repeated starts with invalid configuration, but not due to timeouts. Of course the better solution would be to remove the Before, which again appears to be there to coordinate the shutdown process.

I've done some digging here, and we have Before=systemd-user-sessions.service to ensure that SSSD stops after systemd-user-sessions to prevent the system from hanging on shutdown per ea0a719. This is better documented in the linked RedHat issue - or at least to my mind the "before permitting user sessions" isn't particularly relevant.

This in turn introduced a problem where the system would not finish booting in the event that sssd failed to start (e.g. due to a misconfiguration), which was addressed in a049ac7 by changing Restart=on-failure to Restart=on-abnormal (as well as StartLimit* properties) so that in the event that sssd fails to start and returns a non-zero status code, it enters the failed state and the startup can continue.

In this issue, we see that in the event that sssd's child processes are not responding (e.g. due to I/O issues on virtualized hardware), it will kill itself and exit with a non-zero status; however because it now has Restart=on-abnormal the service will not restart. I've seen the suggestions earlier in this thread about increasing retries and timeouts, however this is problematic in the event that the service actually needs to restart.

I suspect that the Restart=on-abnormal is not correct, and should be reverted to one of either on-failure or even always, as it's my understanding that the StartLimit* properties should be sufficient to prevent the unbootable system scenario, something like:
[Unit]
Before=systemd-user-sessions.service
StartLimitIntervalSec=15
StartLimitBurst=5

[Service]
Restart=always
Ideally you want to set the start limit so that the limit is triggered by repeated starts with invalid configuration, but not due to timeouts. Of course the better solution would be to remove the Before, which again appears to be there to coordinate the shutdown process.

Ive run into this issue when doing a zfs recv on a very weak IO computer. Applying the suggested changes to sssd.service and restarting sssd immediately fixed the issue and allow me to log back in as an AD user.

Any progress on this major problem?

We are also affected several times a week on our 40 gitlab runners. We see OOM errors in the kernel log "sssd_be invoked oom-killer" and then typically a java build process is killed and then the connection errors in sssd_pam, sssd_ssh, sssd_sudo, sssd_nss and the watchdog errors in the sssd log.

SSSD / sssd

sssd don't restart properly after being killed by watchdog #6219