Oplock timing issue.

Thu Jun 7 15:24:03 GMT 2001

We have tested our Netbench problems using SuSE Linux 7.1 on an RS/6000 43p/150.  The problem seems to be a timing issue, one smbd process is still processing the oplock break  while the other is doing fd_open on it.

In this case, Netbench v6.0 was used.  The first client that executes oplocks client.cfg, the second one, when it does an NT_create_and_X on the file also attempts an oplock.  The first client responds to the oplock break request with a close.  While the oplock break is processing, the second client is refused acces to the file.

I have attached 2 log files with level 10 debugging turned on, log.greedo is the first system which is running the controller and the first client, log.falcon is the second client that recieves an access denied message when trying to open client.cfg.

You can find these at around 04:44:35.613878 (these are per client logs taken at the same time).

I have pared down the logs to just the file open and oplock break, I have much larger logs that have the entire session.

By the way, the inode number for client.cfg is 376594.
-- 
Scott Prather
MCSE, MCP+I
Software Engineer
AIX PC Interoperability
sprather at austin.ibm.com
(512)838-3313
-------------- next part --------------
[2001/06/06 04:44:35.612318, 3] smbd/oplock_linux.c:linux_oplock_receive_message(144)
  receive_local_message: kernel oplock break request received for dev = 803, inode = 376594
[2001/06/06 04:44:35.612512, 5] smbd/oplock.c:process_local_message(300)
  process_local_message: Got a message of length 14 from port (0)
[2001/06/06 04:44:35.612585, 3] smbd/oplock_linux.c:linux_kernel_oplock_parse(237)
  kernel oplock break request for file dev = 803, inode = 376594
[2001/06/06 04:44:35.612673, 3] smbd/oplock.c:initial_break_processing(493)
  initial_break_processing: called for dev = 803, inode = 376594 tv_sec = 0, tv_usec = 0.
  Current oplocks_open (exclusive = 4, levelII = 0)
[2001/06/06 04:44:35.612902, 6] lib/util_sock.c:write_socket(560)
  write_socket(11,55)
[2001/06/06 04:44:35.613040, 6] lib/util_sock.c:write_socket(563)
  write_socket(11,55) wrote 55
[2001/06/06 04:44:35.613179, 3] smbd/sec_ctx.c:set_sec_ctx(310)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2001/06/06 04:44:35.613292, 5] smbd/uid.c:unbecome_user(217)
  unbecome_user now uid=(0,0) gid=(0,0)
[2001/06/06 04:44:35.613360, 3] smbd/oplock.c:initial_break_processing(493)
  initial_break_processing: called for dev = 803, inode = 376594 tv_sec = 0, tv_usec = 0.
  Current oplocks_open (exclusive = 4, levelII = 0)
[2001/06/06 04:44:35.615331, 10] lib/util_sock.c:read_smb_length_return_keepalive(602)
  got smb length of 41
[2001/06/06 04:44:35.615463, 6] smbd/process.c:process_smb(830)
  got message type 0x0 of len 0x29
[2001/06/06 04:44:35.615527, 3] smbd/process.c:process_smb(831)
  Transaction 184 of length 45
[2001/06/06 04:44:35.615582, 5] lib/util.c:show_msg(292)
  size=41

-------------- next part --------------
[2001/06/06 04:44:35.608018, 3] smbd/process.c:switch_message(650)
  switch message SMBntcreateX (pid 28969)
[2001/06/06 04:44:35.608079, 4] smbd/uid.c:become_user(119)
  Skipping become_user - already user
[2001/06/06 04:44:35.608140, 10] smbd/nttrans.c:map_create_disposition(395)
  map_create_disposition: Mapped create_disposition 1 to 1
[2001/06/06 04:44:35.608211, 10] smbd/nttrans.c:get_filename(262)
  get_filename: data_offset = 87, data_len = 10, fname_len = 10
[2001/06/06 04:44:35.608332, 10] smbd/nttrans.c:map_share_mode(522)
  map_share_mode: Mapped desired access 20089, share access 3, file attributes 80 to open_mode 40
[2001/06/06 04:44:35.608404, 5] smbd/filename.c:unix_convert(146)
  unix_convert called on file "NETBENCH\client.cfg"
[2001/06/06 04:44:35.608467, 3] lib/util.c:unix_clean_name(384)
  unix_clean_name [NETBENCH/client.cfg]
[2001/06/06 04:44:35.608535, 5] smbd/mangle.c:is_8_3(338)
  Checking client.cfg for 8.3
[2001/06/06 04:44:35.608645, 5] smbd/filename.c:unix_convert(222)
  unix_convert begin: name = NETBENCH/client.cfg, dirpath = NETBENCH, start = client.cfg
[2001/06/06 04:44:35.608877, 8] lib/util.c:is_in_path(1188)
  is_in_path: .
[2001/06/06 04:44:35.608960, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609017, 8] lib/util.c:is_in_path(1188)
  is_in_path: ..
[2001/06/06 04:44:35.609069, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609121, 8] lib/util.c:is_in_path(1188)
  is_in_path: CLIENT.CFG
[2001/06/06 04:44:35.609173, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609225, 8] lib/util.c:is_in_path(1188)
  is_in_path: CONFIG.CDB
[2001/06/06 04:44:35.609277, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609329, 8] lib/util.c:is_in_path(1188)
  is_in_path: client.exe
[2001/06/06 04:44:35.609381, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609433, 8] lib/util.c:is_in_path(1188)
  is_in_path: CPUID32.dll
[2001/06/06 04:44:35.609485, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609537, 8] lib/util.c:is_in_path(1188)
  is_in_path: NB_ERR.HLP
[2001/06/06 04:44:35.609589, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609641, 8] lib/util.c:is_in_path(1188)
  is_in_path: nbctrla.exe
[2001/06/06 04:44:35.609693, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609745, 8] lib/util.c:is_in_path(1188)
[2001/06/06 04:44:35.609745, 8] lib/util.c:is_in_path(1188)
  is_in_path: nbctrlb.exe
[2001/06/06 04:44:35.609797, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609850, 8] lib/util.c:is_in_path(1188)
  is_in_path: netbench.dll
[2001/06/06 04:44:35.609902, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.609954, 8] lib/util.c:is_in_path(1188)
  is_in_path: NETBENCH.HLP
[2001/06/06 04:44:35.610006, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610058, 8] lib/util.c:is_in_path(1188)
  is_in_path: NETBENCH.xla
[2001/06/06 04:44:35.610110, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610162, 8] lib/util.c:is_in_path(1188)
  is_in_path: README.WRI
[2001/06/06 04:44:35.610214, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610266, 8] lib/util.c:is_in_path(1188)
  is_in_path: RESULTS.XLM
[2001/06/06 04:44:35.610317, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610369, 8] lib/util.c:is_in_path(1188)
  is_in_path: docs
[2001/06/06 04:44:35.610421, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610473, 8] lib/util.c:is_in_path(1188)
  is_in_path: TSTMB.EXE
[2001/06/06 04:44:35.610525, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610577, 8] lib/util.c:is_in_path(1188)
  is_in_path: TSTMT.EXE
[2001/06/06 04:44:35.610629, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610680, 8] lib/util.c:is_in_path(1188)
  is_in_path: client
[2001/06/06 04:44:35.610733, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610785, 8] lib/util.c:is_in_path(1188)
  is_in_path: suites
[2001/06/06 04:44:35.610837, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.610889, 8] lib/util.c:is_in_path(1188)
  is_in_path: results
[2001/06/06 04:44:35.610941, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.611053, 8] lib/util.c:is_in_path(1188)
  is_in_path: netbench.ini
[2001/06/06 04:44:35.611111, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.611164, 8] lib/util.c:is_in_path(1188)
  is_in_path: client.dif
[2001/06/06 04:44:35.611216, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.611268, 8] lib/util.c:is_in_path(1188)
  is_in_path: login.sem
[2001/06/06 04:44:35.611320, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.611395, 5] smbd/mangle.c:name_map_mangle(990)
  name_map_mangle( CLIENT.CFG, need83 = FALSE, cache83 = TRUE, 4 )
[2001/06/06 04:44:35.611485, 5] smbd/mangle.c:name_map_mangle(1024)
  name_map_mangle() ==> [CLIENT.CFG]
[2001/06/06 04:44:35.611568, 5] smbd/statcache.c:stat_cache_add(132)
  stat_cache_add: Added entry NETBENCH/CLIENT.CFG -> NETBENCH/CLIENT.CFG
[2001/06/06 04:44:35.611639, 5] smbd/filename.c:unix_convert(407)
  conversion finished NETBENCH/client.cfg -> NETBENCH/CLIENT.CFG
[2001/06/06 04:44:35.611704, 3] smbd/dosmode.c:unix_mode(113)
  unix_mode(NETBENCH/CLIENT.CFG) returning 0744
[2001/06/06 04:44:35.611781, 5] smbd/files.c:file_new(107)
  allocated file structure 1789, fnum = 5885 (4 used)
[2001/06/06 04:44:35.611843, 10] smbd/open.c:open_file_shared(611)
  open_file_shared: fname = NETBENCH/CLIENT.CFG, share_mode = 40, ofun = 1, mode = 744, oplock request =
3
[2001/06/06 04:44:35.611907, 8] lib/util.c:is_in_path(1188)
  is_in_path: NETBENCH/CLIENT.CFG
[2001/06/06 04:44:35.611961, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/06 04:44:35.612012, 3] lib/util.c:unix_clean_name(384)
  unix_clean_name [NETBENCH/CLIENT.CFG]
[2001/06/06 04:44:35.612074, 4] smbd/open.c:open_file_shared(740)
  calling open_file with flags=0x0 flags2=0x0 mode=0744
[2001/06/06 04:44:35.613521, 10] smbd/open.c:fd_open(52)
  fd_open: name NETBENCH/CLIENT.CFG, flags = 04000 mode = 0744, fd = -1. Resource temporarily unavailable
[2001/06/06 04:44:35.613878, 3] smbd/open.c:open_file(158)
  Error opening file NETBENCH/CLIENT.CFG (Resource temporarily unavailable) (local_flags=0) (flags=0)
[2001/06/06 04:44:35.613970, 5] smbd/files.c:file_free(306)
  freed files structure 5885 (3 used)
[2001/06/06 04:44:35.614046, 3] smbd/error.c:error_packet(123)
  error string = Resource temporarily unavailable
[2001/06/06 04:44:35.614115, 3] smbd/error.c:error_packet(141)
  error packet at line 945 cmd=162 (SMBntcreateX) eclass=1 ecode=5