[Samba] Cannot get plaintext+pam auth to work on 4.2.10

Marcin Owsiany marcin at owsiany.pl
Wed Dec 14 07:43:51 UTC 2016


Hello,

After an almost 19 year gap, I need to ask this list for help again :-)

I have somewhat specific circumstances, where I think I can tolerate
plaintext passwords on the wire as long as I get samba to authenticate
against the system /etc/shadow (using PAM) in exchange.

0) I'm using Debian 8.4 (jessie), samba packages 2:4.2.10+dfsg-0+deb8u3.

1) I have created user smbtest with password asdasd

2) put the following into /etc/samba/smb.conf and reloaded smbd:

[global]
 debug level = 10 passdb:10
 server role = standalone server
 obey pam restrictions = yes
 encrypt passwords = no
 lanman auth = yes
 ntlm auth = no
 server max protocol = LANMAN2
 client lanman auth = yes
 client plaintext auth = yes
 client ntlmv2 auth = no
 ; the above seem relevant, see below for dump of full config
[data]
 path = /srv
 read only = no

3)  /etc/pam.d/samba is at unexciting default:
@include common-auth
@include common-account
@include common-session-noninteractive

4) and yet:

porridge at piec:~$ smbclient -U smbtest //localhost/data asdasd
session setup failed: NT_STATUS_ACCESS_DENIED
porridge at piec:~$

It seems that the password is being sent as plaintext,

  make_user_info_for_reply: User passwords not in encrypted format.

 but authentication using pam is failing for some reason:

  check_ntlm_password: unix authentication for user [SMBTEST] FAILED with
error NT_STATUS_LOGON_FAILURE

Does anyone have a clue why? From what I understood plaintext auth is
discouraged, but should still work?

Full debug output from both smbclient and smbd follows:

porridge at piec:~$ smbclient -d 10 -U smbtest //localhost/data asdasd
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
lp_load_ex: refreshing parameters
Initialising global parameters
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
Processing section "[global]"
doing parameter workgroup = WORKGROUP
doing parameter dns proxy = no
doing parameter log file = /var/log/samba/log.%m
doing parameter max log size = 1000
doing parameter syslog = 0
doing parameter panic action = /usr/share/samba/panic-action %d
doing parameter debug level = 10 passdb:10
doing parameter server role = standalone server
doing parameter obey pam restrictions = yes
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 = yes
doing parameter encrypt passwords = no
doing parameter lanman auth = yes
doing parameter ntlm auth = no
doing parameter server max protocol = LANMAN2
doing parameter client lanman auth = yes
doing parameter client plaintext auth = yes
doing parameter client ntlmv2 auth = no
pm_process() returned Yes
lp_servicenumber: couldn't find homes
added interface eth0 ip=192.168.1.1 bcast=192.168.1.255
netmask=255.255.255.0
added interface eth1 ip=192.168.192.1 bcast=192.168.192.255
netmask=255.255.255.0
Netbios name list:-
my_netbios_names[0]="PIEC"
Client started (version 4.2.10-Debian).
Opening cache file at /var/cache/samba/gencache.tdb
gencache_init: Opening cache file /var/cache/samba/gencache.tdb read-only.
Opening cache file at /var/run/samba/gencache_notrans.tdb
sitename_fetch: No stored sitename for
internal_resolve_name: looking up localhost#20 (sitename (null))
no entry for localhost#20 found.
resolve_lmhosts: Attempting lmhosts lookup for name localhost<0x20>
resolve_lmhosts: Attempting lmhosts lookup for name localhost<0x20>
startlmhosts: Can't open lmhosts file /etc/samba/lmhosts. Error was Nie ma
takiego pliku ani katalogu
resolve_wins: WINS server resolution selected and no WINS servers listed.
resolve_hosts: Attempting host lookup for name localhost<0x20>
remove_duplicate_addrs2: looking for duplicate address/port pairs
namecache_store: storing 2 addresses for localhost#20: [::1],127.0.0.1
Adding cache entry with key=[NBT/LOCALHOST#20] and timeout=[śro gru 14
08:49:32 2016 CET] (660 seconds ahead)
internal_resolve_name: returning 2 addresses: ::1:0 127.0.0.1:0
Connecting to ::1 at port 445
Socket options:
        SO_KEEPALIVE = 0
        SO_REUSEADDR = 0
        SO_BROADCAST = 0
        TCP_NODELAY = 1
        TCP_KEEPCNT = 9
        TCP_KEEPIDLE = 7200
        TCP_KEEPINTVL = 75
        IPTOS_LOWDELAY = 0
        IPTOS_THROUGHPUT = 0
        SO_REUSEPORT = 0
        SO_SNDBUF = 2626560
        SO_RCVBUF = 1061504
        SO_SNDLOWAT = 1
        SO_RCVLOWAT = 1
        SO_SNDTIMEO = 0
        SO_RCVTIMEO = 0
        TCP_QUICKACK = 1
        TCP_DEFER_ACCEPT = 0
 session request ok
session setup failed: NT_STATUS_ACCESS_DENIED
porridge at piec:~$


[2016/12/14 08:17:38.025725,  6, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2134(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Tue Dec
13 22:44:22 2016

  file /etc/samba/smb.conf modified: Wed Dec 14 08:09:01 2016

[2016/12/14 08:17:38.025767,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1237(free_service)
  free_service: Freeing service homes
[2016/12/14 08:17:38.025787,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1237(free_service)
  free_service: Freeing service printers
[2016/12/14 08:17:38.025802,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1237(free_service)
  free_service: Freeing service print$
[2016/12/14 08:17:38.025817,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1237(free_service)
  free_service: Freeing service data
[2016/12/14 08:17:38.025826,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1237(free_service)
  free_service: Freeing service IPC$
[2016/12/14 08:17:38.025834,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:3636(lp_load_ex)
  lp_load_ex: refreshing parameters
[2016/12/14 08:17:38.025840,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1212(free_param_opts)
  Freeing parametrics:
[2016/12/14 08:17:38.025881,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:527(init_globals)
  Initialising global parameters
[2016/12/14 08:17:38.025941,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2579(lp_do_section)
  Processing section "[global]"
  doing parameter workgroup = WORKGROUP
  doing parameter dns proxy = no
  doing parameter log file = /var/log/samba/log.%m
  doing parameter max log size = 1000
  doing parameter syslog = 0
  doing parameter panic action = /usr/share/samba/panic-action %d
  doing parameter debug level = 10 passdb:10
[2016/12/14 08:17:38.026008,  5, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/debug.c:334(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
  doing parameter server role = standalone server
  doing parameter obey pam restrictions = yes
  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 = yes
  doing parameter encrypt passwords = no
  doing parameter lanman auth = yes
  doing parameter ntlm auth = no
  doing parameter server max protocol = LANMAN2
  doing parameter client lanman auth = yes
  doing parameter client plaintext auth = yes
  doing parameter client ntlmv2 auth = no
[2016/12/14 08:17:38.026136,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[homes]"
[2016/12/14 08:17:38.026151,  8, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1319(add_a_service)
  add_a_service: Creating snum = 89 for homes
[2016/12/14 08:17:38.026156, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1369(hash_a_service)
  hash_a_service: hashing index 89 for service name homes
  doing parameter comment = Home Directories
  doing parameter browseable = no
  doing parameter read only = yes
  doing parameter create mask = 0700
  doing parameter directory mask = 0700
  doing parameter valid users = %S
[2016/12/14 08:17:38.026214,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[printers]"
[2016/12/14 08:17:38.026226,  8, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1319(add_a_service)
  add_a_service: Creating snum = 90 for printers
[2016/12/14 08:17:38.026231, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1369(hash_a_service)
  hash_a_service: hashing index 90 for service name printers
  doing parameter comment = All Printers
  doing parameter browseable = no
  doing parameter path = /var/spool/samba
  doing parameter printable = yes
  doing parameter guest ok = no
  doing parameter read only = yes
  doing parameter create mask = 0700
[2016/12/14 08:17:38.026281,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[print$]"
[2016/12/14 08:17:38.026300,  8, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1319(add_a_service)
  add_a_service: Creating snum = 91 for print$
[2016/12/14 08:17:38.026306, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1369(hash_a_service)
  hash_a_service: hashing index 91 for service name print$
  doing parameter comment = Printer Drivers
  doing parameter path = /var/lib/samba/printers
  doing parameter browseable = yes
  doing parameter read only = yes
  doing parameter guest ok = no
[2016/12/14 08:17:38.026339,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[data]"
[2016/12/14 08:17:38.026349,  8, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1319(add_a_service)
  add_a_service: Creating snum = 92 for data
[2016/12/14 08:17:38.026355, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1369(hash_a_service)
  hash_a_service: hashing index 92 for service name data
  doing parameter path = /srv
  doing parameter read only = no
[2016/12/14 08:17:38.026375,  4, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:3677(lp_load_ex)
  pm_process() returned Yes
[2016/12/14 08:17:38.026391,  8, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1319(add_a_service)
  add_a_service: Creating snum = 93 for IPC$
[2016/12/14 08:17:38.026396, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1369(hash_a_service)
  hash_a_service: hashing index 93 for service name IPC$
[2016/12/14 08:17:38.026403,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1476(lp_add_ipc)
  adding IPC service
[2016/12/14 08:17:38.026471,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/interface.c:341(add_interface)
  added interface eth0 ip=192.168.1.1 bcast=192.168.1.255
netmask=255.255.255.0
[2016/12/14 08:17:38.026483,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/interface.c:341(add_interface)
  added interface eth1 ip=192.168.192.1 bcast=192.168.192.255
netmask=255.255.255.0
[2016/12/14 08:17:38.026493,  5, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/util_net.c:1055(print_socket_options)
  Socket options:
   SO_KEEPALIVE = 1
   SO_REUSEADDR = 1
   SO_BROADCAST = 0
   TCP_NODELAY = 1
   TCP_KEEPCNT = 9
   TCP_KEEPIDLE = 7200
   TCP_KEEPINTVL = 75
   IPTOS_LOWDELAY = 0
   IPTOS_THROUGHPUT = 0
   SO_REUSEPORT = 1
   SO_SNDBUF = 2626560
   SO_RCVBUF = 1061696
   SO_SNDLOWAT = 1
   SO_RCVLOWAT = 1
   SO_SNDTIMEO = 0
   SO_RCVTIMEO = 0
   TCP_QUICKACK = 1
   TCP_DEFER_ACCEPT = 0
[2016/12/14 08:17:38.026529,  5, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/util_net.c:1055(print_socket_options)
  Socket options:
   SO_KEEPALIVE = 1
   SO_REUSEADDR = 1
   SO_BROADCAST = 0
   TCP_NODELAY = 1
   TCP_KEEPCNT = 9
   TCP_KEEPIDLE = 7200
   TCP_KEEPINTVL = 75
   IPTOS_LOWDELAY = 0
   IPTOS_THROUGHPUT = 0
   SO_REUSEPORT = 1
   SO_SNDBUF = 2626560
   SO_RCVBUF = 1061696
   SO_SNDLOWAT = 1
   SO_RCVLOWAT = 1
   SO_SNDTIMEO = 0
   SO_RCVTIMEO = 0
   TCP_QUICKACK = 1
   TCP_DEFER_ACCEPT = 0
[2016/12/14 08:17:38.026579,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 774 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026586,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 778 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026591,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 770 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026596,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 787 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026601,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 779 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026610,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 15 - private_data=(nil)
[2016/12/14 08:17:38.026616,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:399(messaging_register)
  Overriding messaging pointer for type 15 - private_data=(nil)
[2016/12/14 08:17:38.026621,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:431(messaging_deregister)
  Deregistering messaging pointer for type 16 - private_data=(nil)
[2016/12/14 08:17:38.026626,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 16 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026631,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:431(messaging_deregister)
  Deregistering messaging pointer for type 33 - private_data=0x7ff15c662f00
[2016/12/14 08:17:38.026636,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 33 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026641,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:431(messaging_deregister)
  Deregistering messaging pointer for type 790 - private_data=(nil)
[2016/12/14 08:17:38.026646,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 790 - private_data=0x7ff15c68c6c0
[2016/12/14 08:17:38.026651,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:431(messaging_deregister)
  Deregistering messaging pointer for type 791 - private_data=(nil)
[2016/12/14 08:17:38.026656,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:431(messaging_deregister)
  Deregistering messaging pointer for type 1 - private_data=(nil)
[2016/12/14 08:17:38.026661,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/messages.c:384(messaging_register)
  Registering messaging pointer for type 1 - private_data=(nil)
[2016/12/14 08:17:38.026668, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/events.c:483(event_add_idle)
  event_add_idle: idle_evt(keepalive) 0x7ff15c690080
[2016/12/14 08:17:38.026674, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/events.c:483(event_add_idle)
  event_add_idle: idle_evt(deadtime) 0x7ff15c6902d0
[2016/12/14 08:17:38.026682, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/events.c:483(event_add_idle)
  event_add_idle: idle_evt(housekeeping) 0x7ff15c690520
[2016/12/14 08:17:38.026700, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util_sock.c:369(read_smb_length_return_keepalive)
  got smb length of 190
[2016/12/14 08:17:38.026708,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:168(show_msg)
[2016/12/14 08:17:38.026712,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:178(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
[2016/12/14 08:17:38.026732, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/util.c:559(dump_data)
  [0000] 02 50 43 20 4E 45 54 57   4F 52 4B 20 50 52 4F 47   .PC NETW ORK
PROG
  [0010] 52 41 4D 20 31 2E 30 00   02 4D 49 43 52 4F 53 4F   RAM 1.0.
.MICROSO
  [0020] 46 54 20 4E 45 54 57 4F   52 4B 53 20 31 2E 30 33   FT NETWO RKS
1.03
  [0030] 00 02 4D 49 43 52 4F 53   4F 46 54 20 4E 45 54 57   ..MICROS OFT
NETW
  [0040] 4F 52 4B 53 20 33 2E 30   00 02 4C 41 4E 4D 41 4E   ORKS 3.0
..LANMAN
  [0050] 31 2E 30 00 02 4C 4D 31   2E 32 58 30 30 32 00 02   1.0..LM1
.2X002..
  [0060] 44 4F 53 20 4C 41 4E 4D   41 4E 32 2E 31 00 02 4C   DOS LANM
AN2.1..L
  [0070] 41 4E 4D 41 4E 32 2E 31   00 02 53 61 6D 62 61 00   ANMAN2.1
..Samba.
  [0080] 02 4E 54 20 4C 41 4E 4D   41 4E 20 31 2E 30 00 02   .NT LANM AN
1.0..
  [0090] 4E 54 20 4C 4D 20 30 2E   31 32 00                  NT LM 0. 12.
[2016/12/14 08:17:38.026849,  5, pid=30811, effective(0, 0), real(0, 0)]
../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2016/12/14 08:17:38.026859,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2016/12/14 08:17:38.027388, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:1291(set_remote_arch)
  set_remote_arch: Client arch is 'Samba'
[2016/12/14 08:17:38.027409,  6, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2134(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Dec
14 08:09:01 2016

[2016/12/14 08:17:38.027422,  5, pid=30811, effective(0, 0), real(0, 0)]
../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order)
  check lock order 2 for /var/run/samba/serverid.tdb
[2016/12/14 08:17:38.027428, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/dbwrap/dbwrap.c:133(debug_lock_order)
  lock order:  1:<none> 2:/var/run/samba/serverid.tdb 3:<none>
[2016/12/14 08:17:38.027436, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key)
  Locking key 5B78000000000000FFFF
[2016/12/14 08:17:38.027446, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal)
  Allocated locked data 0x0x7ff15c691410
[2016/12/14 08:17:38.027454, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key)
  Unlocking key 5B78000000000000FFFF
[2016/12/14 08:17:38.027460,  5, pid=30811, effective(0, 0), real(0, 0)]
../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor)
  release lock order 2 for /var/run/samba/serverid.tdb
[2016/12/14 08:17:38.027465, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/dbwrap/dbwrap.c:133(debug_lock_order)
  lock order:  1:<none> 2:<none> 3:<none>
[2016/12/14 08:17:38.027477,  6, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2134(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Dec
14 08:09:01 2016

[2016/12/14 08:17:38.027499,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:168(show_msg)
[2016/12/14 08:17:38.027502,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:178(show_msg)
  size=61
  smb_com=0x72
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=129
  smb_flg2=49155
  smb_tid=0
  smb_pid=65534
  smb_uid=0
  smb_mid=0
  smt_wct=13
  smb_vwv[ 0]=    6 (0x6)
  smb_vwv[ 1]=    1 (0x1)
  smb_vwv[ 2]=16644 (0x4104)
  smb_vwv[ 3]=   50 (0x32)
  smb_vwv[ 4]=    1 (0x1)
  smb_vwv[ 5]=    3 (0x3)
  smb_vwv[ 6]=30811 (0x785B)
  smb_vwv[ 7]=    0 (0x0)
  smb_vwv[ 8]=16947 (0x4233)
  smb_vwv[ 9]=18830 (0x498E)
  smb_vwv[10]=65476 (0xFFC4)
  smb_vwv[11]=    0 (0x0)
  smb_vwv[12]=    0 (0x0)
  smb_bcc=0
[2016/12/14 08:17:38.027543, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/util.c:559(dump_data)
[2016/12/14 08:17:38.027825, 10, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util_sock.c:369(read_smb_length_return_keepalive)
  got smb length of 90
[2016/12/14 08:17:38.027855,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:168(show_msg)
[2016/12/14 08:17:38.027859,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:178(show_msg)
  size=90
  smb_com=0x73
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=3
  smb_tid=65535
  smb_pid=30809
  smb_uid=0
  smb_mid=1
  smt_wct=10
  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]=30811 (0x785B)
  smb_vwv[ 6]=    0 (0x0)
  smb_vwv[ 7]=    6 (0x6)
  smb_vwv[ 8]=    0 (0x0)
  smb_vwv[ 9]=    0 (0x0)
  smb_bcc=35
[2016/12/14 08:17:38.027896, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/util.c:559(dump_data)
  [0000] 61 73 64 61 73 64 53 4D   42 54 45 53 54 00 57 4F   asdasdSM
BTEST.WO
  [0010] 52 4B 47 52 4F 55 50 00   55 6E 69 78 00 53 61 6D   RKGROUP.
Unix.Sam
  [0020] 62 61 00                                           ba.
[2016/12/14 08:17:38.027933,  5, pid=30811, effective(0, 0), real(0, 0)]
../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2016/12/14 08:17:38.027939,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2016/12/14 08:17:38.027971,  6, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2134(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Dec
14 08:09:01 2016

[2016/12/14 08:17:38.027987,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:491(make_auth_context_subsystem)
  Making default auth method list for server role = 'standalone server',
encrypt passwords = yes
[2016/12/14 08:17:38.027992,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:497(make_auth_context_subsystem)
  Making default auth method list for server role = 'standalone server',
encrypt passwords = no
[2016/12/14 08:17:38.028000,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend sam
[2016/12/14 08:17:38.028008,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'sam'
[2016/12/14 08:17:38.028013,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend sam_ignoredomain
[2016/12/14 08:17:38.028018,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'sam_ignoredomain'
[2016/12/14 08:17:38.028023,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend unix
[2016/12/14 08:17:38.028028,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'unix'
[2016/12/14 08:17:38.028033,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend winbind
[2016/12/14 08:17:38.028038,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'winbind'
[2016/12/14 08:17:38.028043,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend wbc
[2016/12/14 08:17:38.028048,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'wbc'
[2016/12/14 08:17:38.028053,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend trustdomain
[2016/12/14 08:17:38.028058,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'trustdomain'
[2016/12/14 08:17:38.028062,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend ntdomain
[2016/12/14 08:17:38.028070,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'ntdomain'
[2016/12/14 08:17:38.028075,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend guest
[2016/12/14 08:17:38.028112,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'guest'
[2016/12/14 08:17:38.028121,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match guest
[2016/12/14 08:17:38.028127,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method guest has a valid init
[2016/12/14 08:17:38.028132,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match unix
[2016/12/14 08:17:38.028138,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method unix has a valid init
[2016/12/14 08:17:38.028147,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth_util.c:297(make_user_info_for_reply)
  make_user_info_for_reply: User passwords not in encrypted format.
[2016/12/14 08:17:38.028200,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:62(make_user_info)
  attempting to make a user_info for SMBTEST (SMBTEST)
[2016/12/14 08:17:38.028206,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:70(make_user_info)
  making strings for SMBTEST's user_info struct
[2016/12/14 08:17:38.028215,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:108(make_user_info)
  making blobs for SMBTEST's user_info struct
[2016/12/14 08:17:38.028221, 10, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:159(make_user_info)
  made a user_info for SMBTEST (SMBTEST)
[2016/12/14 08:17:38.028228,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:3636(lp_load_ex)
  lp_load_ex: refreshing parameters
[2016/12/14 08:17:38.028234,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1212(free_param_opts)
  Freeing parametrics:
[2016/12/14 08:17:38.028262,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:527(init_globals)
  Initialising global parameters
[2016/12/14 08:17:38.028324,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2579(lp_do_section)
  Processing section "[global]"
  doing parameter workgroup = WORKGROUP
  doing parameter dns proxy = no
  doing parameter log file = /var/log/samba/log.%m
  doing parameter max log size = 1000
  doing parameter syslog = 0
  doing parameter panic action = /usr/share/samba/panic-action %d
  doing parameter debug level = 10 passdb:10
[2016/12/14 08:17:38.028383,  5, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/debug.c:334(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
  doing parameter server role = standalone server
  doing parameter obey pam restrictions = yes
  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 = yes
  doing parameter encrypt passwords = no
  doing parameter lanman auth = yes
  doing parameter ntlm auth = no
  doing parameter server max protocol = LANMAN2
  doing parameter client lanman auth = yes
  doing parameter client plaintext auth = yes
  doing parameter client ntlmv2 auth = no
[2016/12/14 08:17:38.028510,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[homes]"
  doing parameter comment = Home Directories
  doing parameter browseable = no
  doing parameter read only = yes
  doing parameter create mask = 0700
  doing parameter directory mask = 0700
  doing parameter valid users = %S
[2016/12/14 08:17:38.028566,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[printers]"
  doing parameter comment = All Printers
  doing parameter browseable = no
  doing parameter path = /var/spool/samba
  doing parameter printable = yes
  doing parameter guest ok = no
  doing parameter read only = yes
  doing parameter create mask = 0700
[2016/12/14 08:17:38.028608,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[print$]"
  doing parameter comment = Printer Drivers
  doing parameter path = /var/lib/samba/printers
  doing parameter browseable = yes
  doing parameter read only = yes
  doing parameter guest ok = no
[2016/12/14 08:17:38.028639,  2, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:2596(lp_do_section)
  Processing section "[data]"
  doing parameter path = /srv
  doing parameter read only = no
[2016/12/14 08:17:38.028658,  4, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:3677(lp_load_ex)
  pm_process() returned Yes
[2016/12/14 08:17:38.028669,  3, pid=30811, effective(0, 0), real(0, 0)]
../source3/param/loadparm.c:1476(lp_add_ipc)
  adding IPC service
[2016/12/14 08:17:38.028682,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth_util.c:117(make_user_info_map)
  Mapping user []\[SMBTEST] from workstation [__1]
[2016/12/14 08:17:38.028690,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth_util.c:139(make_user_info_map)
  Mapped domain from [] to [PIEC] for user [SMBTEST] from workstation [__1]
[2016/12/14 08:17:38.028695,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:62(make_user_info)
  attempting to make a user_info for SMBTEST (SMBTEST)
[2016/12/14 08:17:38.028700,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:70(make_user_info)
  making strings for SMBTEST's user_info struct
[2016/12/14 08:17:38.028706,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:108(make_user_info)
  making blobs for SMBTEST's user_info struct
[2016/12/14 08:17:38.028711, 10, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/user_info.c:159(make_user_info)
  made a user_info for SMBTEST (SMBTEST)
[2016/12/14 08:17:38.028716,  3, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:178(auth_check_ntlm_password)
  check_ntlm_password:  Checking password for unmapped user
[]\[SMBTEST]@[__1] with the new password interface
[2016/12/14 08:17:38.028722,  3, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:181(auth_check_ntlm_password)
  check_ntlm_password:  mapped user is: [PIEC]\[SMBTEST]@[__1]
[2016/12/14 08:17:38.028727, 10, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:190(auth_check_ntlm_password)
  check_ntlm_password: auth_context challenge created by random
[2016/12/14 08:17:38.028732, 10, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:192(auth_check_ntlm_password)
  challenge is:
[2016/12/14 08:17:38.028737,  5, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/util.c:559(dump_data)
  [0000] 77 7C DA 22 29 C0 63 B6                             w|.").c.
[2016/12/14 08:17:38.028748, 10, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth_builtin.c:41(check_guest_security)
  Check auth for: [SMBTEST]
[2016/12/14 08:17:38.028753, 10, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:233(auth_check_ntlm_password)
  check_ntlm_password: guest had nothing to say
[2016/12/14 08:17:38.028758, 10, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth_unix.c:44(check_unix_security)
  Check auth for: [SMBTEST]
[2016/12/14 08:17:38.028767,  5, pid=30811, effective(0, 0), real(0, 0)]
../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2016/12/14 08:17:38.028775,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2016/12/14 08:17:38.028784,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/username.c:181(Get_Pwnam_alloc)
  Finding user SMBTEST
[2016/12/14 08:17:38.028789,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/username.c:120(Get_Pwnam_internals)
  Trying _Get_Pwnam(), username as lowercase is smbtest
[2016/12/14 08:17:38.028826,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/username.c:159(Get_Pwnam_internals)
  Get_Pwnam_internals did find user [SMBTEST]!
[2016/12/14 08:17:38.028835,  5, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:252(auth_check_ntlm_password)
  check_ntlm_password: unix authentication for user [SMBTEST] FAILED with
error NT_STATUS_LOGON_FAILURE
[2016/12/14 08:17:38.028848,  2, pid=30811, effective(0, 0), real(0, 0),
class=auth] ../source3/auth/auth.c:315(auth_check_ntlm_password)
  check_ntlm_password:  Authentication for user [SMBTEST] -> [SMBTEST]
FAILED with error NT_STATUS_LOGON_FAILURE
[2016/12/14 08:17:38.028854,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/auth_ntlmssp.c:188(auth3_check_password)
  Checking NTLMSSP password for \SMBTEST failed: NT_STATUS_LOGON_FAILURE
[2016/12/14 08:17:38.028863,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:168(show_msg)
[2016/12/14 08:17:38.028867,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util.c:178(show_msg)
  size=35
  smb_com=0x73
  smb_rcls=1
  smb_reh=0
  smb_err=5
  smb_flg=136
  smb_flg2=3
  smb_tid=65535
  smb_pid=30809
  smb_uid=0
  smb_mid=1
  smt_wct=0
  smb_bcc=0
[2016/12/14 08:17:38.028887, 10, pid=30811, effective(0, 0), real(0, 0)]
../lib/util/util.c:559(dump_data)
[2016/12/14 08:17:38.028996,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/lib/util_sock.c:132(read_fd_with_timeout)
  read_fd_with_timeout: blocking read. EOF from client.
[2016/12/14 08:17:38.029008,  5, pid=30811, effective(0, 0), real(0, 0)]
../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2016/12/14 08:17:38.029013,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2016/12/14 08:17:38.029022,  5, pid=30811, effective(0, 0), real(0, 0)]
../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2016/12/14 08:17:38.029027,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2016/12/14 08:17:38.029035,  5, pid=30811, effective(0, 0), real(0, 0)]
../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2016/12/14 08:17:38.029039,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2016/12/14 08:17:38.029048,  5, pid=30811, effective(0, 0), real(0, 0)]
../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2016/12/14 08:17:38.029053,  5, pid=30811, effective(0, 0), real(0, 0)]
../source3/auth/token_util.c:639(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups

regards,
Marcin


More information about the samba mailing list