Page 1 of 1

after recent round of patching, sshd no longer authenticates via AD(sssd)

Posted: 2020/11/24 19:00:34
by tguadagno
hi, i have about 20 CentOS 7 (CentOS Linux release 7.9.2009 (Core)) servers. i have configured them all the same way (with respect to AD authentication). I use realm to join them to my AD and this has worked for years.
Recently, after a round of patching (11/13) all of the servers stopped authenticating ssh sessions using AD creds. However, if i login to a server with root, i can su to the AD account without issue.
I think a patch changed the server behavior but i cannot figure out where the issue is. here are some logs that might help

I would really appreciate any ones input.

/var/log/sssd/sssd_somedomain.com:

Code: Select all

(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_dispatch] (0x4000): dbus conn: 0x561688c87cd0
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_dispatch] (0x4000): Dispatching.
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=tonyg@somedomain.com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_attach_req] (0x0400): DP Request [Initgroups #47]: New request. Flags [0x0001].
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_attach_req] (0x0400): Number of active DP request: 1
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [check_if_pac_is_available] (0x4000): No PAC available.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
(2020-11-24 13:51:21): [be[somedomain.com]] [get_ldap_conn_from_sdom_pvt] (0x4000): Returning LDAP connection for user lookup.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [DC=ffusa,DC=com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_print_server] (0x2000): Searching 172.19.4.40:389
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=tonyg)(objectclass=user)(objectSID=*))][DC=ffusa,DC=com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 6
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_op_add] (0x2000): New operation 6 timeout 6
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688cad9a0], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=Tony Guadagno,CN=Users,DC=ffusa,DC=com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [memberOf]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [name]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [primaryGroupID]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [accountExpires]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [userPrincipalName]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688cad9a0], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://ForestDnsZones.somedomain.com/DC=ForestDnsZones,DC=ffusa,DC=com
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688cad9a0], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://DomainDnsZones.somedomain.com/DC=DomainDnsZones,DC=ffusa,DC=com
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688cad9a0], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://somedomain.com/CN=Configuration,DC=ffusa,DC=com
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688cad9a0], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_op_destructor] (0x2000): Operation 6 finished
(2020-11-24 13:51:21): [be[somedomain.com]] [generic_ext_search_handler] (0x4000): Request included referrals which were ignored.
(2020-11-24 13:51:21): [be[somedomain.com]] [generic_ext_search_handler] (0x4000):     Ref: ldap://ForestDnsZones.somedomain.com/DC=ForestDnsZones,DC=ffusa,DC=com
(2020-11-24 13:51:21): [be[somedomain.com]] [generic_ext_search_handler] (0x4000):     Ref: ldap://DomainDnsZones.somedomain.com/DC=DomainDnsZones,DC=ffusa,DC=com
(2020-11-24 13:51:21): [be[somedomain.com]] [generic_ext_search_handler] (0x4000):     Ref: ldap://somedomain.com/CN=Configuration,DC=ffusa,DC=com
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_user] (0x4000): Storing the user
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_save_user] (0x0400): Save user
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_primary_name] (0x0400): Processing object tonyg
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_save_user] (0x0400): Processing user tonyg@somedomain.com
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_save_user] (0x1000): Mapping user [tonyg@somedomain.com] objectSID [S-1-5-21-4264107145-2280387099-501860720-1106] to unix ID
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_save_user] (0x2000): Adding originalDN [CN=Tony Guadagno,CN=Users,DC=ffusa,DC=com] to attributes of [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20201124154505.0Z] to attributes of [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_save_user] (0x0400): Adding user principal [tonyg@somedomain.com] to attributes of [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adAccountExpires [9223372036854775807] to attributes of [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [4260352] to attributes of [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedRHost is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): authType is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): userCertificate is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_attrs_add_ldap_attr] (0x2000): mail is not available for [tonyg@somedomain.com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_save_user] (0x0400): Storing info for user tonyg@somedomain.com
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object (32)]
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_set_cache_entry_attr] (0x0400): No such entry
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [tonyg@somedomain.com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_remove_attrs] (0x2000): Removing attribute [homeDirectory] from [tonyg@somedomain.com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_remove_attrs] (0x2000): Removing attribute [loginShell] from [tonyg@somedomain.com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_remove_attrs] (0x2000): Removing attribute [userCertificate] from [tonyg@somedomain.com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_remove_attrs] (0x2000): Removing attribute [mail] from [tonyg@somedomain.com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_user] (0x4000): Commit change
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_user] (0x4000): Process user's groups
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_print_server] (0x2000): Searching 172.19.4.40:389
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][CN=Tony Guadagno,CN=Users,DC=ffusa,DC=com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 7
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_op_add] (0x2000): New operation 7 timeout 6
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688ca1600], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688ca1600], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=Tony Guadagno,CN=Users,DC=ffusa,DC=com].
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_parse_range] (0x2000): No sub-attributes for [tokenGroups]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[0x561688ca1600], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_op_destructor] (0x2000): Operation 7 finished
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-32-551]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_idmap_sid_to_unix] (0x0400): Object SID [S-1-5-32-551] is a built-in one.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x0400): Skipping built-in object.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-32-544]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_idmap_sid_to_unix] (0x0400): Object SID [S-1-5-32-544] is a built-in one.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x0400): Skipping built-in object.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-32-545]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_idmap_sid_to_unix] (0x0400): Object SID [S-1-5-32-545] is a built-in one.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x0400): Skipping built-in object.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-572]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-572] maps to GID [1940200572]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=Denied RODC Password Replication Group@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-519]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-519] maps to GID [1940200519]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=Enterprise Admins@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-518]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-518] maps to GID [1940200518]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=Schema Admins@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-512]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-512] maps to GID [1940200512]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=Domain Admins@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-1218]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-1218] maps to GID [1940201218]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=VCenter Admins@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-1175]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-1175] maps to GID [1940201175]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=WebTickets@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-513]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-513] maps to GID [1940200513]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=Domain Users@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): Processing membership SID [S-1-5-21-4264107145-2280387099-501860720-1205]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_save_group_membership_with_idmapping] (0x1000): SID [S-1-5-21-4264107145-2280387099-501860720-1205] maps to GID [1940201205]
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=TSSUsers@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for [tonyg@somedomain.com]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_done] (0x4000): Initgroups done
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_done] (0x1000): Mapping primary group to unix ID
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=Domain Users@somedomain.com,cn=groups,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_done] (0x0400): Primary group already cached, nothing to do.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_get_initgr_done] (0x4000): No need to check for domain local group memberships.
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_id_op_destroy] (0x4000): releasing operation connection
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_id_op_done] (0x4000): releasing operation connection
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_done] (0x0400): DP Request [Initgroups #47]: Request handler finished [0]: Success
(2020-11-24 13:51:21): [be[somedomain.com]] [_dp_req_recv] (0x0400): DP Request [Initgroups #47]: Receiving request data.
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object (32)]
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_set_cache_entry_attr] (0x0400): No such entry
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_set_entry_attr] (0x0080): Cannot set ts attrs for name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #47]: Finished. Success.
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_reply_std] (0x1000): DP Request [Initgroups #47]: Returning [Success]: 0,0,Success
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::somedomain.com:name=tonyg@somedomain.com] from reply table
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_destructor] (0x0400): DP Request [Initgroups #47]: Request removed.
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: sh[0x561688c76dd0], connected[1], ops[(nil)], ldap[0x561688c9f400]
(2020-11-24 13:51:21): [be[somedomain.com]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_dispatch] (0x4000): dbus conn: 0x561688c8e7c0
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_dispatch] (0x4000): Dispatching.
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_dispatch] (0x4000): dbus conn: 0x561688c87cd0
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_dispatch] (0x4000): Dispatching.
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider
(2020-11-24 13:51:21): [be[somedomain.com]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_pam_handler] (0x0100): Got request with the following data
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): domain: somedomain.com
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): user: tonyg@somedomain.com
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): service: sshd
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): tty: ssh
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): ruser:
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): rhost: 192.168.199.12
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): authtok type: 1
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): newauthtok type: 0
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): priv: 1
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): cli_pid: 9594
(2020-11-24 13:51:21): [be[somedomain.com]] [pam_print_data] (0x0100): logon name: not set
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #48]: New request. Flags [0000].
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_attach_req] (0x0400): Number of active DP request: 1
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [krb5_auth_queue_send] (0x1000): Wait queue of user [tonyg@somedomain.com] is empty, running request [0x561688c9ca80] immediately.
(2020-11-24 13:51:21): [be[somedomain.com]] [krb5_setup] (0x4000): No mapping for: tonyg@somedomain.com
(2020-11-24 13:51:21): [be[somedomain.com]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=tonyg@somedomain.com,cn=users,cn=somedomain.com,cn=sysdb
(2020-11-24 13:51:21): [be[somedomain.com]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(2020-11-24 13:51:21): [be[somedomain.com]] [krb5_auth_send] (0x0100): Home directory for user [tonyg@somedomain.com] not known.
(2020-11-24 13:51:21): [be[somedomain.com]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
(2020-11-24 13:51:21): [be[somedomain.com]] [get_server_status] (0x1000): Status of server 'dc-1.somedomain.com' is 'working'
(2020-11-24 13:51:21): [be[somedomain.com]] [get_port_status] (0x1000): Port status of port 389 for server 'dc-1.somedomain.com' is 'working'
(2020-11-24 13:51:21): [be[somedomain.com]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(2020-11-24 13:51:21): [be[somedomain.com]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved
(2020-11-24 13:51:21): [be[somedomain.com]] [get_server_status] (0x1000): Status of server 'dc-1.somedomain.com' is 'working'
(2020-11-24 13:51:21): [be[somedomain.com]] [be_resolve_server_process] (0x1000): Saving the first resolved server
(2020-11-24 13:51:21): [be[somedomain.com]] [be_resolve_server_process] (0x0200): Found address for server dc-1.somedomain.com: [172.19.4.40] TTL 3600
(2020-11-24 13:51:21): [be[somedomain.com]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://dc-1.somedomain.com'
(2020-11-24 13:51:21): [be[somedomain.com]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://dc-1.somedomain.com'
(2020-11-24 13:51:21): [be[somedomain.com]] [krb5_add_krb5info_offline_callback] (0x4000): Removal callback already available for service [AD].
(2020-11-24 13:51:21): [be[somedomain.com]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_67aUWF]
(2020-11-24 13:51:21): [be[somedomain.com]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_67aUWF]
(2020-11-24 13:51:21): [be[somedomain.com]] [sss_domain_get_state] (0x1000): Domain somedomain.com is Active
(2020-11-24 13:51:21): [be[somedomain.com]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [9595]
(2020-11-24 13:51:21): [be[somedomain.com]] [child_handler_setup] (0x2000): Signal handler set up for pid [9595]
(2020-11-24 13:51:21): [be[somedomain.com]] [write_pipe_handler] (0x0400): All data has been sent!
(2020-11-24 13:51:21): [be[somedomain.com]] [child_sig_handler] (0x1000): Waiting for child [9595].
(2020-11-24 13:51:21): [be[somedomain.com]] [child_sig_handler] (0x0100): child [9595] finished successfully.
(2020-11-24 13:51:21): [be[somedomain.com]] [read_pipe_handler] (0x0400): EOF received, client finished
(2020-11-24 13:51:21): [be[somedomain.com]] [parse_krb5_child_response] (0x1000): child response [1432158209][6][8].
(2020-11-24 13:51:21): [be[somedomain.com]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information
(2020-11-24 13:51:21): [be[somedomain.com]] [check_wait_queue] (0x1000): Wait queue for user [tonyg@somedomain.com] is empty.
(2020-11-24 13:51:21): [be[somedomain.com]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x561688c9ca80] done.
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #48]: Request handler finished [0]: Success
(2020-11-24 13:51:21): [be[somedomain.com]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #48]: Receiving request data.
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #48]: Request removed.
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_method_enabled] (0x0400): Target selinux is not configured
(2020-11-24 13:51:21): [be[somedomain.com]] [dp_pam_reply] (0x1000): DP Request [PAM Authenticate #48]: Sending result [4][somedomain.com]
/var/log/sssd/krb5_child.log

Code: Select all

(2020-11-24 13:51:21): [krb5_child[9595]] [main] (0x0400): krb5_child started.
(2020-11-24 13:51:21): [krb5_child[9595]] [unpack_buffer] (0x1000): total buffer size: [158]
(2020-11-24 13:51:21): [krb5_child[9595]] [unpack_buffer] (0x0100): cmd [241] uid [1940201106] gid [1940200513] validate [true] enterprise principal [true] offline [false] UPN [tonyg@somedomain.com]
(2020-11-24 13:51:21): [krb5_child[9595]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1940201106] old_ccname: [KEYRING:persistent:1940201106] keytab: [/etc/krb5.keytab]
(2020-11-24 13:51:21): [krb5_child[9595]] [check_use_fast] (0x0100): Not using FAST.
(2020-11-24 13:51:21): [krb5_child[9595]] [switch_creds] (0x0200): Switch user to [1940201106][1940200513].
(2020-11-24 13:51:21): [krb5_child[9595]] [sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.
(2020-11-24 13:51:21): [krb5_child[9595]] [switch_creds] (0x0200): Switch user to [0][0].
(2020-11-24 13:51:21): [krb5_child[9595]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:1940201106] and is  active and TGT is  valid.
(2020-11-24 13:51:21): [krb5_child[9595]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
(2020-11-24 13:51:21): [krb5_child[9595]] [become_user] (0x0200): Trying to become user [1940201106][1940200513].
(2020-11-24 13:51:21): [krb5_child[9595]] [main] (0x2000): Running as [1940201106][1940200513].
(2020-11-24 13:51:21): [krb5_child[9595]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(2020-11-24 13:51:21): [krb5_child[9595]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(2020-11-24 13:51:21): [krb5_child[9595]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(2020-11-24 13:51:21): [krb5_child[9595]] [main] (0x0400): Will perform online auth
(2020-11-24 13:51:21): [krb5_child[9595]] [tgt_req_child] (0x1000): Attempting to get a TGT
(2020-11-24 13:51:21): [krb5_child[9595]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [somedomain.com]
(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798965: Getting initial credentials for tonyg\@somedomain.com@somedomain.com

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798967: Sending unauthenticated request

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798968: Sending request (196 bytes) to somedomain.com

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798969: Initiating TCP connection to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798970: Sending TCP request to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798971: Received answer (736 bytes) from stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798972: Terminating TCP connection to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798973: Response was from master KDC

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798974: Processing preauth types: PA-ETYPE-INFO2 (19)

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798975: Selected etype info: etype aes256-cts, salt "somedomain.comtonyg", params ""

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798976: Produced preauth for next request: (empty)

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_krb5_responder] (0x4000): Got question [password].
(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798977: Getting AS key, salt "somedomain.comtonyg", params ""

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798978: AS key obtained from gak_fct: aes256-cts/19C1

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798979: Decrypted AS reply; session key is: aes256-cts/25F3

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798980: FAST negotiation: unavailable

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [530265404]
(2020-11-24 13:51:21): [krb5_child[9595]] [validate_tgt] (0x2000): Found keytab entry with the realm of the credential.
(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798981: Retrieving restrictedkrbhost/ffcplws.somedomain.com@somedomain.com from MEMORY:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798982: Resolving unique ccache of type MEMORY

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798983: Initializing MEMORY:nPr0P2A with default princ tonyg@somedomain.com

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798984: Storing tonyg@somedomain.com -> krbtgt/somedomain.com@somedomain.com in MEMORY:nPr0P2A

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798985: Getting credentials tonyg@somedomain.com -> restrictedkrbhost/ffcplws.somedomain.com@somedomain.com using ccache MEMORY:nPr0P2A

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798986: Retrieving tonyg@somedomain.com -> restrictedkrbhost/ffcplws.somedomain.com@somedomain.com from MEMORY:nPr0P2A with result: -1765328243/Matching credential not found

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798987: Retrieving tonyg@somedomain.com -> krbtgt/somedomain.com@somedomain.com from MEMORY:nPr0P2A with result: 0/Success

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798988: Starting with TGT for client realm: tonyg@somedomain.com -> krbtgt/somedomain.com@somedomain.com

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798989: Requesting tickets for restrictedkrbhost/ffcplws.somedomain.com@somedomain.com, referrals on

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798990: Generated subkey for TGS request: aes256-cts/0A19

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798991: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798993: Encoding request body and padata into FAST request

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798994: Sending request (924 bytes) to somedomain.com

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798995: Initiating TCP connection to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798996: Sending TCP request to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798997: Received answer (347 bytes) from stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798998: Terminating TCP connection to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.798999: Response was from master KDC

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799000: Decoding FAST response

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799001: TGS request result: -1765328324/Generic error (see e-text)

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799002: Requesting tickets for restrictedkrbhost/ffcplws.somedomain.com@somedomain.com, referrals off

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799003: Generated subkey for TGS request: aes256-cts/0AAB

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799004: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799006: Encoding request body and padata into FAST request

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799007: Sending request (924 bytes) to somedomain.com

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799008: Initiating TCP connection to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799009: Sending TCP request to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799010: Received answer (347 bytes) from stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799011: Terminating TCP connection to stream 172.19.4.40:88

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799012: Response was from master KDC

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799013: Decoding FAST response

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799014: TGS request result: -1765328324/Generic error (see e-text)

(2020-11-24 13:51:21): [krb5_child[9595]] [sss_child_krb5_trace_cb] (0x4000): [9595] 1606243881.799015: Destroying ccache MEMORY:nPr0P2A

(2020-11-24 13:51:21): [krb5_child[9595]] [validate_tgt] (0x0020): TGT failed verification using key for [restrictedkrbhost/ffcplws.somedomain.com@somedomain.com].
(2020-11-24 13:51:21): [krb5_child[9595]] [get_and_save_tgt] (0x0020): 1742: [-1765328324][Generic error (see e-text)]
(2020-11-24 13:51:21): [krb5_child[9595]] [map_krb5_error] (0x0020): 1834: [-1765328324][Generic error (see e-text)]
(2020-11-24 13:51:21): [krb5_child[9595]] [k5c_send_data] (0x0200): Received error code 1432158209
(2020-11-24 13:51:21): [krb5_child[9595]] [pack_response_packet] (0x2000): response packet size: [20]
(2020-11-24 13:51:21): [krb5_child[9595]] [k5c_send_data] (0x4000): Response sent.
(2020-11-24 13:51:21): [krb5_child[9595]] [main] (0x0400): krb5_child completed successfully