[Samba] Win2k oplocks and you

[Anthony Awtrey]

Hello list!

I've seen the threads in this months archives on oplock issues, so I 
hope I am not hitting a sore spot by bringing it up again. The reason I 
am beating on this is that I've got a testable, repeatable issue with 
Win2K terminal server (SP2) running CorelDRAW 10 (patched to current) 
against a Debian Woody box running Samba 2.2.3a-6 for Debian. Since I 
can repeatedly test the issue, I've included a link to the tcpdump of 
the session and the log level 10 logs. Hopefully someone can help!

I can double click on a CorelDRAW file in the Windows Explorer view of a 
network share, CorelDRAW brings it right up. Once I am in CorelDRAW if I 
try to open another drawing or attempt to import a file from that same 
share I get a 30 second delay and "Server exit (oplock break failure)" 
in the log.smbd. Here are some interesting bits from the logs and dump 
so you don't have to download the whole log if you don't want to.

Here is the initial request in the log.smbd:

[2002/06/12 17:15:40, 10] smbd/open.c:open_file_shared(650)
   open_file_shared: fname = marketing/Slicks/Components/servericon.cdr,
   share_mode = 8040, ofun = 1, mode = 664, oplock request = 3
[2002/06/12 17:15:40, 8] lib/util.c:is_in_path(1115)
   is_in_path: marketing/Slicks/Components/servericon.cdr
[2002/06/12 17:15:40, 8] lib/util.c:is_in_path(1120)
   is_in_path: no name list.
[2002/06/12 17:15:40, 3] lib/util.c:unix_clean_name(387)
   unix_clean_name [marketing/Slicks/Components/servericon.cdr]
[2002/06/12 17:15:40, 10] locking/locking.c:get_share_modes(454)
   get_share_modes: share_mode_entry[0]: pid = 18911, share_mode = 0x40,
   port = 0x8e16, type= 0x3, file_id = 6, dev = 0x801, inode = 359229
[2002/06/12 17:15:40, 5] smbd/open.c:open_mode_check(495)
   open_mode_check: oplock_request = 3, breaking oplock (3) on file
   marketing/Slicks/Components/servericon.cdr, dev = 801, inode = 359229
[2002/06/12 17:15:40, 5] smbd/oplock.c:request_oplock_break(888)
   request_oplock_break: breaking our own oplock
[2002/06/12 17:15:40, 3] smbd/oplock.c:initial_break_processing(491)
   initial_break_processing: called for dev = 801, inode = 359229
   file_id = 6
   Current oplocks_open (exclusive = 1, levelII = 0)
[2002/06/12 17:15:40, 6] lib/util_sock.c:write_socket(518)
   write_socket(5,55)
[2002/06/12 17:15:40, 6] lib/util_sock.c:write_socket(521)
   write_socket(5,55) wrote 55
[2002/06/12 17:15:40, 5] smbd/vfs.c:vfs_GetWd(800)
   vfs_GetWd /share, inode 814, dev 2049
[2002/06/12 17:15:40, 3] smbd/sec_ctx.c:set_sec_ctx(314)
   setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2002/06/12 17:15:40, 5] smbd/uid.c:change_to_root_user(216)
   change_to_root_user: now uid=(0,0) gid=(0,0)
[2002/06/12 17:15:40, 3] smbd/oplock.c:initial_break_processing(491)
   initial_break_processing: called for dev = 801, inode = 359229
   file_id = 6
   Current oplocks_open (exclusive = 1, levelII = 0)
[2002/06/12 17:15:40, 10] 
lib/util_sock.c:read_smb_length_return_keepalive(560)
   got smb length of 118
[2002/06/12 17:15:40, 6] smbd/process.c:process_smb(859)
   got message type 0x0 of len 0x76
[2002/06/12 17:15:40, 3] smbd/process.c:process_smb(860)
   Transaction 60 of length 122

8< Snipped a bunch of show_msg and dump_data lines >8

[2002/06/12 17:15:40, 3] smbd/process.c:switch_message(667)
   switch message SMBtrans2 (pid 18911)
[2002/06/12 17:15:40, 2] smbd/process.c:switch_message(678)
   switch_message: queueing message due to being in oplock break state.
[2002/06/12 17:15:40, 3] smbd/oplock.c:initial_break_processing(491)
   initial_break_processing: called for dev = 801, inode = 359229
   file_id = 6
   Current oplocks_open (exclusive = 1, levelII = 0)

At this point the logs wait for 30 seconds (the oplock timeout I assume) 
and resumes thusly:

[2002/06/12 17:16:07, 3] smbd/sec_ctx.c:set_sec_ctx(314)
   setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2002/06/12 17:16:07, 5] smbd/uid.c:change_to_root_user(216)
   change_to_root_user: now uid=(0,0) gid=(0,0)
[2002/06/12 17:16:10, 10] lib/util_sock.c:read_socket_with_timeout(274)
   read_socket_with_timeout: timeout read. select timed out.
[2002/06/12 17:16:10, 10] lib/util_sock.c:receive_smb(611)
   receive_smb: length < 0!
[2002/06/12 17:16:10, 0] smbd/oplock.c:oplock_break(758)
   oplock_break: receive_smb error (Success)
   oplock_break failed for file
   marketing/Slicks/Components/servericon.cdr
  (dev = 801, inode = 359229, file_id = 6).

8< Snipped a bunch of cleanup messages >8

[2002/06/12 17:16:10, 3] smbd/server.c:exit_server(492)
   Server exit (oplock break failure)

The tcpdump over the same period indicates that the file is available. 
When the 'NT Create AndX Request' and 'Transaction2' request is sent by 
the Windows box, Samba responds with a 'Locking AndX Request' which the 
Windows box acknowledges. There is a 30 second delay which is followed 
by traffic showing the traffic related to the expiration of the timeout.

Full logs of these sessions are here:

ftp://ftp.idealcorp.com/pub/

The log files themselves are:

smbdump.bin  38 KB  (binary tcpdump)
smbdump.txt  104 KB (text tcpdump)
smblog.txt   10 KB  (log.smbd extract)

I'd really appreciate some insight on this. Hopefully I've given enough 
information to help me. Thanks in advance!

Anthony L. Awtrey
Vice President - Director of Integration
____________________________________________________
I.D.E.A.L. Technology Corporation - Melbourne Office
http://www.idealcorp.com - 321.728.0207