I actually have a followup to this already and it seems that I'm seeing segfaults and service restarts around the times of these failed attempts.
Here is a better bad login attempt sssd_domain.com.log log, at level 0x1310:
``` (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=jsmith@mydomain.com] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sshPublicKeys] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=John Smith,CN=Users,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=jsmith@mydomain.com,cn=users,cn=mydomain.com,cn=sysdb] has set [ts_cache] attrs. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=John Smith,CN=Users,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-32-545] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-32-544] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-572] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-513] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-1103] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-512] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for [ jsmith@mydomain.com] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=jsmith@mydomain.com,cn=users,cn=mydomain.com,cn=sysdb] has set [ts_cache] attrs. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_req_reply_std] (0x1000): DP Request [Initgroups #23]: Returning [Success]: 0,0,Success (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): domain: mydomain.com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): user: jsmith@mydomain.com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): service: sshd (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): tty: ssh (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): ruser: (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): rhost: 192.168.2.111 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): priv: 1 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): cli_pid: 22339 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): logon name: not set (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [distinguishedName] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=cerberusvm,CN=Computers,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [configurationNamingContext] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=Default-First-Site-Name,cn=Sites,CN=Configuration,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): Entry has no attributes [0(Success)]!? (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nTSecurityDescriptor] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFileSysPath] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCMachineExtensionNames] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFunctionalityVersion] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flags] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [be_res_get_opts] (0x0100): Lookup order: ipv4_first (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [recreate_ares_channel] (0x0100): Initializing new c-ares channel (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [confdb_get_domain_internal] (0x1000): pwd_expiration_warning is -1 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_domain_init_internal] (0x0200): DB File for mydomain.com: /var/lib/sss/db/cache_mydomain.com.ldb (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_domain_init_internal] (0x0200): Timestamp file for mydomain.com: /var/lib/sss/db/timestamps_mydomain.com.ldb (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [monitor_common_send_id] (0x0100): Sending ID: (%BE_mydomain.com,1) (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_names_init_from_args] (0x0100): Using re [(((?P<domain>[^\]+)\(?P<name>.+$))|((?P<name>[^@]+)@(?P<domain>.+$))|(^(?P<name>[^@\]+)$))]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_fqnames_init] (0x0100): Using fq format [%1$s@%2$s]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [create_socket_symlink] (0x1000): Symlinking the dbus path /var/lib/sss/pipes/private/sbus-dp_mydomain.com.22340 to a link /var/lib/sss/pipes/private/sbus-dp_mydomain.com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [id] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [auth] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [access] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [chpass] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [sudo] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [autofs] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [selinux] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [hostid] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [subdomains] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [session] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_module_open_lib] (0x1000): Loading module [ad] with path [/usr/lib64/sssd/libsss_ad.so] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_common_options] (0x0100): Setting domain option case_sensitive to [false] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [krb5_service_new] (0x0100): write_kdcinfo for realm mydomain.COM set to false (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [_ad_servers_init] (0x0100): Added failover server prodad1.mydomain.com (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_sdap_options] (0x0100): Option krb5_realm set to mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options] (0x0100): Will look for cerberusvm.mydomain.com@mydomain.COM in default keytab (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [select_principal_from_keytab] (0x0200): trying to select the most appropriate principal from keytab (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [match_principal] (0x1000): Principal matched to the sample (CERBERUSVM$@mydomain.COM). (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [select_principal_from_keytab] (0x0200): Selected primary: CERBERUSVM$ (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [select_principal_from_keytab] (0x0200): Selected realm: mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options] (0x0100): Option ldap_sasl_authid set to CERBERUSVM$ (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options] (0x0100): Option ldap_sasl_realm set to mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_search_bases] (0x0100): Search base not set. SSSD will attempt to discover it later, when connecting to the LDAP server. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_dyndns_init] (0x0100): Dynamic DNS updates are off. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options] (0x0100): Option krb5_server set to prodad1.mydomain.com (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options] (0x0100): Option krb5_realm set to mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options] (0x0100): Option krb5_use_kdcinfo set to true (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [check_lifetime] (0x0200): No lifetime configured. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [check_lifetime] (0x0200): No lifetime configured. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_krb5_check_options] (0x0100): No kpasswd server explicitly configured, using the KDC or defaults. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [parse_krb5_map_user] (0x0100): krb5_map_user is empty! (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init] (0x0100): Target [selinux] is not supported by module [ad]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init] (0x0100): Target [hostid] is not supported by module [ad]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_write_krb5_localauth_snippet] (0x0200): File for localauth plugin configuration is [/var/lib/sss/pubconf/krb5.include.d/localauth_plugin] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_write_krb5_libdefaults_snippet] (0x0200): File for KRB5 kibdefaults configuration is [/var/lib/sss/pubconf/krb5.include.d/krb5_libdefaults] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_write_domain_mappings] (0x0200): Mapping file for domain [mydomain.com] is [/var/lib/sss/pubconf/krb5.include.d/domain_realm_mydomain_com] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_search_bases] (0x0100): Search base not set. SSSD will attempt to discover it later, when connecting to the LDAP server. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init] (0x0100): Target [session] is not supported by module [ad]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [become_user] (0x0200): Trying to become user [0][0]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [become_user] (0x0200): Already user [0]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name not resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'prodad1.mydomain.com' is 'neutral' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name not resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of ' prodad1.mydomain.com' in files (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com' as 'resolving name' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'prodad1.mydomain.com' in files (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of ' prodad1.mydomain.com' in DNS (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [id_callback] (0x0100): Got id ack and version (1) from Monitor (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com' as 'name resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x0200): Found address for server prodad1.mydomain.com: [192.168.2.13] TTL 10800 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://prodad1.mydomain.com' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://prodad1.mydomain.com' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap:// prodad1.mydomain.com:389/??base] with fd [19]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_naming_context] (0x0200): Using value from [defaultNamingContext] as naming context. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [DEFAULT][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_user_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [USER][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_group_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [GROUP][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_netgroup_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [NETGROUP][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_host_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [HOST][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_sudo_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [SUDO][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_service_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [SERVICE][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_autofs_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [AUTOFS][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [6] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Will look for schema at [CN=Schema,CN=Configuration,DC=mydomain,DC=com] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service AD (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x0200): Found address for server prodad1.mydomain.com: [192.168.2.13] TTL 10800 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT... (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [child_sig_handler] (0x1000): Waiting for child [22341]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [child_sig_handler] (0x0100): child [22341] finished successfully. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1547684556 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: CERBERUSVM$ (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'prodad1.mydomain.com' as 'working' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com' as 'working' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [isMemberOfPartialAttributeSet] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=GidNumber,CN=Schema,CN=Configuration,DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=UidNumber,CN=Schema,CN=Configuration,DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flatName] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustPartner] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [securityIdentifier] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustType] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustAttributes] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_slave_domain_done] (0x1000): There are no changes (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [delayed_online_authentication_callback] (0x0200): Backend is online, starting delayed online authentication. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Entering. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Adding connection 0x5632c53a92d0. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Got a connection (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x5632c53af940] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Entering. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Adding connection 0x5632c53ab5d0. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Got a connection (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x5632c539c5a0] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Entering. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Adding connection 0x5632c53b3600. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Got a connection (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x5632c53b9710] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x5632c53af940] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Added Frontend client [PAM] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x5632c539c5a0] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Added Frontend client [SSH] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x5632c53b9710] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Added Frontend client [NSS] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [check_ipv4_addr] (0x0200): Loopback IPv4 address 127.0.0.1 (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [check_ipv6_addr] (0x0200): Loopback IPv6 address ::1 (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoCommand] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoHost] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoUser] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOption] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAs] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsUser] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsGroup] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotBefore] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotAfter] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOrder] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=jlevine@mydomain.com] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sshPublicKeys] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #0]: Returning [Success]: 0,0,Success (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=jlevine@mydomain.com] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sshPublicKeys] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #1]: Returning [Success]: 0,0,Success ```
Here is sssd_sshd:
``` (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'jsmith' matched without domain, user is jsmith (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [client_recv] (0x0200): Client disconnected! (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'jsmith' matched without domain, user is jsmith (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [client_recv] (0x0200): Client disconnected! (Wed Jan 16 16:07:36 2019) [sssd[ssh]] [handle_requests_after_reconnect] (0x1000): Will handle 0 requests after reconnect ```
Here is a /var/log/secure snippet from sshd:
``` Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: fd 5 is not O_NONBLOCK Jan 16 16:07:33 cerberusvm sshd[30533]: debug1: Forked child 22335. Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: send_rexec_state: entering fd = 8 config len 1005 Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: ssh_msg_send: type 0 Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: send_rexec_state: done Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: oom_adjust_restore Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Set /proc/self/oom_score_adj to 0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: inetd sockets after dupping: 3, 3 Jan 16 16:07:33 cerberusvm sshd[22335]: Connection from 192.168.2.111 port 56526 on 192.168.2.17 port 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Client protocol version 2.0; client software version OpenSSH_7.4 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: match: OpenSSH_7.4 pat OpenSSH* compat 0x04000000 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Local version string SSH-2.0-OpenSSH_7.4 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Enabling compatibility mode for protocol 2.0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: fd 3 setting O_NONBLOCK Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_sandbox_init: preparing seccomp filter sandbox Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: Network child is on pid 22336 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: preauth child monitor started Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SELinux support disabled [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: privsep user:group 74:74 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: permanently_set_uid: 74/74 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_sandbox_child: attaching seccomp filter program [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 20 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_KEXINIT sent [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 20 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_KEXINIT received [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: local server KEXINIT proposal [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none, zlib@openssh.com [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none, zlib@openssh.com [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages ctos: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages stoc: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: first_kex_follows 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: reserved 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: peer client KEXINIT proposal [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com, ecdsa-sha2-nistp384-cert-v01@openssh.com, ecdsa-sha2-nistp521-cert-v01@openssh.com ,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521, ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com, ssh-dss-cert-v01@openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none, zlib@openssh.com,zlib [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none, zlib@openssh.com,zlib [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages ctos: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages stoc: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: first_kex_follows 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: reserved 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: algorithm: curve25519-sha256 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 120 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 121 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 120 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 121 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 120 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 121 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 120 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 121 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 30 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_sign entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 6 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 7 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 6 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_sign Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_sign: hostkey proof signature 0x56075779ced0(100) Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 7 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 6 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 31 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 21 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: set_newkeys: mode 1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: rekey after 134217728 blocks [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_NEWKEYS sent [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: expecting SSH2_MSG_NEWKEYS [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 7 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 21 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_NEWKEYS received [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: set_newkeys: mode 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: rekey after 134217728 blocks [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: KEX done [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 5 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 6 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 0 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_getpwnamallow entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 8 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 9 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 8 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pwnamallow Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: parse_server_config: config reprocess config len 1005 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: checking match for 'User mydomain,nagios,ansible,root' user jsmith host 192.168.2.111 addr 192.168.2.111 laddr 192.168.2.17 lport 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: match not found Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_setup_methods_lists: checking methods Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: authentication methods list 0: publickey,keyboard-interactive Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 9 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 8 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: setting up authctxt for jsmith [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_start_pam entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 100 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_inform_authserv entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 4 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_inform_authrole entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 80 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_setup_methods_lists: checking methods [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: authentication methods list 0: publickey,keyboard-interactive [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: Unrecognized authentication method name: none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=0 next methods="publickey" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 100 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: PAM: initializing for "jsmith" Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: PAM: setting PAM_RHOST to "192.168.2.111" Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: PAM: setting PAM_TTY to "ssh" Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 100 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 4 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_authserv: service=ssh-connection, style= Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 4 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 80 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_authrole: role= Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 80 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 1 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: try method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth_pubkey: test whether pkalg/pkblob are acceptable for RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 22 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 23 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key_from_blob: 0x5607577a1bc0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: sshd_selinux_setup_variables: setting execution context Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand command "/usr/bin/sss_ssh_authorizedkeys jsmith" running as root Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand pid 22337 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: matching key found: file /usr/bin/sss_ssh_authorizedkeys, line 2 RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key 0x5607577a1bc0 is allowed Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 23 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 60 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: userauth_pubkey: authenticated 0 pkalg rsa-sha2-512 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: Postponed publickey for jsmith from 192.168.2.111 port 56526 ssh2 [preauth] Jan 16 16:07:33 cerberusvm sshd[32270]: debug2: channel 0: rcvd adjust 49175 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 2 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: try method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: userauth_pubkey: have signature for RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 22 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 23 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key_from_blob: 0x5607577b1e00 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: sshd_selinux_setup_variables: setting execution context Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand command "/usr/bin/sss_ssh_authorizedkeys jsmith" running as root Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand pid 22338 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: matching key found: file /usr/bin/sss_ssh_authorizedkeys, line 2 RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key 0x5607577b1e00 is allowed Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 23 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_verify entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 24 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_verify: waiting for MONITOR_ANS_KEYVERIFY [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 25 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 24 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyverify: key 0x5607577ac580 signature verified Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 25 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_update_methods_lists: updating methods list after "publickey" Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: authentication methods list 0 remaining: "keyboard-interactive" Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_child_preauth: method publickey: partial Jan 16 16:07:33 cerberusvm sshd[22335]: Partial publickey for jsmith from 192.168.2.111 port 56526 ssh2: RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: userauth_pubkey: authenticated 1 pkalg rsa-sha2-512 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_update_methods_lists: updating methods list after "publickey" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: authentication methods list 0 remaining: "keyboard-interactive" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=1 next methods="keyboard-interactive" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method keyboard-interactive [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 3 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: try method keyboard-interactive [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: keyboard-interactive devs [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: auth2_challenge: user=jsmith devs= [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kbdint_alloc: devices 'pam' [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices pam [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: kbdint_next_device: devices <empty> [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: auth2_challenge_start: trying authentication method 'pam' [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 104 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: waiting for MONITOR_ANS_PAM_INIT_CTX [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 105 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 104 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pam_init_ctx Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: PAM: sshpam_init_ctx entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 105 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 104 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_query [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 106 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_query: waiting for MONITOR_ANS_PAM_QUERY [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 107 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 106 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pam_query Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: PAM: sshpam_query entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_msg_recv entering Jan 16 16:07:33 cerberusvm sshd[22339]: debug3: PAM: sshpam_thread_conv entering, 1 messages Jan 16 16:07:33 cerberusvm sshd[22339]: debug3: ssh_msg_send: type 2 Jan 16 16:07:33 cerberusvm sshd[22339]: debug3: ssh_msg_recv entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 107 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_query: pam_query returned 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 60 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: Postponed keyboard-interactive for jsmith from 192.168.2.111 port 56526 ssh2: RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: receive packet: type 61 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_respond [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 108 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: waiting for MONITOR_ANS_PAM_RESPOND [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 109 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: monitor_read: checking request 108 Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_answer_pam_respond Jan 16 16:07:35 cerberusvm sshd[22335]: debug2: PAM: sshpam_respond entering, 1 responses Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: ssh_msg_send: type 6 Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 109 Jan 16 16:07:35 cerberusvm sshd[22335]: debug2: monitor_read: 108 used once, disabling now Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: pam_respond returned 1 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_query [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 106 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_query: waiting for MONITOR_ANS_PAM_QUERY [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 107 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: monitor_read: checking request 106 Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_answer_pam_query Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: PAM: sshpam_query entering Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: ssh_msg_recv entering Jan 16 16:07:35 cerberusvm sshd[22339]: debug3: PAM: sshpam_thread_conv entering, 1 messages Jan 16 16:07:35 cerberusvm sshd[22339]: debug3: ssh_msg_send: type 4 Jan 16 16:07:35 cerberusvm sshd[22339]: Successful Duo login for 'jsmith' from 192.168.2.111 Jan 16 16:07:35 cerberusvm sshd[22339]: debug1: do_pam_account: called Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: ssh_msg_recv entering Jan 16 16:09:05 cerberusvm sshd[22339]: debug3: PAM: do_pam_account pam_acct_mgmt = 9 (Authentication service cannot retrieve authentication info) Jan 16 16:09:05 cerberusvm sshd[22339]: debug3: ssh_msg_send: type 13 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: User account has expired Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 107 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_query: pam_query returned 0 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: send packet: type 60 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: Postponed keyboard-interactive/pam for jsmith from 192.168.2.111 port 56526 ssh2 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: receive packet: type 61 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_respond [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 108 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: waiting for MONITOR_ANS_PAM_RESPOND [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 109 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 108 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_answer_pam_respond Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: PAM: sshpam_respond entering, 0 responses Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 109 Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: monitor_read: 108 used once, disabling now Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: pam_respond returned -1 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices <empty> [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_free_ctx [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 110 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_free_ctx: waiting for MONITOR_ANS_PAM_FREE_CTX [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 111 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 110 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_answer_pam_free_ctx Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_free_ctx entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_thread_cleanup entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 111 Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: monitor_read: 110 used once, disabling now Jan 16 16:09:05 cerberusvm sshd[22335]: Failed keyboard-interactive/pam for jsmith from 192.168.2.111 port 56526 ssh2 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=0 next methods="keyboard-interactive" [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: attempt 4 failures 1 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: input_userauth_request: try method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: keyboard-interactive devs [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge: user=jsmith devs= [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: kbdint_alloc: devices 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices pam [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: kbdint_next_device: devices <empty> [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge_start: trying authentication method 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 104 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: waiting for MONITOR_ANS_PAM_INIT_CTX [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 105 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 104 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_answer_pam_init_ctx Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_init_ctx entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 105 Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: monitor_read: 104 used once, disabling now Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: pam_init_ctx failed [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=0 next methods="keyboard-interactive" [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: attempt 5 failures 2 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: input_userauth_request: try method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: keyboard-interactive devs [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge: user=jsmith devs= [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: kbdint_alloc: devices 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices pam [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: kbdint_next_device: devices <empty> [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge_start: trying authentication method 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 104 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: waiting for MONITOR_ANS_PAM_INIT_CTX [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 105 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 104 Jan 16 16:09:05 cerberusvm sshd[22335]: fatal: monitor_read: unpermitted request 104 Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: do_cleanup Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: PAM: cleanup Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_thread_cleanup entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: Killing privsep child 22336 ```
Now the interesting thing is that when I check `journalctl -u sssd.service`, at the same time this is starting (16:07:35), sssd appears to crash and restart:
``` Jan 16 16:07:35 cerberusvm.mydomain.com sssd[be[mydomain.com]][22340]: Starting up Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 1 Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 1 Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 1 Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 2 ```
This made me look at dmesg, and sssd has been causing a ton of segfaults:
``` [Wed Jan 16 04:55:13 2019] traps: sssd_be[25969] general protection ip:7fdcd54ab766 sp:7fff5f1ce570 error:0 in libtalloc.so.2.1.13[7fdcd54a6000+e000] [Wed Jan 16 06:28:46 2019] traps: sssd_be[10849] general protection ip:7f9601987766 sp:7fffb5f35f10 error:0 in libtalloc.so.2.1.13[7f9601982000+e000] [Wed Jan 16 10:34:01 2019] traps: sssd_be[26901] general protection ip:7f8814b17766 sp:7fff46e2ab40 error:0 in libtalloc.so.2.1.13[7f8814b12000+e000] [Wed Jan 16 10:38:14 2019] traps: sssd_be[28969] general protection ip:7fab7b4a0766 sp:7fff85e9e2f0 error:0 in libtalloc.so.2.1.13[7fab7b49b000+e000] [Wed Jan 16 11:15:09 2019] sssd_be[3446]: segfault at 5646ffffffa0 ip 00007f9799f1f766 sp 00007ffd113922d0 error 4 in libtalloc.so.2.1.13[7f9799f1a000+e000] [Wed Jan 16 11:26:01 2019] sssd_be[4217]: segfault at ffffffffffffffa1 ip 00007f72eadb1766 sp 00007fffdac4d3c0 error 5 in libtalloc.so.2.1.13[7f72eadac000+e000] [Wed Jan 16 11:28:58 2019] sssd_be[6050]: segfault at b403 ip 00007f91435bb766 sp 00007fff278853b0 error 4 in libtalloc.so.2.1.13[7f91435b6000+e000] [Wed Jan 16 13:25:22 2019] traps: sssd_be[24797] general protection ip:7f63511b8766 sp:7ffcef433c90 error:0 in libtalloc.so.2.1.13[7f63511b3000+e000] [Wed Jan 16 13:41:34 2019] sssd_be[29033]: segfault at ffffffffffffffa3 ip 00007f65ef819766 sp 00007fff1827f8f0 error 5 in libtalloc.so.2.1.13[7f65ef814000+e000] [Wed Jan 16 13:44:57 2019] traps: sssd_be[29224] general protection ip:7fa76a909766 sp:7ffde8f7fc60 error:0 in libtalloc.so.2.1.13[7fa76a904000+e000] [Wed Jan 16 14:59:33 2019] sssd_be[6553]: segfault at ffffffffffffffa5 ip 00007f7af1396766 sp 00007ffcd4876d70 error 5 in libtalloc.so.2.1.13[7f7af1391000+e000] [Wed Jan 16 15:39:22 2019] sssd_be[19999]: segfault at 20 ip 00007f31511fa766 sp 00007fffbe331c40 error 4 in libtalloc.so.2.1.13[7f31511f5000+e000] [Wed Jan 16 15:41:36 2019] sssd_be[20245]: segfault at ffffffffffffffe8 ip 00007f0a9fe82766 sp 00007ffd9374afb0 error 5 in libtalloc.so.2.1.13[7f0a9fe7d000+e000] [Wed Jan 16 15:44:43 2019] sssd_be[21086]: segfault at ffffffffffffffaa ip 00007f442b1f6766 sp 00007fff2341ccb0 error 5 in libtalloc.so.2.1.13[7f442b1f1000+e000] [Wed Jan 16 15:50:24 2019] sssd_be[21155]: segfault at ffffffffffffffb0 ip 00007f4df0fcb766 sp 00007ffcecacbf60 error 5 in libtalloc.so.2.1.13[7f4df0fc6000+e000] [Wed Jan 16 16:05:56 2019] sssd_be[24929]: segfault at 501000da0 ip 00007faf383d3766 sp 00007ffc3ea27330 error 4 in libtalloc.so.2.1.13[7faf383ce000+e000] [Wed Jan 16 16:23:51 2019] sssd_be[25298]: segfault at 90 ip 00007fdadd768766 sp 00007fff09a8fe70 error 4 in libtalloc.so.2.1.13[7fdadd763000+e000] [Wed Jan 16 16:29:07 2019] sssd_be[28863]: segfault at 7fba0d3ea0b0 ip 00007fba65f7c766 sp 00007ffc96a709e0 error 4 in libtalloc.so.2.1.13[7fba65f77000+e000] [Wed Jan 16 16:29:24 2019] traps: sssd_be[28885] general protection ip:7f9492228766 sp:7fff07ffd300 error:0 in libtalloc.so.2.1.13[7f9492223000+e000] ```
Although none specifically line up with the logs above, these logs are the cleanest versions of each I could put together and are best representative of the issue, but other failures which align with the segfault times are essentially the same (and all correlate with service restarts in /var/log/messages). If it is vital to see a log associated with one of these segfaults, let me know and I can try to assemble one.
Thanks
On Wed, Jan 16, 2019 at 3:12 PM Jordan Castillo jordantcastillo@gmail.com wrote:
Here are my log files for both the good and bad attempts.
On Wed, Jan 16, 2019 at 05:02:44PM -0800, Jordan Castillo wrote:
I actually have a followup to this already and it seems that I'm seeing segfaults and service restarts around the times of these failed attempts.
Which package version of SSSD are you using? Please make sure all required libraries are updated to the latest versions, especially libtalloc, libtdb, libtevent and libldb.
HTH
bye, Sumit
Here is a better bad login attempt sssd_domain.com.log log, at level 0x1310:
(Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=jsmith@mydomain.com] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sshPublicKeys] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=John Smith,CN=Users,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=jsmith@mydomain.com,cn=users,cn=mydomain.com,cn=sysdb] has set [ts_cache] attrs. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=John Smith,CN=Users,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-32-545] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-32-544] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-572] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-513] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-1103] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_get_posix_members] (0x1000): Processing membership SID [S-1-5-21-1138762004-3630643508-13603300-512] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for [ jsmith@mydomain.com] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=jsmith@mydomain.com,cn=users,cn=mydomain.com,cn=sysdb] has set [ts_cache] attrs. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_req_reply_std] (0x1000): DP Request [Initgroups #23]: Returning [Success]: 0,0,Success (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): domain: mydomain.com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): user: jsmith@mydomain.com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): service: sshd (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): tty: ssh (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): ruser: (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): rhost: 192.168.2.111 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): priv: 1 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): cli_pid: 22339 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data] (0x0100): logon name: not set (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [distinguishedName] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=cerberusvm,CN=Computers,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [configurationNamingContext] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=Default-First-Site-Name,cn=Sites,CN=Configuration,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): Entry has no attributes [0(Success)]!? (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nTSecurityDescriptor] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFileSysPath] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCMachineExtensionNames] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFunctionalityVersion] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flags] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydomain,DC=com]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [be_res_get_opts] (0x0100): Lookup order: ipv4_first (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [recreate_ares_channel] (0x0100): Initializing new c-ares channel (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [confdb_get_domain_internal] (0x1000): pwd_expiration_warning is -1 (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_domain_init_internal] (0x0200): DB File for mydomain.com: /var/lib/sss/db/cache_mydomain.com.ldb (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_domain_init_internal] (0x0200): Timestamp file for mydomain.com: /var/lib/sss/db/timestamps_mydomain.com.ldb (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [monitor_common_send_id] (0x0100): Sending ID: (%BE_mydomain.com,1) (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_names_init_from_args] (0x0100): Using re [(((?P<domain>[^\\]+)\\(?P<name>.+$))|((?P<name>[^@]+)@(?P<domain>.+$))|(^(?P<name>[^@\\]+)$))]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_fqnames_init] (0x0100): Using fq format [%1$s@%2$s]. (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [create_socket_symlink] (0x1000): Symlinking the dbus path /var/lib/sss/pipes/private/sbus-dp_mydomain.com.22340 to a link /var/lib/sss/pipes/private/sbus-dp_mydomain.com (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [id] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [auth] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [access] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [chpass] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [sudo] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [autofs] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [selinux] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [hostid] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [subdomains] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration] (0x0100): Using [ad] provider for [session] (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_module_open_lib] (0x1000): Loading module [ad] with path [/usr/lib64/sssd/libsss_ad.so] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_common_options] (0x0100): Setting domain option case_sensitive to [false] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [krb5_service_new] (0x0100): write_kdcinfo for realm mydomain.COM set to false (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [_ad_servers_init] (0x0100): Added failover server prodad1.mydomain.com (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_sdap_options] (0x0100): Option krb5_realm set to mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options] (0x0100): Will look for cerberusvm.mydomain.com@mydomain.COM in default keytab (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [select_principal_from_keytab] (0x0200): trying to select the most appropriate principal from keytab (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [match_principal] (0x1000): Principal matched to the sample (CERBERUSVM$@mydomain.COM). (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [select_principal_from_keytab] (0x0200): Selected primary: CERBERUSVM$ (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [select_principal_from_keytab] (0x0200): Selected realm: mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options] (0x0100): Option ldap_sasl_authid set to CERBERUSVM$ (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options] (0x0100): Option ldap_sasl_realm set to mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_search_bases] (0x0100): Search base not set. SSSD will attempt to discover it later, when connecting to the LDAP server. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_dyndns_init] (0x0100): Dynamic DNS updates are off. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options] (0x0100): Option krb5_server set to prodad1.mydomain.com (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options] (0x0100): Option krb5_realm set to mydomain.COM (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options] (0x0100): Option krb5_use_kdcinfo set to true (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [check_lifetime] (0x0200): No lifetime configured. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [check_lifetime] (0x0200): No lifetime configured. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_krb5_check_options] (0x0100): No kpasswd server explicitly configured, using the KDC or defaults. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [parse_krb5_map_user] (0x0100): krb5_map_user is empty! (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init] (0x0100): Target [selinux] is not supported by module [ad]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init] (0x0100): Target [hostid] is not supported by module [ad]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_write_krb5_localauth_snippet] (0x0200): File for localauth plugin configuration is [/var/lib/sss/pubconf/krb5.include.d/localauth_plugin] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_write_krb5_libdefaults_snippet] (0x0200): File for KRB5 kibdefaults configuration is [/var/lib/sss/pubconf/krb5.include.d/krb5_libdefaults] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sss_write_domain_mappings] (0x0200): Mapping file for domain [mydomain.com] is [/var/lib/sss/pubconf/krb5.include.d/domain_realm_mydomain_com] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_search_bases] (0x0100): Search base not set. SSSD will attempt to discover it later, when connecting to the LDAP server. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init] (0x0100): Target [session] is not supported by module [ad]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [become_user] (0x0200): Trying to become user [0][0]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [become_user] (0x0200): Already user [0]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name not resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'prodad1.mydomain.com' is 'neutral' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name not resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of ' prodad1.mydomain.com' in files (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com' as 'resolving name' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'prodad1.mydomain.com' in files (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of ' prodad1.mydomain.com' in DNS (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [id_callback] (0x0100): Got id ack and version (1) from Monitor (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com' as 'name resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x0200): Found address for server prodad1.mydomain.com: [192.168.2.13] TTL 10800 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://prodad1.mydomain.com' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://prodad1.mydomain.com' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap:// prodad1.mydomain.com:389/??base] with fd [19]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_naming_context] (0x0200): Using value from [defaultNamingContext] as naming context. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [DEFAULT][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_user_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [USER][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_group_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [GROUP][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_netgroup_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [NETGROUP][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_host_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [HOST][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_sudo_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [SUDO][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_service_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [SERVICE][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_autofs_search_base] to [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [common_parse_search_base] (0x0100): Search base added: [AUTOFS][DC=mydomain,DC=com][SUBTREE][] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [6] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Will look for schema at [CN=Schema,CN=Configuration,DC=mydomain,DC=com] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service AD (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status] (0x1000): Status of server 'prodad1.mydomain.com' is 'name resolved' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [be_resolve_server_process] (0x0200): Found address for server prodad1.mydomain.com: [192.168.2.13] TTL 10800 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT... (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [child_sig_handler] (0x1000): Waiting for child [22341]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [child_sig_handler] (0x0100): child [22341] finished successfully. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1547684556 (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: CERBERUSVM$ (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'prodad1.mydomain.com' as 'working' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com' as 'working' (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [isMemberOfPartialAttributeSet] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=GidNumber,CN=Schema,CN=Configuration,DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=UidNumber,CN=Schema,CN=Configuration,DC=mydomain,DC=com]. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flatName] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustPartner] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [securityIdentifier] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustType] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustAttributes] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_slave_domain_done] (0x1000): There are no changes (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [delayed_online_authentication_callback] (0x0200): Backend is online, starting delayed online authentication. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Entering. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Adding connection 0x5632c53a92d0. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Got a connection (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x5632c53af940] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Entering. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Adding connection 0x5632c53ab5d0. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Got a connection (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x5632c539c5a0] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Entering. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Adding connection 0x5632c53b3600. (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sbus_server_init_new_connection] (0x0200): Got a connection (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init] (0x0100): Set-up Backend ID timeout [0x5632c53b9710] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x5632c53af940] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Added Frontend client [PAM] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x5632c539c5a0] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Added Frontend client [SSH] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x5632c53b9710] (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register] (0x0100): Added Frontend client [NSS] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [check_ipv4_addr] (0x0200): Loopback IPv4 address 127.0.0.1 (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [check_ipv6_addr] (0x0200): Loopback IPv6 address ::1 (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoCommand] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoHost] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoUser] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOption] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAs] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsUser] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsGroup] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotBefore] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotAfter] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOrder] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=jlevine@mydomain.com] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sshPublicKeys] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #0]: Returning [Success]: 0,0,Success (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=jlevine@mydomain.com] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state] (0x1000): Domain mydomain.com is Active (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sshPublicKeys] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com (Wed Jan 16 16:09:01 2019) [sssd[be[mydomain.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #1]: Returning [Success]: 0,0,SuccessHere is sssd_sshd:
(Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'jsmith' matched without domain, user is jsmith (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [client_recv] (0x0200): Client disconnected! (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'jsmith' matched without domain, user is jsmith (Wed Jan 16 16:07:33 2019) [sssd[ssh]] [client_recv] (0x0200): Client disconnected! (Wed Jan 16 16:07:36 2019) [sssd[ssh]] [handle_requests_after_reconnect] (0x1000): Will handle 0 requests after reconnectHere is a /var/log/secure snippet from sshd:
Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: fd 5 is not O_NONBLOCK Jan 16 16:07:33 cerberusvm sshd[30533]: debug1: Forked child 22335. Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: send_rexec_state: entering fd = 8 config len 1005 Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: ssh_msg_send: type 0 Jan 16 16:07:33 cerberusvm sshd[30533]: debug3: send_rexec_state: done Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: oom_adjust_restore Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Set /proc/self/oom_score_adj to 0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: inetd sockets after dupping: 3, 3 Jan 16 16:07:33 cerberusvm sshd[22335]: Connection from 192.168.2.111 port 56526 on 192.168.2.17 port 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Client protocol version 2.0; client software version OpenSSH_7.4 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: match: OpenSSH_7.4 pat OpenSSH* compat 0x04000000 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Local version string SSH-2.0-OpenSSH_7.4 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: Enabling compatibility mode for protocol 2.0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: fd 3 setting O_NONBLOCK Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_sandbox_init: preparing seccomp filter sandbox Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: Network child is on pid 22336 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: preauth child monitor started Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SELinux support disabled [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: privsep user:group 74:74 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: permanently_set_uid: 74/74 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_sandbox_child: attaching seccomp filter program [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 20 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_KEXINIT sent [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 20 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_KEXINIT received [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: local server KEXINIT proposal [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none, zlib@openssh.com [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none, zlib@openssh.com [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages ctos: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages stoc: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: first_kex_follows 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: reserved 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: peer client KEXINIT proposal [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com, ecdsa-sha2-nistp384-cert-v01@openssh.com, ecdsa-sha2-nistp521-cert-v01@openssh.com ,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521, ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com, ssh-dss-cert-v01@openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr, aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com, hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none, zlib@openssh.com,zlib [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none, zlib@openssh.com,zlib [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages ctos: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: languages stoc: [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: first_kex_follows 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: reserved 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: algorithm: curve25519-sha256 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 120 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 121 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 120 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 121 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 120 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 121 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 120 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 121 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 30 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_sign entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 6 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 7 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 6 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_sign Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_sign: hostkey proof signature 0x56075779ced0(100) Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 7 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 6 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 31 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 21 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: set_newkeys: mode 1 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: rekey after 134217728 blocks [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_NEWKEYS sent [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: expecting SSH2_MSG_NEWKEYS [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 7 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 21 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: SSH2_MSG_NEWKEYS received [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: set_newkeys: mode 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: rekey after 134217728 blocks [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: KEX done [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 5 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 6 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 0 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_getpwnamallow entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 8 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 9 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 8 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pwnamallow Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: parse_server_config: config reprocess config len 1005 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: checking match for 'User mydomain,nagios,ansible,root' user jsmith host 192.168.2.111 addr 192.168.2.111 laddr 192.168.2.17 lport 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: match not found Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_setup_methods_lists: checking methods Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: authentication methods list 0: publickey,keyboard-interactive Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 9 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 8 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: setting up authctxt for jsmith [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_start_pam entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 100 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_inform_authserv entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 4 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_inform_authrole entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 80 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_setup_methods_lists: checking methods [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: authentication methods list 0: publickey,keyboard-interactive [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: Unrecognized authentication method name: none [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=0 next methods="publickey" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 100 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: PAM: initializing for "jsmith" Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: PAM: setting PAM_RHOST to "192.168.2.111" Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: PAM: setting PAM_TTY to "ssh" Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 100 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 4 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_authserv: service=ssh-connection, style= Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 4 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 80 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_authrole: role= Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 80 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 1 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: try method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth_pubkey: test whether pkalg/pkblob are acceptable for RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 22 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 23 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key_from_blob: 0x5607577a1bc0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: sshd_selinux_setup_variables: setting execution context Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand command "/usr/bin/sss_ssh_authorizedkeys jsmith" running as root Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand pid 22337 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: matching key found: file /usr/bin/sss_ssh_authorizedkeys, line 2 RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key 0x5607577a1bc0 is allowed Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 23 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 60 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: userauth_pubkey: authenticated 0 pkalg rsa-sha2-512 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: Postponed publickey for jsmith from 192.168.2.111 port 56526 ssh2 [preauth] Jan 16 16:07:33 cerberusvm sshd[32270]: debug2: channel 0: rcvd adjust 49175 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 2 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: try method publickey [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: userauth_pubkey: have signature for RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 22 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 23 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 22 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key_from_blob: 0x5607577b1e00 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: sshd_selinux_setup_variables: setting execution context Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand command "/usr/bin/sss_ssh_authorizedkeys jsmith" running as root Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: subprocess: AuthorizedKeysCommand pid 22338 Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: temporarily_use_uid: 0/0 (e=0/0) Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: matching key found: file /usr/bin/sss_ssh_authorizedkeys, line 2 RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: restore_uid: 0/0 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyallowed: key 0x5607577b1e00 is allowed Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 23 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_verify entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 24 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_key_verify: waiting for MONITOR_ANS_KEYVERIFY [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 25 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 24 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_keyverify: key 0x5607577ac580 signature verified Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 25 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_update_methods_lists: updating methods list after "publickey" Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: authentication methods list 0 remaining: "keyboard-interactive" Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_child_preauth: method publickey: partial Jan 16 16:07:33 cerberusvm sshd[22335]: Partial publickey for jsmith from 192.168.2.111 port 56526 ssh2: RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: userauth_pubkey: authenticated 1 pkalg rsa-sha2-512 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: auth2_update_methods_lists: updating methods list after "publickey" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: authentication methods list 0 remaining: "keyboard-interactive" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=1 next methods="keyboard-interactive" [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method keyboard-interactive [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: attempt 3 failures 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: input_userauth_request: try method keyboard-interactive [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: keyboard-interactive devs [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: auth2_challenge: user=jsmith devs= [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kbdint_alloc: devices 'pam' [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices pam [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: kbdint_next_device: devices <empty> [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: auth2_challenge_start: trying authentication method 'pam' [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 104 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: waiting for MONITOR_ANS_PAM_INIT_CTX [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 105 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 104 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pam_init_ctx Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: PAM: sshpam_init_ctx entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 105 Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: monitor_read: 104 used once, disabling now Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_query [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 106 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_query: waiting for MONITOR_ANS_PAM_QUERY [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 107 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: monitor_read: checking request 106 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_answer_pam_query Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: PAM: sshpam_query entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: ssh_msg_recv entering Jan 16 16:07:33 cerberusvm sshd[22339]: debug3: PAM: sshpam_thread_conv entering, 1 messages Jan 16 16:07:33 cerberusvm sshd[22339]: debug3: ssh_msg_send: type 2 Jan 16 16:07:33 cerberusvm sshd[22339]: debug3: ssh_msg_recv entering Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 107 Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: mm_sshpam_query: pam_query returned 0 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: debug3: send packet: type 60 [preauth] Jan 16 16:07:33 cerberusvm sshd[22335]: Postponed keyboard-interactive for jsmith from 192.168.2.111 port 56526 ssh2: RSA SHA256:Wtul7zrgzlGGNe4U2EZp5fRybKeSCGbjuzJxIYv0l7o [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: receive packet: type 61 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_respond [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 108 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: waiting for MONITOR_ANS_PAM_RESPOND [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 109 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: monitor_read: checking request 108 Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_answer_pam_respond Jan 16 16:07:35 cerberusvm sshd[22335]: debug2: PAM: sshpam_respond entering, 1 responses Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: ssh_msg_send: type 6 Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 109 Jan 16 16:07:35 cerberusvm sshd[22335]: debug2: monitor_read: 108 used once, disabling now Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: pam_respond returned 1 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_query [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 106 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_sshpam_query: waiting for MONITOR_ANS_PAM_QUERY [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 107 [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: monitor_read: checking request 106 Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: mm_answer_pam_query Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: PAM: sshpam_query entering Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: ssh_msg_recv entering Jan 16 16:07:35 cerberusvm sshd[22339]: debug3: PAM: sshpam_thread_conv entering, 1 messages Jan 16 16:07:35 cerberusvm sshd[22339]: debug3: ssh_msg_send: type 4 Jan 16 16:07:35 cerberusvm sshd[22339]: Successful Duo login for 'jsmith' from 192.168.2.111 Jan 16 16:07:35 cerberusvm sshd[22339]: debug1: do_pam_account: called Jan 16 16:07:35 cerberusvm sshd[22335]: debug3: ssh_msg_recv entering Jan 16 16:09:05 cerberusvm sshd[22339]: debug3: PAM: do_pam_account pam_acct_mgmt = 9 (Authentication service cannot retrieve authentication info) Jan 16 16:09:05 cerberusvm sshd[22339]: debug3: ssh_msg_send: type 13 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: User account has expired Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 107 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_query: pam_query returned 0 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: send packet: type 60 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: Postponed keyboard-interactive/pam for jsmith from 192.168.2.111 port 56526 ssh2 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: receive packet: type 61 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_respond [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 108 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: waiting for MONITOR_ANS_PAM_RESPOND [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 109 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 108 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_answer_pam_respond Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: PAM: sshpam_respond entering, 0 responses Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 109 Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: monitor_read: 108 used once, disabling now Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_respond: pam_respond returned -1 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices <empty> [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_free_ctx [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 110 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_free_ctx: waiting for MONITOR_ANS_PAM_FREE_CTX [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 111 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 110 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_answer_pam_free_ctx Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_free_ctx entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_thread_cleanup entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 111 Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: monitor_read: 110 used once, disabling now Jan 16 16:09:05 cerberusvm sshd[22335]: Failed keyboard-interactive/pam for jsmith from 192.168.2.111 port 56526 ssh2 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=0 next methods="keyboard-interactive" [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: attempt 4 failures 1 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: input_userauth_request: try method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: keyboard-interactive devs [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge: user=jsmith devs= [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: kbdint_alloc: devices 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices pam [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: kbdint_next_device: devices <empty> [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge_start: trying authentication method 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 104 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: waiting for MONITOR_ANS_PAM_INIT_CTX [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 105 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 104 Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_answer_pam_init_ctx Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_init_ctx entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 105 Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: monitor_read: 104 used once, disabling now Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: pam_init_ctx failed [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: userauth_finish: failure partial=0 next methods="keyboard-interactive" [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: send packet: type 51 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: receive packet: type 50 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: userauth-request for user jsmith service ssh-connection method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: attempt 5 failures 2 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: input_userauth_request: try method keyboard-interactive [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: keyboard-interactive devs [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge: user=jsmith devs= [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: kbdint_alloc: devices 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: auth2_challenge_start: devices pam [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug2: kbdint_next_device: devices <empty> [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: auth2_challenge_start: trying authentication method 'pam' [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_send entering: type 104 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_sshpam_init_ctx: waiting for MONITOR_ANS_PAM_INIT_CTX [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive_expect entering: type 105 [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering [preauth] Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: mm_request_receive entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: monitor_read: checking request 104 Jan 16 16:09:05 cerberusvm sshd[22335]: fatal: monitor_read: unpermitted request 104 Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: do_cleanup Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: PAM: cleanup Jan 16 16:09:05 cerberusvm sshd[22335]: debug3: PAM: sshpam_thread_cleanup entering Jan 16 16:09:05 cerberusvm sshd[22335]: debug1: Killing privsep child 22336Now the interesting thing is that when I check `journalctl -u sssd.service`, at the same time this is starting (16:07:35), sssd appears to crash and restart:
Jan 16 16:07:35 cerberusvm.mydomain.com sssd[be[mydomain.com]][22340]: Starting up Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 1 Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 1 Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 1 Jan 16 16:07:36 cerberusvm.mydomain.com sssd_be[22340]: GSSAPI client step 2This made me look at dmesg, and sssd has been causing a ton of segfaults:
[Wed Jan 16 04:55:13 2019] traps: sssd_be[25969] general protection ip:7fdcd54ab766 sp:7fff5f1ce570 error:0 in libtalloc.so.2.1.13[7fdcd54a6000+e000] [Wed Jan 16 06:28:46 2019] traps: sssd_be[10849] general protection ip:7f9601987766 sp:7fffb5f35f10 error:0 in libtalloc.so.2.1.13[7f9601982000+e000] [Wed Jan 16 10:34:01 2019] traps: sssd_be[26901] general protection ip:7f8814b17766 sp:7fff46e2ab40 error:0 in libtalloc.so.2.1.13[7f8814b12000+e000] [Wed Jan 16 10:38:14 2019] traps: sssd_be[28969] general protection ip:7fab7b4a0766 sp:7fff85e9e2f0 error:0 in libtalloc.so.2.1.13[7fab7b49b000+e000] [Wed Jan 16 11:15:09 2019] sssd_be[3446]: segfault at 5646ffffffa0 ip 00007f9799f1f766 sp 00007ffd113922d0 error 4 in libtalloc.so.2.1.13[7f9799f1a000+e000] [Wed Jan 16 11:26:01 2019] sssd_be[4217]: segfault at ffffffffffffffa1 ip 00007f72eadb1766 sp 00007fffdac4d3c0 error 5 in libtalloc.so.2.1.13[7f72eadac000+e000] [Wed Jan 16 11:28:58 2019] sssd_be[6050]: segfault at b403 ip 00007f91435bb766 sp 00007fff278853b0 error 4 in libtalloc.so.2.1.13[7f91435b6000+e000] [Wed Jan 16 13:25:22 2019] traps: sssd_be[24797] general protection ip:7f63511b8766 sp:7ffcef433c90 error:0 in libtalloc.so.2.1.13[7f63511b3000+e000] [Wed Jan 16 13:41:34 2019] sssd_be[29033]: segfault at ffffffffffffffa3 ip 00007f65ef819766 sp 00007fff1827f8f0 error 5 in libtalloc.so.2.1.13[7f65ef814000+e000] [Wed Jan 16 13:44:57 2019] traps: sssd_be[29224] general protection ip:7fa76a909766 sp:7ffde8f7fc60 error:0 in libtalloc.so.2.1.13[7fa76a904000+e000] [Wed Jan 16 14:59:33 2019] sssd_be[6553]: segfault at ffffffffffffffa5 ip 00007f7af1396766 sp 00007ffcd4876d70 error 5 in libtalloc.so.2.1.13[7f7af1391000+e000] [Wed Jan 16 15:39:22 2019] sssd_be[19999]: segfault at 20 ip 00007f31511fa766 sp 00007fffbe331c40 error 4 in libtalloc.so.2.1.13[7f31511f5000+e000] [Wed Jan 16 15:41:36 2019] sssd_be[20245]: segfault at ffffffffffffffe8 ip 00007f0a9fe82766 sp 00007ffd9374afb0 error 5 in libtalloc.so.2.1.13[7f0a9fe7d000+e000] [Wed Jan 16 15:44:43 2019] sssd_be[21086]: segfault at ffffffffffffffaa ip 00007f442b1f6766 sp 00007fff2341ccb0 error 5 in libtalloc.so.2.1.13[7f442b1f1000+e000] [Wed Jan 16 15:50:24 2019] sssd_be[21155]: segfault at ffffffffffffffb0 ip 00007f4df0fcb766 sp 00007ffcecacbf60 error 5 in libtalloc.so.2.1.13[7f4df0fc6000+e000] [Wed Jan 16 16:05:56 2019] sssd_be[24929]: segfault at 501000da0 ip 00007faf383d3766 sp 00007ffc3ea27330 error 4 in libtalloc.so.2.1.13[7faf383ce000+e000] [Wed Jan 16 16:23:51 2019] sssd_be[25298]: segfault at 90 ip 00007fdadd768766 sp 00007fff09a8fe70 error 4 in libtalloc.so.2.1.13[7fdadd763000+e000] [Wed Jan 16 16:29:07 2019] sssd_be[28863]: segfault at 7fba0d3ea0b0 ip 00007fba65f7c766 sp 00007ffc96a709e0 error 4 in libtalloc.so.2.1.13[7fba65f77000+e000] [Wed Jan 16 16:29:24 2019] traps: sssd_be[28885] general protection ip:7f9492228766 sp:7fff07ffd300 error:0 in libtalloc.so.2.1.13[7f9492223000+e000]Although none specifically line up with the logs above, these logs are the cleanest versions of each I could put together and are best representative of the issue, but other failures which align with the segfault times are essentially the same (and all correlate with service restarts in /var/log/messages). If it is vital to see a log associated with one of these segfaults, let me know and I can try to assemble one.
Thanks
On Wed, Jan 16, 2019 at 3:12 PM Jordan Castillo jordantcastillo@gmail.com wrote:
Here are my log files for both the good and bad attempts.
sssd-users mailing list -- sssd-users@lists.fedorahosted.org To unsubscribe send an email to sssd-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.o...
Hi Sumit, Thanks for your response. I am running CentOS 7.4.1708 and installed sssd via yum. I have sssd-1.16.2-13.el7.x86_64 currently installed. None of the libraries mentioned are showing available updates. Here are the versions I see installed for them:
libtalloc-2.1.13-1.el7.x86_64 libtdb-1.3.15-1.el7.x86_64 libtevent-0.9.36-1.el7.x86_64 libldb-1.3.4-1.el7.x86_64
As a test, I have also disabled Duo in my pam.d/ssh config and removed it from the sshd config. The issues are persisting so I don't believe it is Duo related.
Jordan
On Thu, Jan 17, 2019 at 05:52:57PM -0000, Jordan Castillo wrote:
Hi Sumit, Thanks for your response. I am running CentOS 7.4.1708 and installed sssd via yum. I have sssd-1.16.2-13.el7.x86_64 currently installed. None of the libraries mentioned are showing available updates. Here are the versions I see installed for them:
libtalloc-2.1.13-1.el7.x86_64 libtdb-1.3.15-1.el7.x86_64 libtevent-0.9.36-1.el7.x86_64 libldb-1.3.4-1.el7.x86_64
What is the version of the samba-client-libs package?
bye, Sumit
As a test, I have also disabled Duo in my pam.d/ssh config and removed it from the sshd config. The issues are persisting so I don't believe it is Duo related.
Jordan _______________________________________________ sssd-users mailing list -- sssd-users@lists.fedorahosted.org To unsubscribe send an email to sssd-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.o...
Hi Sumit,
The server was running samba-client-libs-4.6.2-12. I did a yum update on samba-client-libs, samba-common-tools, samba-common, samba-common-libs, and samba-libs. Now it is running running 4.8.3-4 for all of those packages and I can no longer reproduce the issue. It appears to be fixed. Thank you so much for your help.
Best, Jordan
On Thu, Jan 17, 2019 at 09:27:19PM -0000, Jordan Castillo wrote:
Hi Sumit,
The server was running samba-client-libs-4.6.2-12. I did a yum update on samba-client-libs, samba-common-tools, samba-common, samba-common-libs, and samba-libs. Now it is running running 4.8.3-4 for all of those packages and I can no longer reproduce the issue. It appears to be fixed. Thank you so much for your help.
yw, glad I could help.
bye, Sumit
Best, Jordan _______________________________________________ sssd-users mailing list -- sssd-users@lists.fedorahosted.org To unsubscribe send an email to sssd-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.o...
sssd-users@lists.fedorahosted.org
-
Jordan Castillo -
Sumit Bose