search

lizardfs / lizardfs

LizardFS is an Open Source Distributed File System licensed under GPLv3.
http://lizardfs.com
GNU General Public License v3.0
955 stars 187 forks source link

3.13.0-rc1 + Samba 4.5 #821

Open nickcoons opened 5 years ago

nickcoons commented 5 years ago

I have a cluster with LFS 3.9.4 serving files to clients with Samba 4.3, and it's working very well.

I've built a new cluster to test with LFS 3.13.0-rc1 and Samba 4.5. It kind of works, but I've run into a strange issue. Specifically, I have an LFS mount point at /netfs/lfs/files, which is owned by user and a member of the group group (not really the names). I also have user2 which is a member of group. The /netfs/lfs/files directory's permissions are set to 770. It's shared out in Samba as files.

When I access it with smbclient (or mount it with mount.cifs, same issue occurs) as follows:

smbclient //localhost/files -U user

Everything works normally.

Then I try it with this user:

smbclient //localhost/files -U user2

And upon doing a directory listing, I receive NT_STATUS_ACCESS_DENIED listing \*. And if I do a directory listing anytime in the ~12 seconds within connecting, I get the same thing. After that, it starts working normally, then as far as I can tell keeps working normally until I exit. If I reconnect/remount, it does it again (gives me access denied errors for ~12 seconds, then works fine after that). Note, it works normally (without giving any errors) if I log in using the user that owns the folder being shared out. It's only when I use a user belonging to the group (but not the owner) that this occurs. If I set the permissions to 777, then it works from the start as well.

I wasn't sure if this was an issue with LFS, Samba, or something else. So I setup Samba to create a share outside of LFS on the local system, and it doesn't behave this way (it works fine).

I then tried mounting /netfs/lfs/files with the debug option. Then when I connect with smbclient, when I do my initial directory listings, I get this:

unique: 5, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 19680
   unique: 5, success, outsize: 120
unique: 6, opcode: LOOKUP (1), nodeid: 1, insize: 48, pid: 19680
   unique: 6, success, outsize: 144
unique: 7, opcode: LOOKUP (1), nodeid: 1057584, insize: 42, pid: 19680
   unique: 7, error: -13 (Permission denied), outsize: 16

If I keep doing dir repeatedly, I'll keep getting the same thing for ~12 seconds, then it starts working normally and I get this instead (note the "Permission denied" message is gone, and it gives me the directory listing):

unique: 11, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 19680
   unique: 11, success, outsize: 120
unique: 12, opcode: LOOKUP (1), nodeid: 1, insize: 48, pid: 19680
   unique: 12, success, outsize: 144
unique: 13, opcode: LOOKUP (1), nodeid: 1057584, insize: 42, pid: 19680
   unique: 13, error: -2 (No such file or directory), outsize: 16
unique: 14, opcode: GETXATTR (22), nodeid: 1057584, insize: 72, pid: 19680
   unique: 14, error: -61 (No data available), outsize: 16
unique: 15, opcode: GETXATTR (22), nodeid: 1057584, insize: 73, pid: 19680
   unique: 15, error: -61 (No data available), outsize: 16
unique: 16, opcode: OPENDIR (27), nodeid: 1057584, insize: 48, pid: 19680
   unique: 16, success, outsize: 32
unique: 17, opcode: READDIR (28), nodeid: 1057584, insize: 80, pid: 19680
   unique: 17, success, outsize: 152
unique: 18, opcode: GETATTR (3), nodeid: 1057584, insize: 56, pid: 19680
   unique: 18, success, outsize: 120
unique: 19, opcode: LOOKUP (1), nodeid: 1057584, insize: 48, pid: 19680
   unique: 19, success, outsize: 144
unique: 20, opcode: LOOKUP (1), nodeid: 1057584, insize: 52, pid: 19680
   unique: 20, success, outsize: 144
unique: 21, opcode: READDIR (28), nodeid: 1057584, insize: 80, pid: 19680
   unique: 21, success, outsize: 16
unique: 22, opcode: RELEASEDIR (29), nodeid: 1057584, insize: 64, pid: 0
   unique: 22, success, outsize: 16
unique: 23, opcode: GETATTR (3), nodeid: 1057584, insize: 56, pid: 19680
   unique: 23, success, outsize: 120
unique: 24, opcode: STATFS (17), nodeid: 1057584, insize: 40, pid: 19680
   unique: 24, success, outsize: 96
unique: 25, opcode: LOOKUP (1), nodeid: 1057584, insize: 58, pid: 19680
   unique: 25, error: -2 (No such file or directory), outsize: 16
unique: 26, opcode: LOOKUP (1), nodeid: 1057584, insize: 58, pid: 19680
   unique: 26, error: -2 (No such file or directory), outsize: 16

It's almost as if LFS is taking it's time to decide that the user I'm connecting with has access, then "something happens" and it starts working. I'm not sure where to go from here.

If I log in through bash and su - bash2, then I don't have this issue. I don't have a setup that would allow me to use the old LFS with the new Samba, or vice-versa, so I can't provide data on that. But given the debug output of mfsmount, I'm inclined to think it's an issue there.

pbeza commented 5 years ago

  1. Do you mount /netfs/lfs/files with default mount options? I'm particularly interested whether you use -n/--nostdopts flag:

    -n
   omit default mount options (-o allow_other,default_permissions)

  2. Do you use any mfsexports.cfg option that impacts groups (e.g. ignoregid, maproot or mapall)?

BTW: similar problem was reported in #265.

nickcoons commented 5 years ago

Up to this point, I had only been mounting with mfsacl,mfsmaster=X.X.X.X (other than debug). I tried adding -n, and that seemed to make things worse. With that, I was unable to access the Samba share at all, even after ~12 seconds (tried for up to about 2 minutes). When I re-mounted again without -n, it "worked" as it had before.

My mfsexports.cfg file is default, so no options added there.

It does look similar to #265 but slightly different in that with that ticket, access was denied entirely, rather than during some sort of timeout period. Do you suggest any changes to mfsexports.cfg?

pbeza commented 5 years ago

I guess that you shouldn't make any changes in mfsexports.cfg to make it work. I suspect it may be a bug...

After fixing #780 I will try to verify whether it's a bug and I will try to fix it. I will keep you updated.

nickcoons commented 5 years ago

I appreciate the response, thank you! I'll keep an eye on this thread.

pbeza commented 5 years ago

@nickcoons Can you share your /etc/samba/smb.conf configuration (at least sections regarding /netfs/lfs/files and [global] section)?

I'm trying to reproduce your issue, but currently it works for me – no bug (click here to enlarge below GIF screen record).

Peek 2019-04-15 13-24

My /etc/samba/smb.conf stripped from comments ([global] section is default):

[global]
   workgroup = WORKGROUP
   server string = %h server (Samba, Ubuntu)
   log file = /var/log/samba/log.%m
   max log size = 1000
   logging = file
   panic action = /usr/share/samba/panic-action %d
   server role = standalone server
   obey pam restrictions = yes
   unix password sync = yes
   passwd program = /usr/bin/passwd %u
   passwd chat = *Enter\snew\s*\spassword:* %n\n *Retype\snew\s*\spassword:* %n\n *password\supdated\ssuccessfully* .
   pam password change = yes
   map to guest = bad user
   usershare allow guests = yes

[test]
   comment = Issue 821
   path = /mnt/lizardfs-test
   guest ok = no
   read only = no
nickcoons commented 5 years ago

I've changed some of the names (like the workgroup, shares, and groups) to prevent exposing private information. Otherwise, here's my /etc/samba/smb.conf global plus the share I'm testing with:

[global]
    kernel change notify = no

    workgroup     = WORKGROUP
    server string = %h server (Samba)
    security      = user
    dns proxy     = no

    interfaces           = 127.0.0.0/8 172.31.2.0/24
    bind interfaces only = yes

    log file     = /var/log/samba/log.%m
    log level    = 6
    max log size = 1000
    panic action = /usr/share/samba/panic-action %d

    server role            = standalone server
    passdb backend         = tdbsam
    obey pam restrictions  = no
    unix password sync     = yes
    passwd program         = /usr/bin/passwd %u
    passwd chat            = *Enter\snew\s*\spassword:* %n\n *Retype\snew\s*\spassword:* %n\n *password\supdated\ssuccessfully* .
    pam password change    = yes
    map to guest           = bad user
    usershare allow guests = no

    strict locking = no

# Activity logging
    vfs objects = full_audit

    full_audit:prefix = %u|%I|%m|%S
    full_audit:success = all
    full_audit:failure = none
    full_audit:facility = local7
    full_audit:priority = NOTICE

[testshare]
    comment           = Test Share
    browseable        = no
    path              = /netfs/lfs/file/testshare
    guest ok          = no
    writable          = yes
    force create mode = 0660
    directory mask    = 0770
    valid users       = @testgroup
    write list        = @testgroup
nickcoons commented 5 years ago

Below is how I reproduce the issue on my end:

# ls -al /netfs/lfs/file/
total 1
drwxrwxr-x 11 root root      1028 Apr  7 00:27 .
drwxr-xr-x  4 root root      4096 Feb 14 15:22 ..
drwxrws---  3 root testgroup    0 Apr  7 01:08 testshare

# groups testuser
testuser : testgroup

# ls -al /netfs/lfs/file/testuser
total 7
drwxrws---   3 root     testgroup    0 Apr  7 01:08 .
drwxrwxr-x  11 root     root      1028 Apr  7 00:27 ..
-rwxrwx---+  1 testuser testgroup 5588 Apr  7 00:54 keys.tar.gz
drwxrws---   2 root     testgroup    0 Apr  7 01:08 testdir

# smbclient //localhost/testshare -U testuser
Enter testuser's password: 
Domain=[WORKGROUP] OS=[Windows 6.1] Server=[Samba 4.5.16-Debian]
smb: \> dir
NT_STATUS_ACCESS_DENIED listing \*
smb: \> dir
NT_STATUS_ACCESS_DENIED listing \*
smb: \> dir
NT_STATUS_ACCESS_DENIED listing \*
smb: \> dir
NT_STATUS_ACCESS_DENIED listing \*
smb: \> dir
NT_STATUS_ACCESS_DENIED listing \*
smb: \> dir
  .                                   D        0  Sun Apr  7 01:08:16 2019
  ..                                  D        0  Sun Apr  7 00:27:13 2019
  testdir                             D        0  Sun Apr  7 01:08:16 2019
  keys.tar.gz                         A     5588  Sun Apr  7 00:54:54 2019

        4711938048 blocks of size 1024. 2478424768 blocks available
smb: \>
pbeza commented 5 years ago

I've copied your /etc/samba/smb.conf configuration and still I'm not able to reproduce your problem (I commented out only interfaces and bind interfaces only options + replaced path). ;-/

I've noticed that you have some ACL permissions set for /netfs/lfs/file/testuser/keys.tar.gz and SUID for all files and directories, but this shouldn't be a problem.

BTW: I reproduced your message NT_STATUS_ACCESS_DENIED listing \* in different use case: after killing mfsmount process type ls in smbclient //172.20.0.5/testshare -U test.

Maybe you can find more logs/hints in journalctl? Do you have any idea why mfsmount start may be delayed? (virtual machine, slow connection between client & master, firewall rules)

nickcoons commented 5 years ago

I'll check journalctl and see if I can find anything. The mfsmount isn't delayed, because I can access the mount point immediately before running smbclient. The LFS cluster are three physical servers, and the client is a VM running on one of those servers. The servers are all interconnected with 10Gbps ethernet, and there aren't any firewall rules between the servers and VMs.

I'm running 3.13.0-rc1, the deb packages downloaded from https://lizardfs.com/download/. Are you possibly running a newer version where changes may have resolved this issue?

pbeza commented 5 years ago

I'm running 3.13.0-rc1 on Ubuntu Disco Dingo (19.04) but I've also tested it on 3.12. Both work for me.

I'm currently not able to reproduce the problem, so can you please double check whether journalctl on client/master server and /var/log/samba/log.* on client have some warnings/error? You can also try to mount your share with -o mfssugidclearmode=X (X is one of the modes) – it's a blind guess, but give it a try.

A few random thoughts that may lead to solution of the problem:

Besides journalctl and Samba logs, you can temporarily disable SELinux/AppArmor and check their logs. Do you have AppArmor or SELinux installed (+ any additional profiles like apparmor-profiles or apparmor-profiles-extra packages)?

One more idea that you can try out – add ignoregid to mfsexports.cfg as suggested here.

ignoregid
    disable testing of group access at mfsmaster level (it’s still done at mfsmount
    level) - in this case “group” and “other” permissions are logically added;
    needed for supplementary groups to work (mfsmaster receives only user primary
    group information)
nickcoons commented 5 years ago

I'm running 3.13.0-rc1 on Ubuntu Disco Dingo (19.04) but I've also tested it on 3.12. Both work for me.

I'm running the same 3.13.0-rc1, but on Debian Stretch (9.8). I have another installation that's setup similarly with Samba on Ubuntu 14.04 and LFS 3.9.4 and it works just fine as well.

I'm currently not able to reproduce the problem, so can you please double check whether journalctl on client/master server and /var/log/samba/log.* on client have some warnings/error?

journalctl doesn't show me anything, but I do have a long entry in /var/log/samba/log.*. It appears when I connect and authenticate to the share, but nothing new gets added to it between the time that the share is inaccessible to when it becomes accessible. I'll post it at the bottom because it's long.

To my knowledge, I don't have AppArmor or SELinux set up, unless they're setup by default on a Debian Stretch installation. Looking at installed packages, I don't think so:

# dpkg -l | grep apparmor
ii  libapparmor1:amd64             2.11.0-3+deb9u2                amd64        changehat AppArmor library

# dpkg -l | grep selinux
ii  libselinux1:amd64              2.6-3+b3                       amd64        SELinux runtime shared libraries

My Samba version is a bit older, but it's the newest one in the Debian repos (I like using the official packages whenever I can). But since I have an instance of this set up with Samba 4.3 elsewhere, I don't think that would necessarily be the issue.

I thought this might also be a problem with FUSE, so I set up a share with SSHFS in place of LFS, but that one works immediately without any issues, so FUSE doesn't appear to be the culprit.

At your suggestion, I tried -o mfssugidclearmode=X for every possible value of X in the documentation, but it had no affect on this issue.

One more idea that you can try out – add ignoregid to mfsexports.cfg as suggested here.

I'll give this a try once I get a chance and let you know how it goes.

[2019/04/16 10:01:42.381377,  6] ../source3/param/loadparm.c:2223(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Sun Apr  7 16:06:24 2019

[2019/04/16 10:01:42.388043,  3] ../source3/smbd/oplock.c:1328(init_oplocks)
  init_oplocks: initializing messages.
[2019/04/16 10:01:42.388070,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 774 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388095,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 778 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388116,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 770 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388136,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 787 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388155,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 779 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388175,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 15 - private_data=(nil)
[2019/04/16 10:01:42.388195,  5] ../source3/lib/messages.c:371(messaging_register)
  Overriding messaging pointer for type 15 - private_data=(nil)
[2019/04/16 10:01:42.388214,  5] ../source3/lib/messages.c:403(messaging_deregister)
  Deregistering messaging pointer for type 16 - private_data=(nil)
[2019/04/16 10:01:42.388235,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 16 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388255,  5] ../source3/lib/messages.c:403(messaging_deregister)
  Deregistering messaging pointer for type 33 - private_data=0x56306fe9ecf0
[2019/04/16 10:01:42.388280,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 33 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388302,  5] ../source3/lib/messages.c:403(messaging_deregister)
  Deregistering messaging pointer for type 790 - private_data=(nil)
[2019/04/16 10:01:42.388322,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 790 - private_data=0x56306feaabe0
[2019/04/16 10:01:42.388343,  5] ../source3/lib/messages.c:403(messaging_deregister)
  Deregistering messaging pointer for type 791 - private_data=(nil)
[2019/04/16 10:01:42.388362,  5] ../source3/lib/messages.c:403(messaging_deregister)
  Deregistering messaging pointer for type 1 - private_data=(nil)
[2019/04/16 10:01:42.388382,  5] ../source3/lib/messages.c:356(messaging_register)
  Registering messaging pointer for type 1 - private_data=(nil)
[2019/04/16 10:01:42.388436,  6] ../source3/smbd/process.c:1956(process_smb)
  got message type 0x0 of len 0xbe
[2019/04/16 10:01:42.388467,  3] ../source3/smbd/process.c:1958(process_smb)
  Transaction 0 of length 194 (0 toread)
[2019/04/16 10:01:42.388488,  5] ../source3/lib/util.c:171(show_msg)
[2019/04/16 10:01:42.388500,  5] ../source3/lib/util.c:181(show_msg)
  size=190
  smb_com=0x72
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51267
  smb_tid=0
  smb_pid=65534
  smb_uid=0
  smb_mid=0
  smt_wct=0
  smb_bcc=155
[2019/04/16 10:01:42.388596,  3] ../source3/smbd/process.c:1538(switch_message)
  switch message SMBnegprot (pid 8320) conn 0x0
[2019/04/16 10:01:42.388629,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.388659,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.388684,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.388734,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2019/04/16 10:01:42.401182,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [PC NETWORK PROGRAM 1.0]
[2019/04/16 10:01:42.401235,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [MICROSOFT NETWORKS 1.03]
[2019/04/16 10:01:42.401260,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [MICROSOFT NETWORKS 3.0]
[2019/04/16 10:01:42.401279,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [LANMAN1.0]
[2019/04/16 10:01:42.401299,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [LM1.2X002]
[2019/04/16 10:01:42.401318,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [DOS LANMAN2.1]
[2019/04/16 10:01:42.401337,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [LANMAN2.1]
[2019/04/16 10:01:42.401356,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [Samba]
[2019/04/16 10:01:42.401375,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [NT LANMAN 1.0]
[2019/04/16 10:01:42.401394,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [NT LM 0.12]
[2019/04/16 10:01:42.401460,  6] ../source3/param/loadparm.c:2223(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Sun Apr  7 16:06:24 2019

[2019/04/16 10:01:42.401508,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 2 for /var/run/samba/serverid.tdb
[2019/04/16 10:01:42.401535,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 2 for /var/run/samba/serverid.tdb
[2019/04/16 10:01:42.401581,  6] ../source3/param/loadparm.c:2223(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Sun Apr  7 16:06:24 2019

[2019/04/16 10:01:42.401668,  5] ../source3/auth/auth.c:491(make_auth_context_subsystem)
  Making default auth method list for server role = 'standalone server', encrypt passwords = yes
[2019/04/16 10:01:42.401695,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend trustdomain
[2019/04/16 10:01:42.401720,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'trustdomain'
[2019/04/16 10:01:42.401739,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend ntdomain
[2019/04/16 10:01:42.401757,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'ntdomain'
[2019/04/16 10:01:42.401775,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend guest
[2019/04/16 10:01:42.401793,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'guest'
[2019/04/16 10:01:42.401810,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend sam
[2019/04/16 10:01:42.401828,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'sam'
[2019/04/16 10:01:42.401845,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend sam_ignoredomain
[2019/04/16 10:01:42.401863,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'sam_ignoredomain'
[2019/04/16 10:01:42.401881,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend winbind
[2019/04/16 10:01:42.401898,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'winbind'
[2019/04/16 10:01:42.401916,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend unix
[2019/04/16 10:01:42.401934,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'unix'
[2019/04/16 10:01:42.401951,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend wbc
[2019/04/16 10:01:42.401969,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'wbc'
[2019/04/16 10:01:42.401986,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match guest
[2019/04/16 10:01:42.402011,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method guest has a valid init
[2019/04/16 10:01:42.402030,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match sam
[2019/04/16 10:01:42.402049,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method sam has a valid init
[2019/04/16 10:01:42.412491,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'gssapi_spnego' registered
[2019/04/16 10:01:42.412532,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'gssapi_krb5' registered
[2019/04/16 10:01:42.412557,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'gssapi_krb5_sasl' registered
[2019/04/16 10:01:42.412578,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'spnego' registered
[2019/04/16 10:01:42.412598,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'schannel' registered
[2019/04/16 10:01:42.412618,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'naclrpc_as_system' registered
[2019/04/16 10:01:42.412638,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'sasl-EXTERNAL' registered
[2019/04/16 10:01:42.412657,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'ntlmssp' registered
[2019/04/16 10:01:42.412677,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'ntlmssp_resume_ccache' registered
[2019/04/16 10:01:42.412698,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'http_basic' registered
[2019/04/16 10:01:42.412718,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'http_ntlm' registered
[2019/04/16 10:01:42.412738,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'krb5' registered
[2019/04/16 10:01:42.412758,  3] ../auth/gensec/gensec_start.c:908(gensec_register)
  GENSEC backend 'fake_gssapi_krb5' registered
[2019/04/16 10:01:42.412808,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC mechanism spnego
[2019/04/16 10:01:42.412850,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC submechanism ntlmssp
[2019/04/16 10:01:42.412898,  3] ../source3/smbd/negprot.c:394(reply_nt1)
  using SPNEGO
[2019/04/16 10:01:42.412920,  3] ../source3/smbd/negprot.c:744(reply_negprot)
  Selected protocol NT LANMAN 1.0
[2019/04/16 10:01:42.412938,  5] ../source3/smbd/negprot.c:746(reply_negprot)
  negprot index=8
[2019/04/16 10:01:42.412957,  5] ../source3/lib/util.c:171(show_msg)
[2019/04/16 10:01:42.412968,  5] ../source3/lib/util.c:181(show_msg)
  size=159
  smb_com=0x72
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=136
  smb_flg2=51267
  smb_tid=0
  smb_pid=65534
  smb_uid=0
  smb_mid=0
  smt_wct=17
  smb_vwv[ 0]=    8 (0x8)
  smb_vwv[ 1]=12803 (0x3203)
  smb_vwv[ 2]=  256 (0x100)
  smb_vwv[ 3]= 1024 (0x400)
  smb_vwv[ 4]=   65 (0x41)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=  256 (0x100)
  smb_vwv[ 7]=32768 (0x8000)
  smb_vwv[ 8]=   32 (0x20)
  smb_vwv[ 9]=64768 (0xFD00)
  smb_vwv[10]=33011 (0x80F3)
  smb_vwv[11]=38016 (0x9480)
  smb_vwv[12]=45608 (0xB228)
  smb_vwv[13]=30224 (0x7610)
  smb_vwv[14]=54516 (0xD4F4)
  smb_vwv[15]=41985 (0xA401)
  smb_vwv[16]=    1 (0x1)
  smb_bcc=90
[2019/04/16 10:01:42.425091,  6] ../source3/smbd/process.c:1956(process_smb)
  got message type 0x0 of len 0x9c
[2019/04/16 10:01:42.425126,  3] ../source3/smbd/process.c:1958(process_smb)
  Transaction 1 of length 160 (0 toread)
[2019/04/16 10:01:42.425146,  5] ../source3/lib/util.c:171(show_msg)
[2019/04/16 10:01:42.425176,  5] ../source3/lib/util.c:181(show_msg)
  size=156
  smb_com=0x73
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51267
  smb_tid=0
  smb_pid=8305
  smb_uid=0
  smb_mid=1
  smt_wct=12
  smb_vwv[ 0]=  255 (0xFF)
  smb_vwv[ 1]=    0 (0x0)
  smb_vwv[ 2]=65535 (0xFFFF)
  smb_vwv[ 3]=    2 (0x2)
  smb_vwv[ 4]=    1 (0x1)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=    0 (0x0)
  smb_vwv[ 7]=   74 (0x4A)
  smb_vwv[ 8]=    0 (0x0)
  smb_vwv[ 9]=    0 (0x0)
  smb_vwv[10]=49236 (0xC054)
  smb_vwv[11]=32768 (0x8000)
  smb_bcc=97
[2019/04/16 10:01:42.425335,  3] ../source3/smbd/process.c:1538(switch_message)
  switch message SMBsesssetupX (pid 8320) conn 0x0
[2019/04/16 10:01:42.425357,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.425376,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.425394,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.425450,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2019/04/16 10:01:42.425482,  3] ../source3/smbd/sesssetup.c:623(reply_sesssetup_and_X)
  wct=12 flg2=0xc843
[2019/04/16 10:01:42.425507,  3] ../source3/smbd/sesssetup.c:140(reply_sesssetup_and_X_spnego)
  Doing spnego session setup
[2019/04/16 10:01:42.425536,  3] ../source3/smbd/sesssetup.c:181(reply_sesssetup_and_X_spnego)
  NativeOS=[Unix] NativeLanMan=[Samba] PrimaryDomain=[]
[2019/04/16 10:01:42.425561,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/run/samba/smbXsrv_session_global.tdb
[2019/04/16 10:01:42.425662,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/run/samba/smbXsrv_session_global.tdb
[2019/04/16 10:01:42.425695,  5] ../source3/auth/auth.c:491(make_auth_context_subsystem)
  Making default auth method list for server role = 'standalone server', encrypt passwords = yes
[2019/04/16 10:01:42.425717,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match guest
[2019/04/16 10:01:42.425736,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method guest has a valid init
[2019/04/16 10:01:42.425755,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match sam
[2019/04/16 10:01:42.425774,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method sam has a valid init
[2019/04/16 10:01:42.425810,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC mechanism spnego
[2019/04/16 10:01:42.425836,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.425857,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.425875,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.425893,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.425910,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.425977,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC submechanism ntlmssp
[2019/04/16 10:01:42.426007,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0x62088215
    NTLMSSP_NEGOTIATE_UNICODE
    NTLMSSP_REQUEST_TARGET
    NTLMSSP_NEGOTIATE_SIGN
    NTLMSSP_NEGOTIATE_NTLM
    NTLMSSP_NEGOTIATE_ALWAYS_SIGN
    NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
    NTLMSSP_NEGOTIATE_VERSION
    NTLMSSP_NEGOTIATE_128
    NTLMSSP_NEGOTIATE_KEY_EXCH
[2019/04/16 10:01:42.426146,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.426181,  5] ../source3/lib/util.c:171(show_msg)
[2019/04/16 10:01:42.426194,  5] ../source3/lib/util.c:181(show_msg)
  size=384
  smb_com=0x73
  smb_rcls=22
  smb_reh=0
  smb_err=49152
  smb_flg=136
  smb_flg2=51203
  smb_tid=0
  smb_pid=8305
  smb_uid=60099
  smb_mid=1
  smt_wct=4
  smb_vwv[ 0]=  255 (0xFF)
  smb_vwv[ 1]=    0 (0x0)
  smb_vwv[ 2]=    0 (0x0)
  smb_vwv[ 3]=  249 (0xF9)
  smb_bcc=341
[2019/04/16 10:01:42.428134,  6] ../source3/smbd/process.c:1956(process_smb)
  got message type 0x0 of len 0x25c
[2019/04/16 10:01:42.428188,  3] ../source3/smbd/process.c:1958(process_smb)
  Transaction 2 of length 608 (0 toread)
[2019/04/16 10:01:42.428210,  5] ../source3/lib/util.c:171(show_msg)
[2019/04/16 10:01:42.428223,  5] ../source3/lib/util.c:181(show_msg)
  size=604
  smb_com=0x73
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51267
  smb_tid=0
  smb_pid=8305
  smb_uid=60099
  smb_mid=2
  smt_wct=12
  smb_vwv[ 0]=  255 (0xFF)
  smb_vwv[ 1]=    0 (0x0)
  smb_vwv[ 2]=65535 (0xFFFF)
  smb_vwv[ 3]=    2 (0x2)
  smb_vwv[ 4]=    1 (0x1)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=    0 (0x0)
  smb_vwv[ 7]=  522 (0x20A)
  smb_vwv[ 8]=    0 (0x0)
  smb_vwv[ 9]=    0 (0x0)
  smb_vwv[10]=49236 (0xC054)
  smb_vwv[11]=32768 (0x8000)
  smb_bcc=545
[2019/04/16 10:01:42.428369,  3] ../source3/smbd/process.c:1538(switch_message)
  switch message SMBsesssetupX (pid 8320) conn 0x0
[2019/04/16 10:01:42.428391,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.428410,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.428428,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.428461,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2019/04/16 10:01:42.428485,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/run/samba/smbXsrv_session_global.tdb
[2019/04/16 10:01:42.428521,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/run/samba/smbXsrv_session_global.tdb
[2019/04/16 10:01:42.428548,  3] ../source3/smbd/sesssetup.c:623(reply_sesssetup_and_X)
  wct=12 flg2=0xc843
[2019/04/16 10:01:42.428567,  3] ../source3/smbd/sesssetup.c:140(reply_sesssetup_and_X_spnego)
  Doing spnego session setup
[2019/04/16 10:01:42.428587,  3] ../source3/smbd/sesssetup.c:181(reply_sesssetup_and_X_spnego)
  NativeOS=[Unix] NativeLanMan=[Samba] PrimaryDomain=[]
[2019/04/16 10:01:42.428608,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.428628,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.428646,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.428664,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.428681,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.428732,  3] ../auth/ntlmssp/ntlmssp_server.c:452(ntlmssp_server_preauth)
  Got user=[testuser] domain=[WORKGROUP] workstation=[FILESERVER-00-01] len1=24 len2=286
[2019/04/16 10:01:42.428763,  6] ../librpc/ndr/ndr_string.c:171(ndr_pull_string)
  short string '', sent with NULL termination despite NOTERM flag in IDL
[2019/04/16 10:01:42.428797,  3] ../source3/param/loadparm.c:3739(lp_load_ex)
  lp_load_ex: refreshing parameters
[2019/04/16 10:01:42.428819,  5] ../source3/param/loadparm.c:1312(free_param_opts)
  Freeing parametrics:
[2019/04/16 10:01:42.428894,  3] ../source3/param/loadparm.c:542(init_globals)
  Initialising global parameters
[2019/04/16 10:01:42.428976,  3] ../source3/param/loadparm.c:2668(lp_do_section)
  Processing section "[global]"
  doing parameter kernel change notify = no
  doing parameter workgroup = WORKGROUP
  doing parameter server string = %h server (Samba)
  doing parameter security = user
  doing parameter dns proxy = no
  doing parameter interfaces = 127.0.0.0/8 172.31.2.0/24
  doing parameter bind interfaces only = yes
  doing parameter log file = /var/log/samba/log.%m
  doing parameter log level = 6
[2019/04/16 10:01:42.429107,  5] ../lib/util/debug.c:642(debug_dump_status)
  INFO: Current debug levels:
    all: 6
    tdb: 6
    printdrivers: 6
    lanman: 6
    smb: 6
    rpc_parse: 6
    rpc_srv: 6
    rpc_cli: 6
    passdb: 6
    sam: 6
    auth: 6
    winbind: 6
    vfs: 6
    idmap: 6
    quota: 6
    acls: 6
    locking: 6
    msdfs: 6
    dmapi: 6
    registry: 6
    scavenger: 6
    dns: 6
    ldb: 6
    tevent: 6
  doing parameter max log size = 1000
  doing parameter panic action = /usr/share/samba/panic-action %d
  doing parameter server role = standalone server
  doing parameter passdb backend = tdbsam
  doing parameter obey pam restrictions = no
  doing parameter unix password sync = yes
  doing parameter passwd program = /usr/bin/passwd %u
  doing parameter passwd chat = *Enter\snew\s*\spassword:* %n\n *Retype\snew\s*\spassword:* %n\n *password\supdated\ssuccessfully* .
  doing parameter pam password change = yes
  doing parameter map to guest = bad user
  doing parameter usershare allow guests = no
  doing parameter strict locking = no
  doing parameter vfs objects = full_audit
  doing parameter full_audit:prefix = %u|%I|%m|%S
  doing parameter full_audit:success = all
  doing parameter full_audit:failure = none
  doing parameter full_audit:facility = local7
  doing parameter full_audit:priority = NOTICE
[2019/04/16 10:01:42.429595,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[testshare]"
  doing parameter comment = Test Share
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/testshare
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @testgroup
  doing parameter write list = @testgroup
  doing parameter locking = no
[2019/04/16 10:01:42.429754,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[ccroofing_1]"
  doing parameter comment = C&C Roofing
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/ccroofing
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @ccroofing
  doing parameter write list = @ccroofing
  doing parameter dfree command = /usr/local/bin/freespace.php ccroofing
[2019/04/16 10:01:42.429908,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[fairbanksaz_2]"
  doing parameter comment = Fairbanks AZ
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/fairbanksaz
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @fairbanksaz
  doing parameter write list = @fairbanksaz
  doing parameter dfree command = /usr/local/bin/freespace.php fairbanksaz
[2019/04/16 10:01:42.430061,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[mcba_3]"
  doing parameter comment = MCBA
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/mcba
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @mcba
  doing parameter write list = @mcba
  doing parameter dfree command = /usr/local/bin/freespace.php mcba
[2019/04/16 10:01:42.430212,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[mattlopez_4]"
  doing parameter comment = Matt Lopez
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/mattlopez
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @mattlopez
  doing parameter write list = @mattlopez
  doing parameter dfree command = /usr/local/bin/freespace.php mattlopez
  doing parameter veto files = /._*/.DS_Store/
  doing parameter delete veto files = yes
[2019/04/16 10:01:42.430396,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[detours_5]"
  doing parameter comment = Detours
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/detours
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @detours
  doing parameter write list = @detours
  doing parameter dfree command = /usr/local/bin/freespace.php detours
[2019/04/16 10:01:42.430550,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[fatstaf_6]"
  doing parameter comment = Fatstaf
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/fatstaf
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @fatstaf
  doing parameter write list = @fatstaf
  doing parameter dfree command = /usr/local/bin/freespace.php fatstaf
[2019/04/16 10:01:42.430701,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[brownchiro_7]"
  doing parameter comment = Brown Chiro
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/brownchiro
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @brownchiro
  doing parameter write list = @brownchiro
  doing parameter dfree command = /usr/local/bin/freespace.php brownchiro
[2019/04/16 10:01:42.430854,  2] ../source3/param/loadparm.c:2685(lp_do_section)
  Processing section "[lojb_8]"
  doing parameter comment = Law Offices of Jose Bracamonte
  doing parameter browseable = no
  doing parameter path = /netfs/lfs/file/lojb
  doing parameter guest ok = no
  doing parameter writable = yes
  doing parameter force create mode = 0660
  doing parameter directory mask = 0770
  doing parameter valid users = @lojb
  doing parameter write list = @lojb
  doing parameter dfree command = /usr/local/bin/freespace.php lojb
[2019/04/16 10:01:42.431014,  4] ../source3/param/loadparm.c:3780(lp_load_ex)
  pm_process() returned Yes
[2019/04/16 10:01:42.431045,  3] ../source3/param/loadparm.c:1585(lp_add_ipc)
  adding IPC service
[2019/04/16 10:01:42.431085,  5] ../source3/auth/auth_util.c:122(make_user_info_map)
  Mapping user [WORKGROUP]\[testuser] from workstation [FILESERVER-00-01]
[2019/04/16 10:01:42.431110,  5] ../source3/auth/auth_util.c:143(make_user_info_map)
  Mapped domain from [WORKGROUP] to [FILESERVER-00-01] for user [testuser] from workstation [FILESERVER-00-01]
[2019/04/16 10:01:42.431130,  5] ../source3/auth/user_info.c:62(make_user_info)
  attempting to make a user_info for testuser (testuser)
[2019/04/16 10:01:42.431148,  5] ../source3/auth/user_info.c:70(make_user_info)
  making strings for testuser's user_info struct
[2019/04/16 10:01:42.431168,  5] ../source3/auth/user_info.c:108(make_user_info)
  making blobs for testuser's user_info struct
[2019/04/16 10:01:42.431186,  3] ../source3/auth/auth.c:178(auth_check_ntlm_password)
  check_ntlm_password:  Checking password for unmapped user [WORKGROUP]\[testuser]@[FILESERVER-00-01] with the new password interface
[2019/04/16 10:01:42.431205,  3] ../source3/auth/auth.c:181(auth_check_ntlm_password)
  check_ntlm_password:  mapped user is: [FILESERVER-00-01]\[testuser]@[FILESERVER-00-01]
[2019/04/16 10:01:42.431223,  5] ../lib/util/util.c:555(dump_data)
  [0000] E9 49 12 69 48 AF 17 88                             .I.iH... 
[2019/04/16 10:01:42.431268,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.431290,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.431308,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.431332,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.431351,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.432206,  4] ../source3/lib/substitute.c:435(automount_server)
  Home server: fileserver-00-01
[2019/04/16 10:01:42.432244,  4] ../source3/lib/substitute.c:435(automount_server)
  Home server: fileserver-00-01
[2019/04/16 10:01:42.432275,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.432300,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.432318,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.432337,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.432354,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.432406,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.432440,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.432461,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.432479,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.432497,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.432514,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.432558,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.432583,  5] ../source3/lib/username.c:181(Get_Pwnam_alloc)
  Finding user testuser
[2019/04/16 10:01:42.432602,  5] ../source3/lib/username.c:120(Get_Pwnam_internals)
  Trying _Get_Pwnam(), username as lowercase is testuser
[2019/04/16 10:01:42.432681,  5] ../source3/lib/username.c:159(Get_Pwnam_internals)
  Get_Pwnam_internals did find user [testuser]!
[2019/04/16 10:01:42.432754,  3] ../source3/passdb/lookup_sid.c:1645(get_primary_group_sid)
  Forcing Primary Group to 'Domain Users' for testuser
[2019/04/16 10:01:42.432782,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.432803,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.432820,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.432838,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.432855,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.432901,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.432931,  4] ../source3/lib/substitute.c:435(automount_server)
  Home server: fileserver-00-01
[2019/04/16 10:01:42.432956,  4] ../source3/lib/substitute.c:435(automount_server)
  Home server: fileserver-00-01
[2019/04/16 10:01:42.432981,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.433001,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433019,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.433037,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.433062,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.433109,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433145,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.433170,  4] ../libcli/auth/ntlm_check.c:359(ntlm_password_check)
  ntlm_password_check: Checking NTLMv2 password with domain [WORKGROUP]
[2019/04/16 10:01:42.433206,  4] ../source3/auth/check_samsec.c:183(sam_account_ok)
  sam_account_ok: Checking SMB password for user testuser
[2019/04/16 10:01:42.433229,  5] ../source3/auth/check_samsec.c:165(logon_hours_ok)
  logon_hours_ok: user testuser allowed to logon at this time (Tue Apr 16 17:01:42 2019
  )
[2019/04/16 10:01:42.433254,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433273,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.433291,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433309,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.433326,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.433372,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.433397,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433466,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.433486,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433507,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.433525,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.433559,  5] ../source3/lib/username.c:181(Get_Pwnam_alloc)
  Finding user testuser
[2019/04/16 10:01:42.433578,  5] ../source3/lib/username.c:120(Get_Pwnam_internals)
  Trying _Get_Pwnam(), username as lowercase is testuser
[2019/04/16 10:01:42.433597,  5] ../source3/lib/username.c:159(Get_Pwnam_internals)
  Get_Pwnam_internals did find user [testuser]!
[2019/04/16 10:01:42.433620,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.433641,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433659,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.433676,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.433694,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.433738,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433762,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.433781,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433799,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.433816,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.433833,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.433884,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.433910,  5] ../source3/lib/username.c:181(Get_Pwnam_alloc)
  Finding user testuser
[2019/04/16 10:01:42.433928,  5] ../source3/lib/username.c:120(Get_Pwnam_internals)
  Trying _Get_Pwnam(), username as lowercase is testuser
[2019/04/16 10:01:42.433948,  5] ../source3/lib/username.c:159(Get_Pwnam_internals)
  Get_Pwnam_internals did find user [testuser]!
[2019/04/16 10:01:42.434170,  5] ../source3/auth/server_info_sam.c:122(make_server_info_sam)
  make_server_info_sam: made server info for user testuser -> testuser
[2019/04/16 10:01:42.434208,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434232,  3] ../source3/auth/auth.c:249(auth_check_ntlm_password)
  check_ntlm_password: sam authentication for user [testuser] succeeded
[2019/04/16 10:01:42.434256,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.434276,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434294,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.434312,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.434330,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.434368,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434389,  5] ../source3/auth/auth.c:292(auth_check_ntlm_password)
  check_ntlm_password:  PAM Account for user [testuser] succeeded
[2019/04/16 10:01:42.434407,  2] ../source3/auth/auth.c:305(auth_check_ntlm_password)
  check_ntlm_password:  authentication for user [testuser] -> [testuser] -> [testuser] succeeded
[2019/04/16 10:01:42.434585,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.434613,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434632,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.434650,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.434676,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.434728,  3] ../source3/auth/token_util.c:547(finalize_local_nt_token)
  Failed to fetch domain sid for WORKGROUP
[2019/04/16 10:01:42.434758,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434789,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.434810,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434828,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.434846,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.434863,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.434902,  3] ../source3/auth/token_util.c:579(finalize_local_nt_token)
  Failed to fetch domain sid for WORKGROUP
[2019/04/16 10:01:42.434931,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434953,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.434978,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.434998,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.435016,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.435033,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.435275,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.435305,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-2283378400-2303874118-2828177990-1009]
[2019/04/16 10:01:42.435334,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-2283378400-2303874118-2828177990-513]
[2019/04/16 10:01:42.435361,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1000]
[2019/04/16 10:01:42.441267,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-24]
[2019/04/16 10:01:42.441300,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-25]
[2019/04/16 10:01:42.441327,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-27]
[2019/04/16 10:01:42.441353,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-29]
[2019/04/16 10:01:42.441379,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-30]
[2019/04/16 10:01:42.441451,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-44]
[2019/04/16 10:01:42.441484,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-46]
[2019/04/16 10:01:42.441513,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-108]
[2019/04/16 10:01:42.441539,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1005]
[2019/04/16 10:01:42.441565,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1009]
[2019/04/16 10:01:42.441591,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1013]
[2019/04/16 10:01:42.441616,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1016]
[2019/04/16 10:01:42.441642,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1055]
[2019/04/16 10:01:42.441668,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1058]
[2019/04/16 10:01:42.441694,  5] ../source3/lib/privileges.c:176(get_privileges_for_sids)
  get_privileges_for_sids: sid = S-1-1-0
  Privilege set: 0x0
[2019/04/16 10:01:42.441725,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-2]
[2019/04/16 10:01:42.441751,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-11]
[2019/04/16 10:01:42.441855,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.441881,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.441900,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.441918,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.441935,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.441977,  5] ../source3/passdb/pdb_interface.c:1749(lookup_global_sam_rid)
  lookup_global_sam_rid: looking up RID 513.
[2019/04/16 10:01:42.442001,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.442020,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442038,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.442056,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.442073,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.442113,  5] ../source3/passdb/pdb_tdb.c:658(tdbsam_getsampwrid)
  pdb_getsampwrid (TDB): error looking up RID 513 by key RID_00000201.
[2019/04/16 10:01:42.442152,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442174,  5] ../source3/passdb/pdb_interface.c:1825(lookup_global_sam_rid)
  Can't find a unix id for an unmapped group
[2019/04/16 10:01:42.442192,  5] ../source3/passdb/pdb_interface.c:1535(pdb_default_sid_to_id)
  SID S-1-5-21-2283378400-2303874118-2828177990-513 belongs to our domain, but there is no corresponding object in the database.
[2019/04/16 10:01:42.442221,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442243,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442262,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442279,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442297,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.442314,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.442347,  5] ../source3/passdb/pdb_interface.c:1749(lookup_global_sam_rid)
  lookup_global_sam_rid: looking up RID 513.
[2019/04/16 10:01:42.442368,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.442387,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442405,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2019/04/16 10:01:42.442422,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.442439,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.442477,  5] ../source3/passdb/pdb_tdb.c:658(tdbsam_getsampwrid)
  pdb_getsampwrid (TDB): error looking up RID 513 by key RID_00000201.
[2019/04/16 10:01:42.442514,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442536,  5] ../source3/passdb/pdb_interface.c:1825(lookup_global_sam_rid)
  Can't find a unix id for an unmapped group
[2019/04/16 10:01:42.442555,  5] ../source3/passdb/pdb_interface.c:1535(pdb_default_sid_to_id)
  SID S-1-5-21-2283378400-2303874118-2828177990-513 belongs to our domain, but there is no corresponding object in the database.
[2019/04/16 10:01:42.442584,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442606,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442624,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442649,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442667,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.442685,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.442725,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442747,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442766,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442784,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442801,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.442818,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.442858,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442881,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442900,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.442918,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.442935,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.442952,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.442991,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.443048,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.443070,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.443088,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.443106,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.443123,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.443164,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.443187,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.443206,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.443223,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.443245,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.443263,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.443304,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.443330,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.443348,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.443366,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.445813,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.445941,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.446264,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.446417,  3] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
  NTLMSSP Sign/Seal - Initialising with flags:
[2019/04/16 10:01:42.446633,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0x62088215
    NTLMSSP_NEGOTIATE_UNICODE
    NTLMSSP_REQUEST_TARGET
    NTLMSSP_NEGOTIATE_SIGN
    NTLMSSP_NEGOTIATE_NTLM
    NTLMSSP_NEGOTIATE_ALWAYS_SIGN
    NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
    NTLMSSP_NEGOTIATE_VERSION
    NTLMSSP_NEGOTIATE_128
    NTLMSSP_NEGOTIATE_KEY_EXCH
[2019/04/16 10:01:42.447528,  3] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
  NTLMSSP Sign/Seal - Initialising with flags:
[2019/04/16 10:01:42.447647,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0x62088215
    NTLMSSP_NEGOTIATE_UNICODE
    NTLMSSP_REQUEST_TARGET
    NTLMSSP_NEGOTIATE_SIGN
    NTLMSSP_NEGOTIATE_NTLM
    NTLMSSP_NEGOTIATE_ALWAYS_SIGN
    NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
    NTLMSSP_NEGOTIATE_VERSION
    NTLMSSP_NEGOTIATE_128
    NTLMSSP_NEGOTIATE_KEY_EXCH
[2019/04/16 10:01:42.448494,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.448969,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.449088,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.449684,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.449780,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.449807,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.449851,  3] ../source3/auth/token_util.c:547(finalize_local_nt_token)
  Failed to fetch domain sid for WORKGROUP
[2019/04/16 10:01:42.449884,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.449917,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.449938,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.449956,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.449973,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.449991,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.450565,  3] ../source3/auth/token_util.c:579(finalize_local_nt_token)
  Failed to fetch domain sid for WORKGROUP
[2019/04/16 10:01:42.450601,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.450782,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.450920,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.450945,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.450965,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.450983,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.451572,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.451768,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-2283378400-2303874118-2828177990-1009]
[2019/04/16 10:01:42.452058,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-2283378400-2303874118-2828177990-513]
[2019/04/16 10:01:42.452097,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1000]
[2019/04/16 10:01:42.452131,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-24]
[2019/04/16 10:01:42.452160,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-25]
[2019/04/16 10:01:42.452186,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-27]
[2019/04/16 10:01:42.452212,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-29]
[2019/04/16 10:01:42.452238,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-30]
[2019/04/16 10:01:42.452264,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-44]
[2019/04/16 10:01:42.452289,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-46]
[2019/04/16 10:01:42.452841,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-108]
[2019/04/16 10:01:42.452886,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1005]
[2019/04/16 10:01:42.452917,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1009]
[2019/04/16 10:01:42.452943,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1013]
[2019/04/16 10:01:42.452970,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1016]
[2019/04/16 10:01:42.452995,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1055]
[2019/04/16 10:01:42.453021,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-1058]
[2019/04/16 10:01:42.453353,  5] ../source3/lib/privileges.c:176(get_privileges_for_sids)
  get_privileges_for_sids: sid = S-1-1-0
  Privilege set: 0x0
[2019/04/16 10:01:42.453540,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-2]
[2019/04/16 10:01:42.453575,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-11]
[2019/04/16 10:01:42.453630,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.453654,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.453672,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.453691,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.453709,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.453743,  5] ../source3/passdb/pdb_interface.c:1749(lookup_global_sam_rid)
  lookup_global_sam_rid: looking up RID 513.
[2019/04/16 10:01:42.453765,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.453785,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.453810,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.453829,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.453846,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.453886,  5] ../source3/passdb/pdb_tdb.c:658(tdbsam_getsampwrid)
  pdb_getsampwrid (TDB): error looking up RID 513 by key RID_00000201.
[2019/04/16 10:01:42.453924,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.453946,  5] ../source3/passdb/pdb_interface.c:1825(lookup_global_sam_rid)
  Can't find a unix id for an unmapped group
[2019/04/16 10:01:42.453964,  5] ../source3/passdb/pdb_interface.c:1535(pdb_default_sid_to_id)
  SID S-1-5-21-2283378400-2303874118-2828177990-513 belongs to our domain, but there is no corresponding object in the database.
[2019/04/16 10:01:42.453993,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454015,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454034,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454051,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454069,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.454086,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.454119,  5] ../source3/passdb/pdb_interface.c:1749(lookup_global_sam_rid)
  lookup_global_sam_rid: looking up RID 513.
[2019/04/16 10:01:42.454140,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.454159,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454177,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2019/04/16 10:01:42.454195,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.454212,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.454250,  5] ../source3/passdb/pdb_tdb.c:658(tdbsam_getsampwrid)
  pdb_getsampwrid (TDB): error looking up RID 513 by key RID_00000201.
[2019/04/16 10:01:42.454287,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454309,  5] ../source3/passdb/pdb_interface.c:1825(lookup_global_sam_rid)
  Can't find a unix id for an unmapped group
[2019/04/16 10:01:42.454327,  5] ../source3/passdb/pdb_interface.c:1535(pdb_default_sid_to_id)
  SID S-1-5-21-2283378400-2303874118-2828177990-513 belongs to our domain, but there is no corresponding object in the database.
[2019/04/16 10:01:42.454355,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454377,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454396,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454414,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454431,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.454449,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.454494,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454518,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454537,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454554,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454572,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.454589,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.454627,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454650,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454669,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454686,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454704,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.454721,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.454760,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454783,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454801,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454819,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454837,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.454854,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.454892,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454915,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454933,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.454951,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.454969,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.454986,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.455025,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.455047,  4] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.455065,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2019/04/16 10:01:42.455083,  4] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2019/04/16 10:01:42.455101,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2019/04/16 10:01:42.455118,  5] ../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2019/04/16 10:01:42.455196,  4] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2019/04/16 10:01:42.455242,  3] ../source3/smbd/password.c:130(register_homes_share)
  Using static (or previously created) service for user 'testuser'; path = '/netfs/lfs/file/testshare'
[2019/04/16 10:01:42.455286,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/run/samba/smbXsrv_session_global.tdb
[2019/04/16 10:01:42.455354,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/run/samba/smbXsrv_session_global.tdb
pbeza commented 5 years ago

I'm running 3.13.0-rc1 on Ubuntu Disco Dingo (19.04) but I've also tested it on 3.12. Both work for me.

I'm running the same 3.13.0-rc1, but on Debian Stretch (9.8). I have another installation that's setup similarly with Samba on Ubuntu 14.04 and LFS 3.9.4 and it works just fine as well.

Does the same test scenario work for you on Ubuntu 14.0.4 with LFS 3.9.4 and doesn't work on Debian Stretch (9.8)? Do you use similar Samba and LizardFS configuration on Ubuntu and on Debian?

One more idea that you can try out – add ignoregid to mfsexports.cfg as suggested here.

I'll give this a try once I get a chance and let you know how it goes.

OK, let's give it a try and share the results.

Since I'm not able to debug your problem (because I'm not able to reproduce it), I would suggest you to capture and investigate network traffic that is active within this ~12 seconds delay period – maybe you will notice something suspicious. You can use wireshark or tcpdump and share with me .pcap file unless you have any classified/private unencrypted communication that you don't want to share (you can filter out LizardFS packets). But first give try out ignoregid in mfsexports.cfg as suggested here.