7158 – SMB2 connection resets during IOZone tests from 64-bit Vista client

Bug 7158 - SMB2 connection resets during IOZone tests from 64-bit Vista client

Summary: SMB2 connection resets during IOZone tests from 64-bit Vista client

Status:	RESOLVED FIXED

Alias:	None

Product:	Samba 3.5
Classification:	Unclassified
Component:	SMB2 (show other bugs)
Version:	3.5.0rc3
Hardware:	x86 Linux

Importance:	P3 normal
Target Milestone:	---
Assignee:	Jeremy Allison
QA Contact:	Samba QA Contact

URL:
Keywords:

Depends on:
Blocks:

Reported:	2010-02-19 12:36 UTC by clawsoon
Modified:	2010-06-11 13:38 UTC (History)
CC List:	1 user (show)

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description clawsoon 2010-02-19 12:36:29 UTC

I'm running iozone in throughput mode from 64-bit Vista to a 32-bit Centos 5.4 Samba server running 3.5.0rc3, with "max protocol = smb2".  (Throughput is fantastic, BTW.)  Partway through the iozone run - never at exactly the same place - the client disconnects and reconnects to the server, causing the iozone files to all be deleted.

Here's my smb.conf (yes, it's called "opensolaris01" even though it's a Linux box):

===== smb.conf begin =====

[global]

  security = user
  encrypt passwords = yes
  netbios name = opensolaris01
  workgroup = yowzalocal

  passdb backend = ldapsam:ldap://util01

  ldap admin dn = "cn=Manager,dc=yowzalocal"
  ldap ssl = off
  ldap delete dn = yes
  ldap user suffix = ou=Users
  ldap group suffix = ou=Groups
  ldap machine suffix = ou=Computers
  ldap suffix = dc=yowzalocal
  ldap passwd sync = yes

  server string = opensolaris01

  load printers = no
  printing = bsd
  printcap name = /dev/null
  disable spoolss = yes

  max log size = 50
  syslog = 0
  log level = 0


  dns proxy = no

  preserve case = yes
  short preserve case = yes
  mangled names = no

  max protocol = smb2


[testpool01]
  browseable = yes
  read only = no
  path = /testpool01

===== smb.conf end =====


Here's the iozone output:


===== iozone output begin =====

Y:\>"c:\Program Files (x86)\benchmarks\Iozone 3.321\iozone.exe" -e -c -i 0 -i 1
-i 8 -W -+n -+p 80 -r 128k -t 32 -s 256m
        Iozone: Performance Test of File I/O
                Version $Revision: 3.321 $
                Compiled for 32 bit mode.
                Build: Windows

        Contributors:William Norcott, Don Capps, Isom Crawford, Kirby Collins
                     Al Slater, Scott Rhine, Mike Wisner, Ken Goss
                     Steve Landherr, Brad Smith, Mark Kelly, Dr. Alain CYR,
                     Randy Dunlap, Mark Montague, Dan Million, Gavin Brebner,
                     Jean-Marc Zucconi, Jeff Blomberg, Benny Halevy,
                     Erik Habbinga, Kris Strecker, Walter Wong, Joshua Root.

        Run began: Fri Feb 19 11:20:59 2010

        Include fsync in write timing
        Include close in write timing
        Lock file when reading/writing.
        No retest option selected
        Percent read in mix test is 80
        Record Size 128 KB
        File size set to 262144 KB
        Command line used: /cygdrive/c/Program Files (x86)/benchmarks/Iozone 3.3
21/iozone -e -c -i 0 -i 1 -i 8 -W -+n -+p 80 -r 128k -t 32 -s 256m
        Output is in Kbytes/sec
        Time Resolution = 0.000002 seconds.
        Processor cache size set to 1024 Kbytes.
        Processor cache line size set to 32 bytes.
        File stride size set to 17 * record size.
        Throughput test with 32 processes
        Each process writes a 262144 Kbyte file in 128 Kbyte records

        Children see throughput for 32 initial writers  =   89346.39 KB/sec
        Parent sees throughput for 32 initial writers   =   89055.01 KB/sec
        Min throughput per process                      =    2790.03 KB/sec
        Max throughput per process                      =    2794.71 KB/sec
        Avg throughput per process                      =    2792.07 KB/sec
        Min xfer                                        =  261888.00 KB


Error reading block 1600, fd= 4Error reading block 1600, fd= 4
Error reading block 1601, fd= 4Error reading block 1600, fd= 4Error reading bloc
k 1601, fd= 4Error reading block 1600, fd= 4Error reading block 1599, fd= 4Error
 reading block 1601, fd= 4Error reading block 1601, fd= 4Error reading block 160
Error reading block 1601, fd= 4Error reading block 1599, fd= 4

readreadading block 1601, fd= 4Error reading block 1601, fd= 4
Error reading block 1600, fd= 4Error reading block 1600, fd= 4Error reading bloc
read99, fd= 4
read: No such host or network path: No such host or network path: : : : : No suc
: host or network path: readNo such host or network path: : No such host or netw
No such host or network pathNo such host or network pathNo such host or network
No such host or network pathnetwork pathNo such host or network path: No such ho
No such host or network pathNo such host or network pathNo such host or network
No such host or network path: No such host or network path
Error reChildren see throughput for 32 readers ock 1600,=       0.00 KB/sec bloc
k 1601, Parent sees throughput for 32 readers ror readin=       0.00 KB/secError
readreadMin throughput per process read block 1599, fd= =       0.00 KB/sec  159
:  fd= 4Max throughput per process d= 4Error reading blo=       0.00 KB/sec
        Avg throughput per process                      =       0.00 KB/sec
        Min xfer                                        =       0.00 KB
iozone.DUMMY.0: No such file or directory
iozone.DUMMY.1: No such file or directory
iozone.DUMMY.2: No such file or directory
iozone.DUMMY.4: No such file or directory
iozone.DUMMY.3: No such file or directory
iozone.DUMMY.6: No such file or directory
: No such file or directory
iozone.DUMMY.7: No such file or directory
: No such file or directory
iozone.DUMMY.9: No such file or directory
iozone.DUMMY.10: No such file or directory
iozone.DUMMY.11: No such file or directory
iozone.DUMMY.13: No such file or directory
: No such file or directory
iozone.DUMMY.14: No such file or directory
iozone.DUMMY.15: No such file or directory
iozone.DUMMY.16: No such file or directory
iozone.DUMMY.18: No such file or directory
iozone.DUMMY.17: No such file or directory
iozone.DUMMY.19: No such file or directory
iozone.DUMMY.20: No such file or directory
iozone.DUMMY.21: No such file or directory
iozone.DUMMY.22: No such file or directory
iozone.DUMMY.23: No such file or directory

: Can not open temp file: iozone.tmp
No such file or directory
open: No such file or directory


Can not open temp file: iozone.tmpCan not open temp file: iozone.tmp
openopen: : No such file or directoryNo such file or directory


Can not open temp file: iozone.tmp
Can not open temp file: iozone.tmp
openopen: : No such file or directoryNo such file or directory


Can not open temp file: iozone.tmp
open: No such file or directory

Can not open temp file: iozone.tmp
open: No such file or directory

iozone: interrupted

exiting iozone


Y:\>

===== iozone output end =====

Right after iozone fails, I can immediately start another instance and it doesn't complain about the network path not being there.

And here's the log level = 3 output right around the time of the iozone failure:

===== log.smbd begin =====

[2010/02/19 13:28:44.481457,  3] smbd/smb2_write.c:279(smbd_smb2_write_send)
  smbd_smb2_write: fnum=[18828/iozone.DUMMY.15] length=65536 offset=268238848 wrote=65536
[2010/02/19 13:28:44.481895,  3] lib/util.c:1846(fcntl_getlock)
  fcntl_getlock: fd 49 is returned info 2 pid 0
[2010/02/19 13:28:44.482169,  3] smbd/smb2_write.c:279(smbd_smb2_write_send)
  smbd_smb2_write: fnum=[18823/iozone.DUMMY.13] length=65536 offset=268173312 wrote=65536
[2010/02/19 13:28:44.482514,  3] lib/util.c:1846(fcntl_getlock)
  fcntl_getlock: fd 49 is returned info 2 pid 0
[2010/02/19 13:28:44.482736,  3] smbd/smb2_write.c:279(smbd_smb2_write_send)
  smbd_smb2_write: fnum=[18823/iozone.DUMMY.13] length=65536 offset=268238848 wrote=65536
[2010/02/19 13:28:44.482944,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18843 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.483105,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18808 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.483300,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18868 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.483457,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18783 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.483624,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18788 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.483780,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18778 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.483932,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18753 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.484080,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18893 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.484238,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18838 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.484394,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18853 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.484543,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18907 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.484705,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18763 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.484854,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18883 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.485008,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18892 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.485157,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18813 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.485313,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18768 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.485463,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18822 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.485624,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18878 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.485776,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18798 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.485925,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18803 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.486073,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18773 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.486231,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18854 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.489216,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.489271,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.489326,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.8 (numopen=34) NT_STATUS_OK
[2010/02/19 13:28:44.489573,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.489619,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.489670,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.1 (numopen=33) NT_STATUS_OK
[2010/02/19 13:28:44.489895,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.489939,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.489990,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.29 (numopen=32) NT_STATUS_OK
[2010/02/19 13:28:44.490210,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.490257,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.490307,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.16 (numopen=31) NT_STATUS_OK
[2010/02/19 13:28:44.490501,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18908 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.490672,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18858 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.490836,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18873 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.490986,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18867 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.491134,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18828 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.491290,  3] smbd/reply.c:7202(smbd_do_locking)
  smbd_do_locking: fnum=18823 type=0 num_locks=0 num_ulocks=1
[2010/02/19 13:28:44.491513,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.491566,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.491619,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.18 (numopen=30) NT_STATUS_OK
[2010/02/19 13:28:44.491837,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.491880,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.491929,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.11 (numopen=29) NT_STATUS_OK
[2010/02/19 13:28:44.492140,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.492189,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.492240,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.23 (numopen=28) NT_STATUS_OK
[2010/02/19 13:28:44.492462,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.492505,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.492564,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.7 (numopen=27) NT_STATUS_OK
[2010/02/19 13:28:44.492777,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.492822,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.492871,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.6 (numopen=26) NT_STATUS_OK
[2010/02/19 13:28:44.493079,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.493122,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.493170,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.5 (numopen=25) NT_STATUS_OK
[2010/02/19 13:28:44.493388,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.493431,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.493481,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.0 (numopen=24) NT_STATUS_OK
[2010/02/19 13:28:44.493786,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.493836,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.493886,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.27 (numopen=23) NT_STATUS_OK
[2010/02/19 13:28:44.494101,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.494143,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.494202,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.17 (numopen=22) NT_STATUS_OK
[2010/02/19 13:28:44.494412,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.494455,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.494504,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.20 (numopen=21) NT_STATUS_OK
[2010/02/19 13:28:44.494767,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.494812,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.494862,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.2 (numopen=20) NT_STATUS_OK
[2010/02/19 13:28:44.495074,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.495117,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.495166,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.30 (numopen=19) NT_STATUS_OK
[2010/02/19 13:28:44.495383,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.495425,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.495475,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.26 (numopen=18) NT_STATUS_OK
[2010/02/19 13:28:44.495723,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.495770,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.495820,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.28 (numopen=17) NT_STATUS_OK
[2010/02/19 13:28:44.538654,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.538717,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.538771,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.12 (numopen=16) NT_STATUS_OK
[2010/02/19 13:28:44.539014,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.539061,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.539110,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.3 (numopen=15) NT_STATUS_OK
[2010/02/19 13:28:44.539331,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.539376,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.539426,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.25 (numopen=14) NT_STATUS_OK
[2010/02/19 13:28:44.539667,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.539714,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.539764,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.9 (numopen=13) NT_STATUS_OK
[2010/02/19 13:28:44.563356,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.563403,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.563454,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.14 (numopen=12) NT_STATUS_OK
[2010/02/19 13:28:44.563681,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.563725,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.563775,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.10 (numopen=11) NT_STATUS_OK
[2010/02/19 13:28:44.563986,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.564031,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.564080,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.4 (numopen=10) NT_STATUS_OK
[2010/02/19 13:28:44.564298,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.564343,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.564424,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.19 (numopen=9) NT_STATUS_OK
[2010/02/19 13:28:44.564655,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.564701,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.564750,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.31 (numopen=8) NT_STATUS_OK
[2010/02/19 13:28:44.564965,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565007,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565056,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.21 (numopen=7) NT_STATUS_OK
[2010/02/19 13:28:44.565280,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565325,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565375,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.24 (numopen=6) NT_STATUS_OK
[2010/02/19 13:28:44.565592,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565637,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565687,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.22 (numopen=5) NT_STATUS_OK
[2010/02/19 13:28:44.565896,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565940,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.565990,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.15 (numopen=4) NT_STATUS_OK
[2010/02/19 13:28:44.577815,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.577865,  3] locking/locking.c:895(get_share_mode_lock)
  fill_share_mode_lock failed
[2010/02/19 13:28:44.577916,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.13 (numopen=3) NT_STATUS_OK
[2010/02/19 13:28:44.578078,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.578124,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.578154,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.578195,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.578231,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.31) returning 0744
[2010/02/19 13:28:44.578260,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.578296,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.578389,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.31 read=No write=No (numopen=4)
[2010/02/19 13:28:44.578592,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.578638,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.578668,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.578703,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.578737,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.21) returning 0744
[2010/02/19 13:28:44.578766,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.578801,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.578904,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.21 read=No write=No (numopen=5)
[2010/02/19 13:28:44.579089,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.24] [/testpool01]
[2010/02/19 13:28:44.579134,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.24 reduced to /testpool01/iozone.DUMMY.24
[2010/02/19 13:28:44.579170,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.24] [/testpool01]
[2010/02/19 13:28:44.579204,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.24 reduced to /testpool01/iozone.DUMMY.24
[2010/02/19 13:28:44.579240,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.24) returning 0744
[2010/02/19 13:28:44.579268,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.24] [/testpool01]
[2010/02/19 13:28:44.579303,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.24 reduced to /testpool01/iozone.DUMMY.24
[2010/02/19 13:28:44.579377,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.24 read=No write=No (numopen=6)
[2010/02/19 13:28:44.579567,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.579615,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.579643,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.579678,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.579713,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.22) returning 0744
[2010/02/19 13:28:44.579741,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.579776,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.579849,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.22 read=No write=No (numopen=7)
[2010/02/19 13:28:44.580030,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.580075,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.580104,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.580139,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.580181,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.15) returning 0744
[2010/02/19 13:28:44.580209,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.580244,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.580317,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.15 read=No write=No (numopen=8)
[2010/02/19 13:28:44.580495,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.13] [/testpool01]
[2010/02/19 13:28:44.580567,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.13 reduced to /testpool01/iozone.DUMMY.13
[2010/02/19 13:28:44.580599,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.13] [/testpool01]
[2010/02/19 13:28:44.580634,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.13 reduced to /testpool01/iozone.DUMMY.13
[2010/02/19 13:28:44.580669,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.13) returning 0744
[2010/02/19 13:28:44.580697,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.13] [/testpool01]
[2010/02/19 13:28:44.580732,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.13 reduced to /testpool01/iozone.DUMMY.13
[2010/02/19 13:28:44.580836,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.13 read=No write=No (numopen=9)
[2010/02/19 13:28:44.581023,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.31 (numopen=8) NT_STATUS_OK
[2010/02/19 13:28:44.581171,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.21 (numopen=7) NT_STATUS_OK
[2010/02/19 13:28:44.581306,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.24 (numopen=6) NT_STATUS_OK
[2010/02/19 13:28:44.581439,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.22 (numopen=5) NT_STATUS_OK
[2010/02/19 13:28:44.581582,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.15 (numopen=4) NT_STATUS_OK
[2010/02/19 13:28:44.581719,  2] smbd/close.c:656(close_normal_file)
  andrew closed file iozone.DUMMY.13 (numopen=3) NT_STATUS_OK
[2010/02/19 13:28:44.581855,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.581898,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.581928,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.581962,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.581998,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.31) returning 0744
[2010/02/19 13:28:44.582025,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.582060,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.582111,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.31 read=Yes write=Yes (numopen=4)
[2010/02/19 13:28:44.582291,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.582335,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.582364,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.582399,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.582433,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.21) returning 0744
[2010/02/19 13:28:44.582461,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.582496,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.582551,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.21 read=Yes write=Yes (numopen=5)
[2010/02/19 13:28:44.582720,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.24] [/testpool01]
[2010/02/19 13:28:44.582763,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.24 reduced to /testpool01/iozone.DUMMY.24
[2010/02/19 13:28:44.582791,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.24] [/testpool01]
[2010/02/19 13:28:44.582826,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.24 reduced to /testpool01/iozone.DUMMY.24
[2010/02/19 13:28:44.582861,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.24) returning 0744
[2010/02/19 13:28:44.582889,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.24] [/testpool01]
[2010/02/19 13:28:44.582923,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.24 reduced to /testpool01/iozone.DUMMY.24
[2010/02/19 13:28:44.582971,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.24 read=Yes write=Yes (numopen=6)
[2010/02/19 13:28:44.583173,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.583219,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.583248,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.583284,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.583319,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.22) returning 0744
[2010/02/19 13:28:44.583347,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.583382,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.583429,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.22 read=Yes write=Yes (numopen=7)
[2010/02/19 13:28:44.583609,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.583655,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.583684,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.583718,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.583754,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.15) returning 0744
[2010/02/19 13:28:44.583781,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.583816,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.583863,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.15 read=Yes write=Yes (numopen=8)
[2010/02/19 13:28:44.584034,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.13] [/testpool01]
[2010/02/19 13:28:44.584077,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.13 reduced to /testpool01/iozone.DUMMY.13
[2010/02/19 13:28:44.584105,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.13] [/testpool01]
[2010/02/19 13:28:44.584140,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.13 reduced to /testpool01/iozone.DUMMY.13
[2010/02/19 13:28:44.584181,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.13) returning 0744
[2010/02/19 13:28:44.584209,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.13] [/testpool01]
[2010/02/19 13:28:44.584244,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.13 reduced to /testpool01/iozone.DUMMY.13
[2010/02/19 13:28:44.584290,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.13 read=Yes write=Yes (numopen=9)
[2010/02/19 13:28:44.585673,  2] smbd/process.c:2207(deadtime_fn)
  Closing idle connection
[2010/02/19 13:28:44.585834,  3] smbd/server.c:146(msg_exit_server)
  got a SHUTDOWN message
[2010/02/19 13:28:44.585870,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.585921,  3] smbd/connection.c:31(yield_connection)
  Yielding connection to
[2010/02/19 13:28:44.604064,  3] smbd/connection.c:42(yield_connection)
  deleting connection record returned NT_STATUS_NOT_FOUND
[2010/02/19 13:28:44.620547,  3] smbd/server.c:868(exit_server_common)
  Server exit (normal exit)
[2010/02/19 13:28:44.755406,  3] smbd/oplock.c:894(init_oplocks)
  init_oplocks: initializing messages.
[2010/02/19 13:28:44.755638,  3] smbd/oplock_linux.c:224(linux_init_kernel_oplocks)
  Linux kernel oplocks enabled
[2010/02/19 13:28:44.804828,  3] smbd/process.c:1485(process_smb)
  Transaction 0 of length 106 (0 toread)
[2010/02/19 13:28:44.832197,  3] libsmb/ntlmssp.c:65(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0xe2088297
[2010/02/19 13:28:44.849607,  3] libsmb/ntlmssp.c:747(ntlmssp_server_auth)
  Got user=[andrew] domain=[nehapc1] workstation=[NEHAPC1] len1=24 len2=240
[2010/02/19 13:28:44.849720,  3] auth/auth.c:216(check_ntlm_password)
  check_ntlm_password:  Checking password for unmapped user [nehapc1]\[andrew]@[NEHAPC1] with the new password interface
[2010/02/19 13:28:44.849754,  3] auth/auth.c:219(check_ntlm_password)
  check_ntlm_password:  mapped user is: [OPENSOLARIS01]\[andrew]@[NEHAPC1]
[2010/02/19 13:28:44.849802,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.849837,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.849868,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.850081,  2] lib/smbldap.c:950(smbldap_open_connection)
  smbldap_open_connection: connection opened
[2010/02/19 13:28:44.852363,  3] lib/smbldap.c:1166(smbldap_connect_system)
  ldap_connect_system: successful connection to the LDAP server
[2010/02/19 13:28:44.853016,  2] passdb/pdb_ldap.c:572(init_sam_from_ldap)
  init_sam_from_ldap: Entry found for user: andrew
[2010/02/19 13:28:44.853303,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.853334,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/02/19 13:28:44.853361,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.853883,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.854144,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.854180,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/02/19 13:28:44.854207,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.854623,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.873523,  2] passdb/pdb_ldap.c:2446(init_group_from_ldap)
  init_group_from_ldap: Entry found for group: 100
[2010/02/19 13:28:44.892929,  3] passdb/pdb_get_set.c:271(pdb_get_group_sid)
  Primary group S-1-5-21-746454896-165841458-1213027620-4023 for user andrew is a UNKNOWN and not a domain group
[2010/02/19 13:28:44.893007,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.893037,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/02/19 13:28:44.893064,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.893130,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.893206,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.893235,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/02/19 13:28:44.893261,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.893309,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.909323,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.909402,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/02/19 13:28:44.909429,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.909492,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 3
[2010/02/19 13:28:44.909520,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 2
[2010/02/19 13:28:44.909546,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 3
[2010/02/19 13:28:44.910286,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.910337,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.910378,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.910516,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.910545,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.910572,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.910631,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.910662,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.910689,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.910715,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.915310,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.915364,  3] auth/auth.c:265(check_ntlm_password)
  check_ntlm_password: sam authentication for user [andrew] succeeded
[2010/02/19 13:28:44.915395,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.915424,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.915458,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.915499,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.915527,  2] auth/auth.c:304(check_ntlm_password)
  check_ntlm_password:  authentication for user [andrew] -> [andrew] -> [andrew] succeeded
[2010/02/19 13:28:44.916857,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.916908,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.916939,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.917350,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.917389,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.917417,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.917444,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.917527,  3] auth/token_util.c:467(create_local_nt_token)
  Failed to fetch domain sid for YOWZALOCAL
[2010/02/19 13:28:44.917560,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.917589,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.917616,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.917643,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.918468,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.918532,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-746454896-165841458-1213027620-4072]
[2010/02/19 13:28:44.918599,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-746454896-165841458-1213027620-4023]
[2010/02/19 13:28:44.918649,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-2]
[2010/02/19 13:28:44.918685,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-11]
[2010/02/19 13:28:44.918722,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-746454896-165841458-1213027620-4021]
[2010/02/19 13:28:44.918760,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-746454896-165841458-1213027620-4025]
[2010/02/19 13:28:44.919831,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.919879,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.919906,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.920300,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.921353,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.921401,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.921428,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.921843,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.922875,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.922921,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.922948,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.923336,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.923421,  3] libsmb/ntlmssp_sign.c:343(ntlmssp_sign_init)
  NTLMSSP Sign/Seal - Initialising with flags:
[2010/02/19 13:28:44.923460,  3] libsmb/ntlmssp.c:65(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0xe2088215
[2010/02/19 13:28:44.924144,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924186,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.924212,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924273,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.924307,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924334,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.924359,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924407,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.924479,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924507,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.924533,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924581,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.924636,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924664,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.924690,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924725,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.924778,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/02/19 13:28:44.924804,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.925700,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.925751,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.925809,  3] smbd/service.c:807(make_connection_snum)
  Connect path is '/testpool01' for service [testpool01]
[2010/02/19 13:28:44.925877,  3] smbd/vfs.c:97(vfs_init_default)
  Initialising default vfs hooks
[2010/02/19 13:28:44.925913,  3] smbd/vfs.c:122(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2010/02/19 13:28:44.926182,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926219,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.926246,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926301,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.926334,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926361,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.926387,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926434,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.926505,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926534,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.926560,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926608,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.926662,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926690,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/02/19 13:28:44.926717,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926752,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.926779,  3] smbd/uid.c:429(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/02/19 13:28:44.926806,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/02/19 13:28:44.927787,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/02/19 13:28:44.927833,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.927872,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (1536, 100) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.927943,  1] smbd/service.c:1069(make_connection_snum)
  nehapc1 (::ffff:192.168.16.158) connect to service testpool01 initially as user andrew (uid=1536, gid=100) (pid 8275)
[2010/02/19 13:28:44.927980,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.928419,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (1536, 100) - sec_ctx_stack_ndx = 0
[2010/02/19 13:28:44.928567,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.928615,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.928646,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.928681,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.928748,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.15) returning 0744
[2010/02/19 13:28:44.928776,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.15] [/testpool01]
[2010/02/19 13:28:44.928812,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.15 reduced to /testpool01/iozone.DUMMY.15
[2010/02/19 13:28:44.929074,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.15 read=No write=No (numopen=1)
[2010/02/19 13:28:44.929317,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.929368,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.929397,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.929432,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.929477,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.31) returning 0744
[2010/02/19 13:28:44.929506,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.31] [/testpool01]
[2010/02/19 13:28:44.929544,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.31 reduced to /testpool01/iozone.DUMMY.31
[2010/02/19 13:28:44.929633,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.31 read=No write=No (numopen=2)
[2010/02/19 13:28:44.929855,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.929904,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.929932,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.929967,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.930002,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.22) returning 0744
[2010/02/19 13:28:44.930031,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.22] [/testpool01]
[2010/02/19 13:28:44.930079,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.22 reduced to /testpool01/iozone.DUMMY.22
[2010/02/19 13:28:44.930164,  2] smbd/open.c:631(open_file)
  andrew opened file iozone.DUMMY.22 read=No write=No (numopen=3)
[2010/02/19 13:28:44.930346,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.930399,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.930427,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.930469,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21
[2010/02/19 13:28:44.930503,  3] smbd/dosmode.c:166(unix_mode)
  unix_mode(iozone.DUMMY.21) returning 0744
[2010/02/19 13:28:44.930532,  3] smbd/vfs.c:851(check_reduced_name)
  check_reduced_name [iozone.DUMMY.21] [/testpool01]
[2010/02/19 13:28:44.930566,  3] smbd/vfs.c:1008(check_reduced_name)
  check_reduced_name: iozone.DUMMY.21 reduced to /testpool01/iozone.DUMMY.21

===== log.smbd end =====

Let me know if any other info would be useful.  Thanks.

Andrew

Comment 1 Jeremy Allison 2010-02-19 18:13:58 UTC

OK I'm going to be working on SMB2 bugs at connectathon next week.

Does it depend on being run on 64-bit Vista or can you reproduce the problem on 32-bit machines ?

Jeremy.

Comment 2 clawsoon 2010-02-22 12:31:08 UTC

(In reply to comment #1)
> OK I'm going to be working on SMB2 bugs at connectathon next week.
> 
> Does it depend on being run on 64-bit Vista or can you reproduce the problem on
> 32-bit machines ?
> 
> Jeremy.

Hi Jeremy,

Unfortunately, I don't have any 32-bit Vista clients to try it with.  However, it doesn't happen when using 32-bit XP clients.  Obviously the 32-bit XP clients aren't using SMB2.

I could send you a Wireshark capture file, if that would be useful.  It would be a very large file, though.

Andrew

Comment 3 Jeremy Allison 2010-02-22 17:29:43 UTC

Just want to check. Are you running the pre-built 32-bit IOZone binary from the iozone.org site ? I'm just about to start using this in my Connectathon tests...

Jeremy.

Comment 4 clawsoon 2010-02-22 17:36:35 UTC

Yes, this one:

http://www.iozone.org/src/current/IozoneSetup.zip

Andrew

Comment 5 Jeremy Allison 2010-04-01 14:34:59 UTC

Ok, metze's patch in master: 6f30b9a6ff57ca6112e6319c64c411d2bf09be79 fixes the connection reset.

Now I'm trying to track down file corruption over SMB2 with the published version of iozone.exe.

When I build it myself under cygwin and run under gdb the corruption doesn't happen :-(.

Jeremy.

Comment 6 Jeremy Allison 2010-04-01 15:21:57 UTC

Oh. Great. If I run iozone I compiled myself it just works :-(.
Jeremy.

Comment 7 Volker Lendecke 2010-04-28 11:21:56 UTC

Jeremy, as you are working on SMB2 right now maybe you're more appropriate as the bug assignee. Feel free to re-assign to me if you don't think so.

Thanks,

Volker

Comment 8 Jeremy Allison 2010-05-19 21:40:01 UTC

This should now be fixed with commit af445935555dc3fab3cefc52b375dd18b8d9bb4c in master.

Please test and confirm.

Jeremy.

Comment 9 Karolin Seeger 2010-06-11 04:10:53 UTC

Change component.

Comment 10 Jeremy Allison 2010-06-11 13:38:57 UTC

Actually this bug is fixed in master with commit efd0c35a7e195865b18ce75bf2d592aaf1724d7d. The set of changes needed is too great to back-port for 3.5.x, so I'd like to close this out as fixed for 3.6.0.

Jeremy.