[Samba] winbind causing huge timeouts/delays since 4.8
Alexander Spannagel
aspannagel at gmx.de
Thu Feb 28 16:08:50 UTC 2019
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)
More information about the samba
mailing list