[SSSD-users] Re: Intermittent SSH authentication failures: SSSD+AD+PAM+Duo

[Sumit Bose]

On Wed, Jan 16, 2019 at 05:02:44PM -0800, Jordan Castillo wrote:
> I actually have a followup to this already and it seems that I'm seeing
> segfaults and service restarts around the times of these failed attempts.

Which package version of SSSD are you using? Please make sure all
required libraries are updated to the latest versions, especially
libtalloc, libtdb, libtevent and libldb.

HTH

bye,
Sumit

> 
> Here is a better bad login attempt sssd_domain.com.log log, at level 0x1310:
> 
> ```
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [dp_get_account_info_handler] (0x0200): Got request for
> [0x3][BE_REQ_INITGROUPS][name=jsm...@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=jsm...@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 [
> jsm...@mydomain.com]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sysdb_set_entry_attr]
> (0x0200): Entry [name=jsm...@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: jsm...@mydomain.com
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): service: sshd
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): tty: ssh
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): ruser:
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): rhost: 192.168.2.111
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): authtok type: 0
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): newauthtok type: 0
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): priv: 1
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): cli_pid: 22339
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [pam_print_data]
> (0x0100): logon name: not set
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_domain_get_state]
> (0x1000): Domain mydomain.com is Active
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [distinguishedName]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [CN=cerberusvm,CN=Computers,DC=mydomain,DC=com].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_add_references] (0x1000): Additional References:
> ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [configurationNamingContext]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPLink]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gpOptions]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN:
> [cn=Default-First-Site-Name,cn=Sites,CN=Configuration,DC=mydomain,DC=com].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): Entry has no attributes [0(Success)]!?
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [nTSecurityDescriptor]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gPCFileSysPath]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [gPCMachineExtensionNames]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [gPCFunctionalityVersion]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flags]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN:
> [CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=mydomain,DC=com].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [be_res_get_opts]
> (0x0100): Lookup order: ipv4_first
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [recreate_ares_channel]
> (0x0100): Initializing new c-ares channel
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [confdb_get_domain_internal] (0x1000): pwd_expiration_warning is -1
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sysdb_domain_init_internal] (0x0200): DB File for mydomain.com:
> /var/lib/sss/db/cache_mydomain.com.ldb
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sysdb_domain_init_internal] (0x0200): Timestamp file for mydomain.com:
> /var/lib/sss/db/timestamps_mydomain.com.ldb
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [monitor_common_send_id] (0x0100): Sending ID: (%BE_mydomain.com,1)
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]]
> [sss_names_init_from_args] (0x0100): Using re
> [(((?P<domain>[^\\]+)\\(?P<name>.+$))|((?P<name>[^@]+)@(?P<domain>.+$))|(^(?P<name>[^@\\]+)$))].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [sss_fqnames_init]
> (0x0100): Using fq format [%1$s@%2$s].
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [create_socket_symlink]
> (0x1000): Symlinking the dbus path
> /var/lib/sss/pipes/private/sbus-dp_mydomain.com.22340 to a link
> /var/lib/sss/pipes/private/sbus-dp_mydomain.com
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [id]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [auth]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [access]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [chpass]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [sudo]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [autofs]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [selinux]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [hostid]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [subdomains]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_load_configuration]
> (0x0100): Using [ad] provider for [session]
> (Wed Jan 16 16:07:35 2019) [sssd[be[mydomain.com]]] [dp_module_open_lib]
> (0x1000): Loading module [ad] with path [/usr/lib64/sssd/libsss_ad.so]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_common_options]
> (0x0100): Setting domain option case_sensitive to [false]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [krb5_service_new]
> (0x0100): write_kdcinfo for realm mydomain.COM set to false
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [_ad_servers_init]
> (0x0100): Added failover server prodad1.mydomain.com
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_sdap_options]
> (0x0100): Option krb5_realm set to mydomain.COM
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options]
> (0x0100): Will look for cerberusvm.mydomain....@mydomain.com in default
> keytab
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [select_principal_from_keytab] (0x0200): trying to select the most
> appropriate principal from keytab
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [match_principal]
> (0x1000): Principal matched to the sample (CERBERUSVM$@mydomain.COM).
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [select_principal_from_keytab] (0x0200): Selected primary: CERBERUSVM$
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [select_principal_from_keytab] (0x0200): Selected realm: mydomain.COM
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options]
> (0x0100): Option ldap_sasl_authid set to CERBERUSVM$
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_sasl_options]
> (0x0100): Option ldap_sasl_realm set to mydomain.COM
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_search_bases]
> (0x0100): Search base not set. SSSD will attempt to discover it later, when
> connecting to the LDAP server.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_dyndns_init]
> (0x0100): Dynamic DNS updates are off.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options]
> (0x0100): Option krb5_server set to prodad1.mydomain.com
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options]
> (0x0100): Option krb5_realm set to mydomain.COM
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_get_auth_options]
> (0x0100): Option krb5_use_kdcinfo set to true
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [check_lifetime]
> (0x0200): No lifetime configured.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [check_lifetime]
> (0x0200): No lifetime configured.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sss_krb5_check_options] (0x0100): No kpasswd server explicitly configured,
> using the KDC or defaults.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [parse_krb5_map_user]
> (0x0100): krb5_map_user is empty!
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init]
> (0x0100): Target [selinux] is not supported by module [ad].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init]
> (0x0100): Target [hostid] is not supported by module [ad].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sss_write_krb5_localauth_snippet] (0x0200): File for localauth plugin
> configuration is [/var/lib/sss/pubconf/krb5.include.d/localauth_plugin]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sss_write_krb5_libdefaults_snippet] (0x0200): File for KRB5 kibdefaults
> configuration is [/var/lib/sss/pubconf/krb5.include.d/krb5_libdefaults]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sss_write_domain_mappings] (0x0200): Mapping file for domain [mydomain.com]
> is [/var/lib/sss/pubconf/krb5.include.d/domain_realm_mydomain_com]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_set_search_bases]
> (0x0100): Search base not set. SSSD will attempt to discover it later, when
> connecting to the LDAP server.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_target_init]
> (0x0100): Target [session] is not supported by module [ad].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [become_user] (0x0200):
> Trying to become user [0][0].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [become_user] (0x0200):
> Already user [0].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status]
> (0x1000): Status of server 'prodad1.mydomain.com' is 'name not resolved'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_port_status]
> (0x1000): Port status of port 0 for server 'prodad1.mydomain.com' is
> 'neutral'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status]
> (0x1000): Status of server 'prodad1.mydomain.com' is 'name not resolved'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of '
> prodad1.mydomain.com' in files
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com'
> as 'resolving name'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record
> of 'prodad1.mydomain.com' in files
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [resolv_gethostbyname_next] (0x0200): No more address families to retry
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of '
> prodad1.mydomain.com' in DNS
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [id_callback] (0x0100):
> Got id ack and version (1) from Monitor
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com'
> as 'name resolved'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [be_resolve_server_process] (0x1000): Saving the first resolved server
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [be_resolve_server_process] (0x0200): Found address for server
> prodad1.mydomain.com: [192.168.2.13] TTL 10800
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_resolve_callback]
> (0x0100): Constructed uri 'ldap://prodad1.mydomain.com'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [ad_resolve_callback]
> (0x0100): Constructed GC uri 'ldap://prodad1.mydomain.com'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://
> prodad1.mydomain.com:389/??base] with fd [19].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [supportedLDAPVersion]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [supportedSASLMechanisms]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [domainControllerFunctionality]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [defaultNamingContext]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [highestCommittedUSN]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_naming_context]
> (0x0200): Using value from [defaultNamingContext] as naming context.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_search_base] to [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [DEFAULT][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_user_search_base] to [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [USER][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_group_search_base] to [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [GROUP][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_netgroup_search_base] to
> [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [NETGROUP][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_host_search_base] to [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [HOST][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_sudo_search_base] to [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [SUDO][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_service_search_base] to [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [SERVICE][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_set_search_base]
> (0x0100): Setting option [ldap_autofs_search_base] to [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [common_parse_search_base] (0x0100): Search base added:
> [AUTOFS][DC=mydomain,DC=com][SUBTREE][]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility
> level to [6]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_server_opts_from_rootdse] (0x0100): Will look for schema at
> [CN=Schema,CN=Configuration,DC=mydomain,DC=com]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_kinit_next_kdc]
> (0x1000): Resolving next KDC for service AD
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status]
> (0x1000): Status of server 'prodad1.mydomain.com' is 'name resolved'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [get_server_status]
> (0x1000): Status of server 'prodad1.mydomain.com' is 'name resolved'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [be_resolve_server_process] (0x1000): Saving the first resolved server
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [be_resolve_server_process] (0x0200): Found address for server
> prodad1.mydomain.com: [192.168.2.13] TTL 10800
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT...
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [child_sig_handler]
> (0x1000): Waiting for child [22341].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [child_sig_handler]
> (0x0100): child [22341] finished successfully.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_cli_auth_step]
> (0x0100): expire timeout is 900
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_cli_auth_step]
> (0x1000): the connection will expire at 1547684556
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sasl_bind_send]
> (0x0100): Executing sasl bind mech: gssapi, user: CERBERUSVM$
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [fo_set_port_status]
> (0x0100): Marking port 0 of server 'prodad1.mydomain.com' as 'working'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [set_server_common_status] (0x0100): Marking server 'prodad1.mydomain.com'
> as 'working'
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN: [].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs:
> [isMemberOfPartialAttributeSet]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN:
> [CN=GidNumber,CN=Schema,CN=Configuration,DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [sdap_parse_entry]
> (0x1000): OriginalDN:
> [CN=UidNumber,CN=Schema,CN=Configuration,DC=mydomain,DC=com].
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [flatName]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustPartner]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [securityIdentifier]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustType]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [trustAttributes]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_add_references] (0x1000): Additional References:
> ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [ad_get_slave_domain_done] (0x1000): There are no changes
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [delayed_online_authentication_callback] (0x0200): Backend is online,
> starting delayed online authentication.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Entering.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Adding connection
> 0x5632c53a92d0.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Got a connection
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init]
> (0x0100): Set-up Backend ID timeout [0x5632c53af940]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Entering.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Adding connection
> 0x5632c53ab5d0.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Got a connection
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init]
> (0x0100): Set-up Backend ID timeout [0x5632c539c5a0]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Entering.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Adding connection
> 0x5632c53b3600.
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]]
> [sbus_server_init_new_connection] (0x0200): Got a connection
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_init]
> (0x0100): Set-up Backend ID timeout [0x5632c53b9710]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register]
> (0x0100): Cancel DP ID timeout [0x5632c53af940]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register]
> (0x0100): Added Frontend client [PAM]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register]
> (0x0100): Cancel DP ID timeout [0x5632c539c5a0]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register]
> (0x0100): Added Frontend client [SSH]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register]
> (0x0100): Cancel DP ID timeout [0x5632c53b9710]
> (Wed Jan 16 16:07:36 2019) [sssd[be[mydomain.com]]] [dp_client_register]
> (0x0100): Added Frontend client [NSS]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [check_ipv4_addr]
> (0x0200): Loopback IPv4 address 127.0.0.1
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]] [check_ipv6_addr]
> (0x0200): Loopback IPv6 address ::1
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoCommand]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoHost]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoUser]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOption]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAs]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsUser]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoRunAsGroup]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotBefore]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoNotAfter]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sudoOrder]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
> (Wed Jan 16 16:07:46 2019) [sssd[be[mydomain.com]]]
> [sdap_get_generic_ext_add_references] (0x1000): Additional References:
> ldap://mydomain.com/CN=Configuration,DC=mydomain,DC=com
> (Wed Jan 16 16:08:01 2019) [sssd[be[mydomain.com]]]
> [dp_get_account_info_handler] (0x0200): Got request for
> [0x1][BE_REQ_USER][name=jlev...@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=jlev...@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-sha...@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-poly1...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,
> aes128-...@openssh.com,aes256-...@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-poly1...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,
> aes128-...@openssh.com,aes256-...@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-...@openssh.com,umac-128-...@openssh.com,
> hmac-sha2-256-...@openssh.com,hmac-sha2-512-...@openssh.com,
> hmac-sha1-...@openssh.com,umac...@openssh.com,umac-...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
> [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs stoc:
> umac-64-...@openssh.com,umac-128-...@openssh.com,
> hmac-sha2-256-...@openssh.com,hmac-sha2-512-...@openssh.com,
> hmac-sha1-...@openssh.com,umac...@openssh.com,umac-...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
> [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none,
> z...@openssh.com [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none,
> z...@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-sha...@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-...@openssh.com,
> ecdsa-sha2-nistp384-cert-...@openssh.com,
> ecdsa-sha2-nistp521-cert-...@openssh.com
> ,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,
> ssh-ed25519-cert-...@openssh.com,ssh-rsa-cert-...@openssh.com,
> ssh-dss-cert-...@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-poly1...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,
> aes128-...@openssh.com,aes256-...@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc
> [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: ciphers stoc:
> chacha20-poly1...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,
> aes128-...@openssh.com,aes256-...@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc
> [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs ctos:
> umac-64-...@openssh.com,umac-128-...@openssh.com,
> hmac-sha2-256-...@openssh.com,hmac-sha2-512-...@openssh.com,
> hmac-sha1-...@openssh.com,umac...@openssh.com,umac-...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
> [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: MACs stoc:
> umac-64-...@openssh.com,umac-128-...@openssh.com,
> hmac-sha2-256-...@openssh.com,hmac-sha2-512-...@openssh.com,
> hmac-sha1-...@openssh.com,umac...@openssh.com,umac-...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
> [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression ctos: none,
> z...@openssh.com,zlib [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug2: compression stoc: none,
> z...@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-poly1...@openssh.com MAC: <implicit> compression: none [preauth]
> Jan 16 16:07:33 cerberusvm sshd[22335]: debug1: kex: server->client cipher:
> chacha20-poly1...@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 <jordantcasti...@gmail.com>
> wrote:
> 
> > Here are my log files for both the good and bad attempts.
> >

> _______________________________________________
> sssd-users mailing list -- sssd-users@lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-le...@lists.fedorahosted.org
> Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: 
> https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.org
_______________________________________________
sssd-users mailing list -- sssd-users@lists.fedorahosted.org
To unsubscribe send an email to sssd-users-le...@lists.fedorahosted.org
Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: 
https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.org