Alexander Spannagel
2019-Feb-28 16:08 UTC
[Samba] winbind causing huge timeouts/delays since 4.8
Am 26.02.19 um 12:26 schrieb Ralph Böhme:> On Tue, Feb 26, 2019 at 11:19:45AM +0100, Alexander Spannagel via samba > wrote: >> The huge delays are seen, when user isn't known to sssd and winbind >> tries to look that user without explicitly a domain given and the >> option "winbind use default domain" is on it's default of "No" in >> smb.conf. > > can you test with the latest Samba version? Ideally with the Samba > development branch master from git. If it's reproducible there, the > level 10 logs from winbindd would tell us what's going wrong. > > -slow >It has taken it's time to get the latest version from git compiled (4.11), but finally i got it completed and working as needed (e.g. existing local and domain accounts resolve as needed). Bad news the problem is still around and reproducible. I teared down noisy services, so i could generate logs with only wbinfo call hitting winbind for testing. Here my result from command line: [root at centos7dev64 samba]# systemctl restart smb winbind sssd ; sss_cache -E ; net cache flush ; date ; smbcontrol winbind debug 10 ; sleep 60 ; date ; touch start ; wbinfo -i foo ; touch stop ; smbcontrol winbind debug 3 ; date ; sleep 5 ; sync ; cp -a st* log.winbindd* log.wb* BAK/ Thu Feb 28 10:31:52 EST 2019 Thu Feb 28 10:32:52 EST 2019 failed to call wbcGetpwnam: WBC_ERR_DOMAIN_NOT_FOUND Could not get info for user foo Thu Feb 28 10:33:52 EST 2019 [root at centos7dev64 samba]# Beside log.winbindd i also added log.wb-CENTOS7DEV64 as it may be of interest too. So let me know if there is something i can test once more. Alex -------------- next part -------------- [2019/02/28 10:31:52.827255, 3] ../../lib/util/debug_s3.c:75(debug_message) INFO: Remote set of debug to `10' (pid 18451 from pid 18439) [2019/02/28 10:31:52.827297, 5, pid=18451, effective(0, 0), real(0, 0)] ../../lib/util/debug.c:804(debug_dump_status) INFO: Current debug levels: all: 10 tdb: 10 printdrivers: 10 lanman: 10 smb: 10 rpc_parse: 10 rpc_srv: 10 rpc_cli: 10 passdb: 10 sam: 10 auth: 10 winbind: 10 vfs: 10 idmap: 10 quota: 10 acls: 10 locking: 10 msdfs: 10 dmapi: 10 registry: 10 scavenger: 10 dns: 10 ldb: 10 tevent: 10 auth_audit: 10 auth_json_audit: 10 kerberos: 10 drs_repl: 10 smb2: 10 smb2_credits: 10 dsdb_audit: 10 dsdb_json_audit: 10 dsdb_password_audit: 10 dsdb_password_json_audit: 10 dsdb_transaction_audit: 10 dsdb_transaction_json_audit: 10 dsdb_group_audit: 10 dsdb_group_json_audit: 10 [2019/02/28 10:32:22.837321, 10, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:1828(fork_domain_child) fork_domain_child: domain CENTOS7DEV64 no longer in 'startup' mode. [2019/02/28 10:32:52.906306, 10, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:119(child_read_request) Need to read 36 extra bytes [2019/02/28 10:32:52.906359, 4, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:1597(child_handler) child daemon request 56 [2019/02/28 10:32:52.906389, 10, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:744(child_process_request) child_process_request: request fn NDRCMD [2019/02/28 10:32:52.906419, 10, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual_ndr.c:362(winbindd_dual_ndrcmd) winbindd_dual_ndrcmd: Running command WBINT_LOOKUPNAME (CENTOS7DEV64) [2019/02/28 10:32:52.906474, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : '' name : * name : 'FOO' flags : 0x00000008 (8) [2019/02/28 10:32:52.906640, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/namemap_cache.c:324(namemap_cache_find_name) namemap_cache_find_name: gencache_parse(NAME2SID/\FOO) failed [2019/02/28 10:32:52.906679, 10, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cache.c:1772(wcache_name_to_sid) wcache_name_to_sid: namemap_cache_find_name failed [2019/02/28 10:32:52.906709, 10, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cache.c:1819(wb_cache_name_to_sid) name_to_sid: [Cached] - doing backend query for name for domain CENTOS7DEV64 [2019/02/28 10:32:52.906738, 3, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_samr.c:595(sam_name_to_sid) sam_name_to_sid [2019/02/28 10:32:52.906771, 3, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_rpc.c:280(rpc_name_to_sid) name_to_sid: FOO for domain [2019/02/28 10:32:52.906848, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) lsa_LookupNames: struct lsa_LookupNames in: struct lsa_LookupNames handle : * handle: struct policy_handle handle_type : 0x00000000 (0) uuid : 00000020-0000-0000-775c-e8fe13480000 num_names : 0x00000001 (1) names: ARRAY(1) names: struct lsa_String length : 0x0006 (6) size : 0x0006 (6) string : * string : 'FOO' sids : * sids: struct lsa_TransSidArray count : 0x00000000 (0) sids : NULL level : LSA_LOOKUP_NAMES_ALL (1) count : * count : 0x00000000 (0) [2019/02/28 10:32:52.907160, 6, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:339(find_policy_by_hnd_internal) Found policy hnd[0] [0000] 00 00 00 00 20 00 00 00 00 00 00 00 77 5C E8 FE .... ... ....w\.. [0010] 13 48 00 00 .H.. [2019/02/28 10:32:52.907228, 5, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/lsa/srv_lsa_nt.c:163(lookup_lsa_rids) lookup_lsa_rids: looking up name FOO [2019/02/28 10:32:52.907259, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/passdb/lookup_sid.c:113(lookup_name) lookup_name: FOO => domain=[], name=[FOO] [2019/02/28 10:32:52.907284, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/passdb/lookup_sid.c:114(lookup_name) lookup_name: flags = 0x073 [2019/02/28 10:32:52.907317, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/util_wellknown.c:165(lookup_wellknown_name) map_name_to_wellknown_sid: looking up \FOO [2019/02/28 10:32:52.907386, 5, pid=18451, effective(0, 0), real(0, 0), class=passdb] ../../source3/passdb/pdb_tdb.c:600(tdbsam_getsampwnam) pdb_getsampwnam (TDB): error fetching database. Key: USER_foo [2019/02/28 10:32:52.907444, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/groupdb/mapping_tdb.c:279(find_map) failed to unpack map [2019/02/28 10:32:52.907532, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/groupdb/mapping_tdb.c:279(find_map) failed to unpack map [2019/02/28 10:32:52.907624, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:181(Get_Pwnam_alloc) Finding user FOO [2019/02/28 10:32:52.907660, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:120(Get_Pwnam_internals) Trying _Get_Pwnam(), username as lowercase is foo [2019/02/28 10:33:02.388357, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:128(Get_Pwnam_internals) Trying _Get_Pwnam(), username as given is FOO [2019/02/28 10:33:12.388229, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:153(Get_Pwnam_internals) Checking combinations of 0 uppercase letters in foo [2019/02/28 10:33:12.388269, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:159(Get_Pwnam_internals) Get_Pwnam_internals didn't find user [FOO]! [2019/02/28 10:33:22.388268, 5, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/lsa/srv_lsa_nt.c:181(lookup_lsa_rids) init_lsa_rids: FOO not found [2019/02/28 10:33:22.388308, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) lsa_LookupNames: struct lsa_LookupNames out: struct lsa_LookupNames domains : * domains : * domains: struct lsa_RefDomainList count : 0x00000000 (0) domains : NULL max_size : 0x00000000 (0) sids : * sids: struct lsa_TransSidArray count : 0x00000001 (1) sids : * sids: ARRAY(1) sids: struct lsa_TranslatedSid sid_type : SID_NAME_UNKNOWN (8) rid : 0x00000000 (0) sid_index : 0xffffffff (4294967295) count : * count : 0x00000000 (0) result : NT_STATUS_NONE_MAPPED [2019/02/28 10:33:22.388547, 2, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_rpc.c:299(rpc_name_to_sid) name_to_sid: failed to lookup name: NT_STATUS_NONE_MAPPED [2019/02/28 10:33:22.388593, 10, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:418(close_policy_by_pipe) Deleted handle list for RPC connection samr [2019/02/28 10:33:22.388664, 4, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_ncacn_np.c:221(make_internal_rpc_pipe_p) Create pipe requested samr [2019/02/28 10:33:22.388699, 10, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:223(init_pipe_handles) init_pipe_handle_list: created handle list for pipe samr [2019/02/28 10:33:22.388724, 10, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:240(init_pipe_handles) init_pipe_handle_list: pipe_handles ref count = 1 for pipe samr [2019/02/28 10:33:22.388787, 4, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_ncacn_np.c:261(make_internal_rpc_pipe_p) Created internal pipe samr [2019/02/28 10:33:22.388838, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) samr_Connect2: struct samr_Connect2 in: struct samr_Connect2 system_name : NULL access_mask : 0x02000000 (33554432) 0: SAMR_ACCESS_CONNECT_TO_SERVER 0: SAMR_ACCESS_SHUTDOWN_SERVER 0: SAMR_ACCESS_INITIALIZE_SERVER 0: SAMR_ACCESS_CREATE_DOMAIN 0: SAMR_ACCESS_ENUM_DOMAINS 0: SAMR_ACCESS_LOOKUP_DOMAIN [2019/02/28 10:33:22.388966, 5, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/samr/srv_samr_nt.c:3889(_samr_Connect2) _samr_Connect2: 3889 [2019/02/28 10:33:22.389011, 10, pid=18451, effective(0, 0), real(0, 0)] ../../libcli/security/access_check.c:58(se_map_generic) se_map_generic(): mapped mask 0xb0000000 to 0x000f003f [2019/02/28 10:33:22.389047, 4, pid=18451, effective(0, 0), real(0, 0)] ../../source3/rpc_server/srv_access_check.c:95(access_check_object) _samr_Connect2: ACCESS should be DENIED (requested: 0x000f003f) but overritten by euid == initial uid [2019/02/28 10:33:22.389078, 4, pid=18451, effective(0, 0), real(0, 0)] ../../source3/rpc_server/srv_access_check.c:117(access_check_object) _samr_Connect2: access GRANTED (requested: 0x000f003f, granted: 0x000f003f) [2019/02/28 10:33:22.389105, 6, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:304(create_rpc_handle_internal) Opened policy hnd[1] [0000] 00 00 00 00 21 00 00 00 00 00 00 00 77 5C 42 FF ....!... ....w\B. [0010] 13 48 00 00 .H.. [2019/02/28 10:33:22.389180, 5, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/samr/srv_samr_nt.c:3918(_samr_Connect2) _samr_Connect2: 3918 [2019/02/28 10:33:22.389207, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) samr_Connect2: struct samr_Connect2 out: struct samr_Connect2 connect_handle : * connect_handle: struct policy_handle handle_type : 0x00000000 (0) uuid : 00000021-0000-0000-775c-42ff13480000 result : NT_STATUS_OK [2019/02/28 10:33:22.389319, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) samr_OpenDomain: struct samr_OpenDomain in: struct samr_OpenDomain connect_handle : * connect_handle: struct policy_handle handle_type : 0x00000000 (0) uuid : 00000021-0000-0000-775c-42ff13480000 access_mask : 0x02000000 (33554432) 0: SAMR_DOMAIN_ACCESS_LOOKUP_INFO_1 0: SAMR_DOMAIN_ACCESS_SET_INFO_1 0: SAMR_DOMAIN_ACCESS_LOOKUP_INFO_2 0: SAMR_DOMAIN_ACCESS_SET_INFO_2 0: SAMR_DOMAIN_ACCESS_CREATE_USER 0: SAMR_DOMAIN_ACCESS_CREATE_GROUP 0: SAMR_DOMAIN_ACCESS_CREATE_ALIAS 0: SAMR_DOMAIN_ACCESS_LOOKUP_ALIAS 0: SAMR_DOMAIN_ACCESS_ENUM_ACCOUNTS 0: SAMR_DOMAIN_ACCESS_OPEN_ACCOUNT 0: SAMR_DOMAIN_ACCESS_SET_INFO_3 sid : * sid : S-1-5-21-2661641715-394499615-2988108416 [2019/02/28 10:33:22.389519, 6, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:339(find_policy_by_hnd_internal) Found policy hnd[0] [0000] 00 00 00 00 21 00 00 00 00 00 00 00 77 5C 42 FF ....!... ....w\B. [0010] 13 48 00 00 .H.. [2019/02/28 10:33:22.389571, 10, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:523(_policy_handle_find) found handle of type struct samr_connect_info [2019/02/28 10:33:22.389599, 10, pid=18451, effective(0, 0), real(0, 0)] ../../libcli/security/access_check.c:58(se_map_generic) se_map_generic(): mapped mask 0xb0000000 to 0x000f07ff [2019/02/28 10:33:22.389626, 4, pid=18451, effective(0, 0), real(0, 0)] ../../source3/rpc_server/srv_access_check.c:84(access_check_object) access_check_object: user rights access mask [0x3f0] [2019/02/28 10:33:22.389651, 4, pid=18451, effective(0, 0), real(0, 0)] ../../source3/rpc_server/srv_access_check.c:95(access_check_object) _samr_OpenDomain: ACCESS should be DENIED (requested: 0x000f040f) but overritten by euid == initial uid [2019/02/28 10:33:22.389681, 4, pid=18451, effective(0, 0), real(0, 0)] ../../source3/rpc_server/srv_access_check.c:117(access_check_object) _samr_OpenDomain: access GRANTED (requested: 0x000f040f, granted: 0x000f07ff) [2019/02/28 10:33:22.389708, 6, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:304(create_rpc_handle_internal) Opened policy hnd[2] [0000] 00 00 00 00 22 00 00 00 00 00 00 00 77 5C 42 FF ...."... ....w\B. [0010] 13 48 00 00 .H.. [2019/02/28 10:33:22.389757, 5, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/samr/srv_samr_nt.c:506(_samr_OpenDomain) _samr_OpenDomain: 506 [2019/02/28 10:33:22.389786, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) samr_OpenDomain: struct samr_OpenDomain out: struct samr_OpenDomain domain_handle : * domain_handle: struct policy_handle handle_type : 0x00000000 (0) uuid : 00000022-0000-0000-775c-42ff13480000 result : NT_STATUS_OK [2019/02/28 10:33:22.389976, 4, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_ncacn_np.c:221(make_internal_rpc_pipe_p) Create pipe requested lsarpc [2019/02/28 10:33:22.390011, 10, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:240(init_pipe_handles) init_pipe_handle_list: pipe_handles ref count = 2 for pipe lsarpc [2019/02/28 10:33:22.390064, 4, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_ncacn_np.c:261(make_internal_rpc_pipe_p) Created internal pipe lsarpc [2019/02/28 10:33:22.390112, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) lsa_OpenPolicy: struct lsa_OpenPolicy in: struct lsa_OpenPolicy system_name : * system_name : 0x005c (92) attr : * attr: struct lsa_ObjectAttribute len : 0x00000018 (24) root_dir : NULL object_name : NULL attributes : 0x00000000 (0) sec_desc : NULL sec_qos : * sec_qos: struct lsa_QosInfo len : 0x0000000c (12) impersonation_level : 0x0002 (2) context_mode : 0x01 (1) effective_only : 0x00 (0) access_mask : 0x02000000 (33554432) 0: LSA_POLICY_VIEW_LOCAL_INFORMATION 0: LSA_POLICY_VIEW_AUDIT_INFORMATION 0: LSA_POLICY_GET_PRIVATE_INFORMATION 0: LSA_POLICY_TRUST_ADMIN 0: LSA_POLICY_CREATE_ACCOUNT 0: LSA_POLICY_CREATE_SECRET 0: LSA_POLICY_CREATE_PRIVILEGE 0: LSA_POLICY_SET_DEFAULT_QUOTA_LIMITS 0: LSA_POLICY_SET_AUDIT_REQUIREMENTS 0: LSA_POLICY_AUDIT_LOG_ADMIN 0: LSA_POLICY_SERVER_ADMIN 0: LSA_POLICY_LOOKUP_NAMES 0: LSA_POLICY_NOTIFICATION [2019/02/28 10:33:22.390415, 10, pid=18451, effective(0, 0), real(0, 0)] ../../libcli/security/access_check.c:58(se_map_generic) se_map_generic(): mapped mask 0xb0000000 to 0x000f1fff [2019/02/28 10:33:22.390449, 4, pid=18451, effective(0, 0), real(0, 0)] ../../source3/rpc_server/srv_access_check.c:95(access_check_object) _lsa_OpenPolicy2: ACCESS should be DENIED (requested: 0x000f1fff) but overritten by euid == initial uid [2019/02/28 10:33:22.390481, 4, pid=18451, effective(0, 0), real(0, 0)] ../../source3/rpc_server/srv_access_check.c:117(access_check_object) _lsa_OpenPolicy2: access GRANTED (requested: 0x000f1fff, granted: 0x000f1fff) [2019/02/28 10:33:22.390508, 6, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:304(create_rpc_handle_internal) Opened policy hnd[3] [0000] 00 00 00 00 23 00 00 00 00 00 00 00 77 5C 42 FF ....#... ....w\B. [0010] 13 48 00 00 .H.. [2019/02/28 10:33:22.390558, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) lsa_OpenPolicy: struct lsa_OpenPolicy out: struct lsa_OpenPolicy handle : * handle: struct policy_handle handle_type : 0x00000000 (0) uuid : 00000023-0000-0000-775c-42ff13480000 result : NT_STATUS_OK [2019/02/28 10:33:22.390650, 3, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_rpc.c:280(rpc_name_to_sid) name_to_sid: FOO for domain [2019/02/28 10:33:22.390700, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) lsa_LookupNames: struct lsa_LookupNames in: struct lsa_LookupNames handle : * handle: struct policy_handle handle_type : 0x00000000 (0) uuid : 00000023-0000-0000-775c-42ff13480000 num_names : 0x00000001 (1) names: ARRAY(1) names: struct lsa_String length : 0x0006 (6) size : 0x0006 (6) string : * string : 'FOO' sids : * sids: struct lsa_TransSidArray count : 0x00000000 (0) sids : NULL level : LSA_LOOKUP_NAMES_ALL (1) count : * count : 0x00000000 (0) [2019/02/28 10:33:22.390878, 6, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_handles.c:339(find_policy_by_hnd_internal) Found policy hnd[0] [0000] 00 00 00 00 23 00 00 00 00 00 00 00 77 5C 42 FF ....#... ....w\B. [0010] 13 48 00 00 .H.. [2019/02/28 10:33:22.390929, 5, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/lsa/srv_lsa_nt.c:163(lookup_lsa_rids) lookup_lsa_rids: looking up name FOO [2019/02/28 10:33:22.390955, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/passdb/lookup_sid.c:113(lookup_name) lookup_name: FOO => domain=[], name=[FOO] [2019/02/28 10:33:22.390980, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/passdb/lookup_sid.c:114(lookup_name) lookup_name: flags = 0x073 [2019/02/28 10:33:22.391007, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/util_wellknown.c:165(lookup_wellknown_name) map_name_to_wellknown_sid: looking up \FOO [2019/02/28 10:33:22.391059, 5, pid=18451, effective(0, 0), real(0, 0), class=passdb] ../../source3/passdb/pdb_tdb.c:600(tdbsam_getsampwnam) pdb_getsampwnam (TDB): error fetching database. Key: USER_foo [2019/02/28 10:33:22.391109, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/groupdb/mapping_tdb.c:279(find_map) failed to unpack map [2019/02/28 10:33:22.391208, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/groupdb/mapping_tdb.c:279(find_map) failed to unpack map [2019/02/28 10:33:22.391249, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:181(Get_Pwnam_alloc) Finding user FOO [2019/02/28 10:33:22.391276, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:120(Get_Pwnam_internals) Trying _Get_Pwnam(), username as lowercase is foo [2019/02/28 10:33:32.388219, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:128(Get_Pwnam_internals) Trying _Get_Pwnam(), username as given is FOO [2019/02/28 10:33:42.388344, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:153(Get_Pwnam_internals) Checking combinations of 0 uppercase letters in foo [2019/02/28 10:33:42.388397, 5, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/username.c:159(Get_Pwnam_internals) Get_Pwnam_internals didn't find user [FOO]! [2019/02/28 10:33:52.388680, 5, pid=18451, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/lsa/srv_lsa_nt.c:181(lookup_lsa_rids) init_lsa_rids: FOO not found [2019/02/28 10:33:52.388736, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) lsa_LookupNames: struct lsa_LookupNames out: struct lsa_LookupNames domains : * domains : * domains: struct lsa_RefDomainList count : 0x00000000 (0) domains : NULL max_size : 0x00000000 (0) sids : * sids: struct lsa_TransSidArray count : 0x00000001 (1) sids : * sids: ARRAY(1) sids: struct lsa_TranslatedSid sid_type : SID_NAME_UNKNOWN (8) rid : 0x00000000 (0) sid_index : 0xffffffff (4294967295) count : * count : 0x00000000 (0) result : NT_STATUS_NONE_MAPPED [2019/02/28 10:33:52.389015, 2, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_rpc.c:299(rpc_name_to_sid) name_to_sid: failed to lookup name: NT_STATUS_NONE_MAPPED [2019/02/28 10:33:52.389084, 10, pid=18451, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:226(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NAME2SID/\FOO] and timeout=[Thu Feb 28 10:38:52 AM 2019 EST] (300 seconds ahead) [2019/02/28 10:33:52.389286, 1, pid=18451, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName out: struct wbint_LookupName type : * type : SID_NAME_USE_NONE (0) sid : * sid : S-0-0 result : NT_STATUS_NONE_MAPPED [2019/02/28 10:33:52.389388, 4, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:1605(child_handler) Finished processing child request 56 [2019/02/28 10:33:52.389419, 10, pid=18451, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:154(child_write_response) Writing 4024 bytes to parent [2019/02/28 10:33:52.530329, 10, pid=18451, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:429(messaging_recv_cb) messaging_recv_cb: Received message 0x1 len 2 (num_fds:0) from 18439 [2019/02/28 10:33:52.530374, 3, pid=18451, effective(0, 0), real(0, 0)] ../../lib/util/debug_s3.c:75(debug_message) INFO: Remote set of debug to `3' (pid 18451 from pid 18439) -------------- next part -------------- [2019/02/28 10:32:52.904941, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:920(new_connection) accepted socket 23 [2019/02/28 10:32:52.905640, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:768(process_request_send) process_request_send: process_request: request fn INTERFACE_VERSION [2019/02/28 10:32:52.905684, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_misc.c:432(winbindd_interface_version) winbindd_interface_version: [wbinfo (18469)]: request interface version (version = 31) [2019/02/28 10:32:52.905747, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:854(process_request_written) process_request_written: [wbinfo(18469):unknown request]: delivered response to client [2019/02/28 10:32:52.905868, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:744(process_request_send) process_request_send: process_request: Handling async request wbinfo(18469):GETPWNAM [2019/02/28 10:32:52.905914, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getpwnam.c:62(winbindd_getpwnam_send) winbindd_getpwnam_send: [wbinfo (18469)] getpwnam foo [2019/02/28 10:32:52.905998, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : '' name : * name : 'FOO' flags : 0x00000008 (8) [2019/02/28 10:32:52.913086, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:744(process_request_send) process_request_send: process_request: Handling async request nss_winbind(18441):GETPWNAM [2019/02/28 10:32:52.913154, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getpwnam.c:62(winbindd_getpwnam_send) winbindd_getpwnam_send: [nss_winbind (18441)] getpwnam foo [2019/02/28 10:32:52.913202, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : '' name : * name : 'FOO' flags : 0x00000008 (8) [2019/02/28 10:32:56.713165, 5, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1207(remove_timed_out_clients) Idle client timed out, shutting down sock 28, pid 18447 [2019/02/28 10:33:02.388061, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1019(winbind_client_activity) winbind_client_activity[18441:GETPWNAM]: client has closed connection - removing client [2019/02/28 10:33:02.388113, 2, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1129(remove_client) final write to client failed: Broken pipe [2019/02/28 10:33:02.392782, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:920(new_connection) accepted socket 25 [2019/02/28 10:33:02.392864, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:768(process_request_send) process_request_send: process_request: request fn INTERFACE_VERSION [2019/02/28 10:33:02.392895, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_misc.c:432(winbindd_interface_version) winbindd_interface_version: [nss_winbind (18441)]: request interface version (version = 31) [2019/02/28 10:33:02.392952, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:854(process_request_written) process_request_written: [nss_winbind(18441):unknown request]: delivered response to client [2019/02/28 10:33:02.393043, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:744(process_request_send) process_request_send: process_request: Handling async request nss_winbind(18441):GETPWNAM [2019/02/28 10:33:02.393076, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getpwnam.c:62(winbindd_getpwnam_send) winbindd_getpwnam_send: [nss_winbind (18441)] getpwnam FOO [2019/02/28 10:33:02.393145, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : '' name : * name : 'FOO' flags : 0x00000008 (8) [2019/02/28 10:33:12.388061, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1019(winbind_client_activity) winbind_client_activity[18441:GETPWNAM]: client has closed connection - removing client [2019/02/28 10:33:12.388113, 2, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1129(remove_client) final write to client failed: Broken pipe [2019/02/28 10:33:12.391289, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:920(new_connection) accepted socket 25 [2019/02/28 10:33:12.391372, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:768(process_request_send) process_request_send: process_request: request fn INTERFACE_VERSION [2019/02/28 10:33:12.391402, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_misc.c:432(winbindd_interface_version) winbindd_interface_version: [nss_winbind (18441)]: request interface version (version = 31) [2019/02/28 10:33:12.391460, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:854(process_request_written) process_request_written: [nss_winbind(18441):unknown request]: delivered response to client [2019/02/28 10:33:12.391551, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:744(process_request_send) process_request_send: process_request: Handling async request nss_winbind(18441):GETGRNAM [2019/02/28 10:33:12.391591, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getgrnam.c:61(winbindd_getgrnam_send) winbindd_getgrnam_send: [nss_winbind (18441)] getgrnam FOO [2019/02/28 10:33:12.391674, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : 'CENTOS7DEV64' name : * name : 'FOO' flags : 0x00000000 (0) [2019/02/28 10:33:22.388108, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1019(winbind_client_activity) winbind_client_activity[18441:GETGRNAM]: client has closed connection - removing client [2019/02/28 10:33:22.388182, 2, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1129(remove_client) final write to client failed: Broken pipe [2019/02/28 10:33:22.394660, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:920(new_connection) accepted socket 25 [2019/02/28 10:33:22.394748, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:768(process_request_send) process_request_send: process_request: request fn INTERFACE_VERSION [2019/02/28 10:33:22.394780, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_misc.c:432(winbindd_interface_version) winbindd_interface_version: [nss_winbind (18441)]: request interface version (version = 31) [2019/02/28 10:33:22.394837, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:854(process_request_written) process_request_written: [nss_winbind(18441):unknown request]: delivered response to client [2019/02/28 10:33:22.394926, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:744(process_request_send) process_request_send: process_request: Handling async request nss_winbind(18441):GETPWNAM [2019/02/28 10:33:22.394960, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getpwnam.c:62(winbindd_getpwnam_send) winbindd_getpwnam_send: [nss_winbind (18441)] getpwnam foo [2019/02/28 10:33:22.395003, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : '' name : * name : 'FOO' flags : 0x00000008 (8) [2019/02/28 10:33:32.388049, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1019(winbind_client_activity) winbind_client_activity[18441:GETPWNAM]: client has closed connection - removing client [2019/02/28 10:33:32.388101, 2, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1129(remove_client) final write to client failed: Broken pipe [2019/02/28 10:33:32.391614, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:920(new_connection) accepted socket 25 [2019/02/28 10:33:32.391708, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:768(process_request_send) process_request_send: process_request: request fn INTERFACE_VERSION [2019/02/28 10:33:32.391739, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_misc.c:432(winbindd_interface_version) winbindd_interface_version: [nss_winbind (18441)]: request interface version (version = 31) [2019/02/28 10:33:32.391796, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:854(process_request_written) process_request_written: [nss_winbind(18441):unknown request]: delivered response to client [2019/02/28 10:33:32.391892, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:744(process_request_send) process_request_send: process_request: Handling async request nss_winbind(18441):GETPWNAM [2019/02/28 10:33:32.391926, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getpwnam.c:62(winbindd_getpwnam_send) winbindd_getpwnam_send: [nss_winbind (18441)] getpwnam FOO [2019/02/28 10:33:32.391975, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : '' name : * name : 'FOO' flags : 0x00000008 (8) [2019/02/28 10:33:42.388160, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1019(winbind_client_activity) winbind_client_activity[18441:GETPWNAM]: client has closed connection - removing client [2019/02/28 10:33:42.388221, 2, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1129(remove_client) final write to client failed: Broken pipe [2019/02/28 10:33:42.391716, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:920(new_connection) accepted socket 25 [2019/02/28 10:33:42.391806, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:768(process_request_send) process_request_send: process_request: request fn INTERFACE_VERSION [2019/02/28 10:33:42.391841, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_misc.c:432(winbindd_interface_version) winbindd_interface_version: [nss_winbind (18441)]: request interface version (version = 31) [2019/02/28 10:33:42.391905, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:854(process_request_written) process_request_written: [nss_winbind(18441):unknown request]: delivered response to client [2019/02/28 10:33:42.392027, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:744(process_request_send) process_request_send: process_request: Handling async request nss_winbind(18441):GETGRNAM [2019/02/28 10:33:42.392066, 3, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getgrnam.c:61(winbindd_getgrnam_send) winbindd_getgrnam_send: [nss_winbind (18441)] getgrnam FOO [2019/02/28 10:33:42.392153, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : 'CENTOS7DEV64' name : * name : 'FOO' flags : 0x00000000 (0) [2019/02/28 10:33:52.388527, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1019(winbind_client_activity) winbind_client_activity[18441:GETGRNAM]: client has closed connection - removing client [2019/02/28 10:33:52.388586, 2, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1129(remove_client) final write to client failed: Broken pipe [2019/02/28 10:33:52.389539, 1, pid=18439, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:471(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName out: struct wbint_LookupName type : * type : SID_NAME_USE_NONE (0) sid : * sid : S-0-0 result : NT_STATUS_NONE_MAPPED [2019/02/28 10:33:52.389729, 5, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_getpwnam.c:143(winbindd_getpwnam_recv) Could not convert sid S-0-0: NT_STATUS_NONE_MAPPED [2019/02/28 10:33:52.389767, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:810(process_request_done) process_request_done: [wbinfo(18469):GETPWNAM]: NT_STATUS_NONE_MAPPED [2019/02/28 10:33:52.389836, 10, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:854(process_request_written) process_request_written: [wbinfo(18469):GETPWNAM]: delivered response to client [2019/02/28 10:33:52.392437, 6, pid=18439, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:969(winbind_client_request_read) closing socket 23, client exited [2019/02/28 10:33:52.529029, 10, pid=18439, effective(0, 0), real(0, 0)] ../../source4/lib/messaging/messaging.c:684(imessaging_dgm_recv) imessaging_dgm_recv: dst 18439 matches my id: 18439, type=0x1 [2019/02/28 10:33:52.529091, 0, pid=18439, effective(0, 0), real(0, 0)] ../../source4/lib/messaging/messaging.c:150(debug_imessage) debug_imessage: INFO: Remote set of debug to `3' (pid 18439 from pid 18474) [2019/02/28 10:33:52.529188, 3] ../../lib/util/debug_s3.c:75(debug_message) INFO: Remote set of debug to `3' (pid 18439 from pid 18474)
On Thu, Feb 28, 2019 at 05:08:50PM +0100, Alexander Spannagel wrote:>Beside log.winbindd i also added log.wb-CENTOS7DEV64 as it may be of >interest too. So let me know if there is something i can test once >more.thnks. We also need log.winbindd-idmap. You may want to file a bug and attach the logs there, so they don't get lost until someone feels like looking into them. -slow -- Ralph Boehme, Samba Team https://samba.org/ Samba Developer, SerNet GmbH https://sernet.de/en/samba/ GPG-Fingerprint FAE2C6088A24252051C559E4AA1E9B7126399E46
Alexander Spannagel
2019-Feb-28 17:54 UTC
[Samba] winbind causing huge timeouts/delays since 4.8
Am 28.02.19 um 17:25 schrieb Ralph Böhme:> On Thu, Feb 28, 2019 at 05:08:50PM +0100, Alexander Spannagel wrote: >> Beside log.winbindd i also added log.wb-CENTOS7DEV64 as it may be of >> interest too. So let me know if there is something i can test once more. > > thnks. We also need log.winbindd-idmap. > > You may want to file a bug and attach the logs there, so they don't get > lost until someone feels like looking into them. > > -slow >Now that i can, created bug-report #13815 and attached the logs and patches. Saw errors within log.winbindd-idmap that are caused by doing quick re-config from autorid to multiple rid setup. Getting back to autorid doesn't show any error on startup and during porcessing nothing changes at all. Alex