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(a)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(a)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(a)mydomain.com]
(Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_set_entry_attr]
(0x0200): Entry [name=jsmith(a)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(a)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>[^(a)\\]+)$))].
(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(a)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$(a)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(a)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(a)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(a)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(a)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(a)openssh.com,
hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm(a)openssh.com,
hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128(a)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(a)openssh.com,
hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm(a)openssh.com,
hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128(a)openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[preauth]
Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none,
zlib(a)openssh.com [preauth]
Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none,
zlib(a)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(a)openssh.com,
ecdsa-sha2-nistp384-cert-v01(a)openssh.com,
ecdsa-sha2-nistp521-cert-v01(a)openssh.com
,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,
ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01(a)openssh.com,
ssh-dss-cert-v01(a)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(a)openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,
aes128-gcm@openssh.com,aes256-gcm(a)openssh.com,aes128-cbc,aes192-cbc,aes256-cbc
[preauth]
Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers stoc:
chacha20-poly1305(a)openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,
aes128-gcm@openssh.com,aes256-gcm(a)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(a)openssh.com,
hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm(a)openssh.com,
hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128(a)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(a)openssh.com,
hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm(a)openssh.com,
hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128(a)openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
[preauth]
Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none,
zlib(a)openssh.com,zlib [preauth]
Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none,
zlib(a)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(a)openssh.com MAC: <implicit> compression: none [preauth]
Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: server->client cipher:
chacha20-poly1305(a)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(a)gmail.com>
wrote:
Here are my log files for both the good and bad attempts.