Alexander Spannagel
2019-Feb-26 10:19 UTC
[Samba] winbind causing huge timeouts/delays since 4.8
Am 23.02.19 um 22:23 schrieb Rowland Penny via samba:> On Sat, 23 Feb 2019 21:54:31 +0100 > Alexander Spannagel via samba <samba at lists.samba.org> wrote: > >> Am 23.02.19 um 15:48 schrieb Rowland Penny via samba: >>>>>>>>> If you have, as you have, 'files sss winbind' in the the >>>>>>>>> passwd & group line in nsswitch.conf, means this: >>>>>>>>> First /etc/passwd or /etc/group is searched and if the user or >>>>>>>>> group is found, this info is returned. >>>>>>>>> Next sssd will be asked, 'do you know this user or group ?' if >>>>>>>>> found, the info is returned. >>>>>>>>> Finally winbind will be asked, 'do you know this user or >>>>>>>>> group ?' if found, the info is returned. >>>>>>>>> >>>>>>>>> Lets take a user called 'fred', this user is in AD. The first >>>>>>>>> search will return nothing, so sssd is asked, this 'asks' AD >>>>>>>>> and returns the users info. Finally, wait that's it, we have >>>>>>>>> the info, there is no need to ask winbind for anything. >>>>>>>>who does what. >>>>>>>> That is incorrect. Alexander stated: >>>>>>>> >>>>>>>>> No. we use max. 3 auth providers: (1. and 2. on all unix >>>>>>>>> servers) 1. unix (local passwd) >>>>>>>>> for static OS/service accounts across all our env >>>>>>>>> 2. sssd (with unix ldap servers as provider) >>>>>>>>> unix experienced user and application related service accounts >>>>>>>>> 3. samba/winbind >>>>>>>>> for windows users/services needing access to a group of unix >>>>>>>>> servers >>>>>>>> >>>>>>>> And: >>>>>>>> >>>>>>>>> They don't - as stated above we use sssd for query/caching >>>>>>>>> entries from our ldap directory server and not Windows >>>>>>>>> DomainConmtrollers >>>>>>>>> - also this is possible, but makes more trouble and don't >>>>>>>>> provide what samba's smb/windbind does. >>>>>>>> >>>>>>>> He clearly writes (in multiple emails) that sssd is configured >>>>>>>> to use his unix ldap servers and not AD. >>>>>>>> >>>>>>>> Maybe three sources of user databases is not regular, but I >>>>>>>> fail to see why this should be a problem (provided that >>>>>>>> usernames, uidNumbers and such are unique across the >>>>>>>> databases). >>>>>>> >>>>>>> And there is the problem, if 'fred' is in /etc/passwd, that user >>>>>>> will be used, but what if you meant fred in ldap or AD ? >>>>>>> >> We are aware of this possible clash and it's handled during users >> account creation. > > If you only used one database, you would be 100% sure you wouldn't get > any clashes. >Agreed, but not feasible in our company as there are - for good reasons - two big server farms spreading across multiple countries. One is based on Linux and the other on Windows. The glue between those two farms is build upon samba due to it's flexibility, strength and reliability.>> >>>>>>> There is absolutely no point in having 4 databases (yes there >>>>>>> are 4, Unix, sssd, winbind and the ldap lines in smb.conf), they >>>>>>> could all be combined in AD. >> No it won't work as our windows team doesn't accept schema changes >> for unix in AD. > > How shall I put this, your windows team is either not telling you the > entire truth or is stupid. The entire RFC2307 attributes are part of > the standard Windows schema. what isn't added is IDMU and this just > makes the Unix attributes tab work in ADUC. You can however use other > tools to create Unix users etc. >Beside what i mentioned earlier you are rigth that the RFC2307 attributes are still around, but reading a blog entry from 2016 in technet it's cleraly stated that one should look on other alternatives as it may go in future realease. Here the comment: "I am using Windows Server IDMU/NIS Server role today, what should I do? We recommend to start planning for alternatives, for example: native LDAP, Samba Client, Kerberos or other non-Microsoft options. Existing Windows Server 2012 R2 or earlier deployments will continue to be supported in accordance with the Microsoft Support lifecycle." Taken out of this blog entry: https://blogs.technet.microsoft.com/activedirectoryua/2016/02/09/identity-management-for-unix-idmu-is-deprecated-in-windows-server/>> >>>>>>> >>>>>>> The main problem is that the OP wants Samba changing to cope >>>>>>> with his mess, it might be a valid change, but the reason for >>>>>>> the change is invalid. >> The intial reason we hitted this after upgrade from samba-4.7 to 4.8 >> is a script that frequentyl checks the system for changes and a final >> "chown root.wheel FILE" freezes the system for approx a minute >> (simliar to "wbinfo -i foo"). The winbind and also sssd log showd >> that both were asked about a user "root.wheel" which is another >> question, why the notation which usually (under linux) indicates >> user.group and not an account with a dot in it's name - but more to >> glibc related. Removing winbind from nss fixed the freeze, but isn't >> an option. It leads to the point that asking winbind for an uknown >> user without domain took a long time before it returns >> WBC_ERR_DOMAIN_NOT_FOUND . > > You see, there you have 2 methods checking for the same thing, also the > problem you are referring to has been fixed in the latest Samba (I > think it has also been backported). > >> >>>>>> >>>>>> Well, I think the problem is you _assume_ users are in multiple >>>>>> databases and we just don't know that. I think there is a good >>>>>> change Alexander perfectly knows what he is doing and users are >>>>>> unique across databases. >>>>>> >>>>>> Nevertheless, at some point nss is clearly querying winbind, >>>>>> which means nss did not find the user in either /etc/passwd nor >>>>>> via sssd. In the case that winbind _is_ queried, Alexander is >>>>>> experiencing, like he wrote, 'frequently system hangs/slowness >>>>>> for a couple of seconds' and he observed that winbind is causing >>>>>> this behaviour. >>>>>> >>>>>> So maybe we should set our focus on winbind instead of the >>>>>> multiple database stuff and figure out why it behaves like this >>>>>> since the upgrade from 4.7 to 4.8. I would say we should start >>>>>> with fixing the winbind stuff in smb.conf. Right? >>>>>> >>>>>> -Remy >>>>>> >>>>>> >>>>>> P.S. I am following this thread since I also noticed occasional >>>>>> 'hangs' when the system is querying winbind. This is Samba 4.8.7 >>>>>> on FreeBSD 11.2.As the function - that i suggested patches for - hasn't changed sinceintroduced patch for Bug 13503 "getpwnam resolves local system accounts to AD accounts" with 4.8.4 it may be the same problem. As mentioned earlier removing patch for Bug 13503 also resolves seen problems.>>>>> >>>>> I am quite prepared to help in getting winbind working correctly, >>>>> but this will require the OP changing their smb.conf considerably >>>>> and removing sssd. We do not support sssd, it is not a Samba >>>>> product (for want of a better name). Samba on a Unix domain member >>>>> is designed around 3 binaries, smbd, nmbd and winbind, the latter >>>>> can do just about anything sssd can do, so why use sssd ? Now you >>>>> say that I am making assumptions, well about this one, probably >>>>> somewhere in the mix there will be Windows domain members and the >>>>> users in ldap are unlikely to be known to them. >>>> >>>> I consider sssd as 'just another' user database, like /etc/passwd >>>> (which Samba apparently does support) and I personally cannot see >>>> any difference there, but I respect your opinion. >>>> >>>> Where is it documented winbind should be the only service which >>>> should be used with nss? If it is not documented, maybe it should. >>> >>> I am not saying that sssd shouldn't be used, just Samba does not >>> support it. If you want to use sssd, then do so, just don't expect >>> to get help with using it, we don't produce it, so don't know it. >>> What I will say is this, there is no need to use both on a Unix >>> domain member, they both do the same thing. >>> >> I'm with you and don't expect that you support sssd. >> On the otherside windind shouln't require to be the only one in >> nss-setup as i didn't ever heard, that only a certain amount can be >> taken into the stack. Before nss_sss we used nss_ldap alongside with >> nss_winbind without issues. > > There is no real problem with using multiple methods in nsswitch.conf, > there is just no real point, the first one to produce a result wins > and as sssd & winbind do the same thing, you don't need both. >They don't and shouldn't provide same thing in our setup. The main jobs in the unix farm can and should be processed while the windows farm may in trouble and vice versa. 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.>>>>> He also has these: >>>>> >>>>> idmap config * : rangesize = 1000000 >>>>> idmap config * : range = 1000000-19999999 >>>>> idmap config * : backend = autorid >>>>> >>>>> The '*' domain is meant for the Well Known SIDs and anything >>>>> outside the Samba domain. I would have expected something like >>>>> this: >>>>> >>>>> idmap config * : backend = tdb >>>>> idmap config * : range = 3000-7999 >>>>> idmap config OPS : backend = rid >>>>> idmap config OPS : range = 10000-999999 >>>> >>>> That should also be fixed. >>>> >>>> >> We use this as we have a multi-domain setup on windows side and this >> is a suggested setup from wiki.samba.org: >> https://wiki.samba.org/index.php/Idmap_config_autorid > > Cannot argue with that fact, it is there, but it also says it is meant > to be used with the 'DOMAIN' domain not the '*' domain, looks like I > will have to make that more prominent. > >> >> I'll try to somehow reconfig idmap as you suggested taking care of >> all the trees in our forest and will report back if that changes the >> situation. >>I reconfigured idmap config auccesfuly like this: idmap config * : range = 3000-7999 idmap config * : backend = tdb idmap config ops : range = 1000000-1999999 idmap config ops : backend = rid idmap config ops2 : range = 2000000-2999999 idmap config ops2 : backend = rid ... But it didn't change the problem with the delayed response or timeout of winbind calling "wbinfo -i foo". One good point about the suggestion - It point to a fix of a "problem" seen with autorid: The used ID ranges from the pool used for different domains seem to vary for servers being member of one of the other domains. Changing from autorid to rid looks like the way to fix that as we can configure dedicated ranges from the pool per domain and so uid/gid resloution will become consitant across all of our domains. :) I did some more tested about nsswitch.conf: 1. removing sss -> no more hangs (independand of shadow configured with winbind or not) passwd: files winbind shadow: files # winbind group: files winbind 2. removing winbind -> no more hangs passwd: files sss shadow: files sss group: files sss 3. exchange winbind/sss - no change, still delays passwd: files winbind sss shadow: files sss group: files winbind sss It still looks that either sssd or winbindd (or both) relays/calls each other, when no domain is given. I will try to get debug logging correlated to see if and if yes which service calls the other. Alex
Rowland Penny
2019-Feb-26 10:45 UTC
[Samba] winbind causing huge timeouts/delays since 4.8
On Tue, 26 Feb 2019 11:19:45 +0100 Alexander Spannagel via samba <samba at lists.samba.org> wrote:> > If you only used one database, you would be 100% sure you wouldn't > > get any clashes. > > > Agreed, but not feasible in our company as there are - for good > reasons > - two big server farms spreading across multiple countries. One is > based on Linux and the other on Windows. The glue between those two > farms is build upon samba due to it's flexibility, strength and > reliability.Fair enough, I still think you could use one database eventually, but it is your network and I am sure you don't to do anything that risks it.> > >> > >>>>>>> There is absolutely no point in having 4 databases (yes there > >>>>>>> are 4, Unix, sssd, winbind and the ldap lines in smb.conf), > >>>>>>> they could all be combined in AD. > >> No it won't work as our windows team doesn't accept schema changes > >> for unix in AD. > > > > How shall I put this, your windows team is either not telling you > > the entire truth or is stupid. The entire RFC2307 attributes are > > part of the standard Windows schema. what isn't added is IDMU and > > this just makes the Unix attributes tab work in ADUC. You can > > however use other tools to create Unix users etc. > > > Beside what i mentioned earlier you are rigth that the RFC2307 > attributes are still around, but reading a blog entry from 2016 in > technet it's cleraly stated that one should look on other > alternatives as it may go in future realease. Here the comment: > "I am using Windows Server IDMU/NIS Server role today, what should I > do? We recommend to start planning for alternatives, for example: > native LDAP, Samba Client, Kerberos or other non-Microsoft options. > Existing Windows Server 2012 R2 or earlier deployments will continue > to be supported in accordance with the Microsoft Support lifecycle." > Taken out of this blog entry: > https://blogs.technet.microsoft.com/activedirectoryua/2016/02/09/identity-management-for-unix-idmu-is-deprecated-in-windows-server/All that has been removed is the IDMU scaffold, all the attributes are still there and I do not think there is any plans to remove them, mainly because they would be so easy to put back. My guess is that Microsoft will just pretend they are not there.> introduced patch for Bug 13503 "getpwnam resolves local system > accounts to AD accounts" with 4.8.4 it may be the same problem. As > mentioned earlier removing patch for Bug 13503 also resolves seen > problems.If this fixes your problem, then great ;-)> > There is no real problem with using multiple methods in > > nsswitch.conf, there is just no real point, the first one to > > produce a result wins and as sssd & winbind do the same thing, you > > don't need both. > > > They don't and shouldn't provide same thing in our setup. The main > jobs in the unix farm can and should be processed while the windows > farm may in trouble and vice versa. > 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.If you have multiple domains, then you should not use 'winbind use default domain = yes', you need to configure smb.conf to use these domains.> >> I'll try to somehow reconfig idmap as you suggested taking care of > >> all the trees in our forest and will report back if that changes > >> the situation. > >> > I reconfigured idmap config auccesfuly like this: > idmap config * : range = 3000-7999 > idmap config * : backend = tdb > idmap config ops : range = 1000000-1999999 > idmap config ops : backend = rid > idmap config ops2 : range = 2000000-2999999 > idmap config ops2 : backend = rid > ... > > But it didn't change the problem with the delayed response or timeout > of winbind calling "wbinfo -i foo".At least this proves there is a problem and not a miss-configuration> > One good point about the suggestion - It point to a fix of a > "problem" seen with autorid: > The used ID ranges from the pool used for different domains seem to > vary for servers being member of one of the other domains. Changing > from autorid to rid looks like the way to fix that as we can > configure dedicated ranges from the pool per domain and so uid/gid > resloution will become consitant across all of our domains. :)This is what I was trying to say, you need different ranges for each domain. It doesn't matter what winbind backend you use, you must use a different range for each domain, it is for this reason that I personally do not see the point to autorid, it doesn't seem to give you much more than what rid does and neither gives you access to the RFC2307 attributes.> > I did some more tested about nsswitch.conf: > 1. removing sss -> no more hangs (independand of shadow configured > with winbind or not) > passwd: files winbind > shadow: files # winbind > group: files winbind > 2. removing winbind -> no more hangs > passwd: files sss > shadow: files sss > group: files sss > 3. exchange winbind/sss - no change, still delays > passwd: files winbind sss > shadow: files sss > group: files winbind sss > > It still looks that either sssd or winbindd (or both) relays/calls > each other, when no domain is given. I will try to get debug logging > correlated to see if and if yes which service calls the other.They are written by different teams and, in theory, have nothing to do with each other. sssd does use some of the winbind libary code, so whether this is causing a possible link, I do not know. Rowland
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 -- Ralph Boehme, Samba Team https://samba.org/ Samba Developer, SerNet GmbH https://sernet.de/en/samba/ GPG-Fingerprint FAE2C6088A24252051C559E4AA1E9B7126399E46
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)