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(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.
>