delete on close problem

Mon Nov 12 15:23:28 GMT 2001

Several weeks ago, I noted a problem where applications were creating lots
of tmp files and unable to save data files when oplocks were on.  I have
captured more useful data on this problem using a new CVS.  Here's a
synopsis of the sequence of events.

open file (creating) new_page_2.htm
close file
set map_share_mode: FILE_SHARE_DELETE requested. open_mode = 8000
open file new_page_2.htm
close file
attempt to create file new_page_2.htm [FAILS because file already exists]

I have a huge level 10 log file that I can share; however, I'm going to
include a portion of that log file for review.  How is FILE_SHARE_DELETE
supposed to function?  Should the second close remove the file which would
allow the succeding open to occur?  The log section that I'm including is
the 2nd open/close pair which is where I think the problem is.

After the application fails to create the file on the third open, it goes
into a cycle of open new tmp file(creating), close file, fail to create
same tmp file.  I don't understand how delete_on_close semantics apply in
these cases since the map_share_mode stuff appears normal during these
iterations.  If you want to see more debug info, just let me know.  I have
a level 10 that shows the full process above along with the succeeding
creation of a bunch of tmp files.

[2001/11/08 13:48:38, 10] smbd/nttrans.c:map_create_disposition(400)
  map_create_disposition: Mapped create_disposition 1 to 1
[2001/11/08 13:48:38, 10] smbd/nttrans.c:get_filename(261)
  get_filename: data_offset = 87, data_len = 16, fname_len = 16
[2001/11/08 13:48:38, 10] smbd/nttrans.c:map_share_mode(487)
  map_share_mode: FILE_SHARE_DELETE requested. open_mode = 8000
[2001/11/08 13:48:38, 10] smbd/nttrans.c:map_share_mode(527)
  map_share_mode: Mapped desired access 20089, share access 7, file attributes 80 to open_mode 8040
[2001/11/08 13:48:38, 5] smbd/filename.c:unix_convert(145)
  unix_convert called on file "\new_page_2.htm"
[2001/11/08 13:48:38, 3] lib/util.c:unix_clean_name(389)
  unix_clean_name [/new_page_2.htm]
[2001/11/08 13:48:38, 5] smbd/mangle.c:is_8_3(337)
  Checking new_page_2.htm for 8.3
[2001/11/08 13:48:38, 5] smbd/statcache.c:stat_cache_add(132)
  stat_cache_add: Added entry NEW_PAGE_2.HTM -> new_page_2.htm
[2001/11/08 13:48:38, 5] smbd/filename.c:unix_convert(215)
  conversion finished new_page_2.htm -> new_page_2.htm
[2001/11/08 13:48:38, 3] smbd/dosmode.c:unix_mode(111)
  unix_mode(new_page_2.htm) returning 0755
[2001/11/08 13:48:38, 5] smbd/files.c:file_new(121)
  allocated file structure 1812, fnum = 5908 (2 used)
[2001/11/08 13:48:38, 10] smbd/open.c:open_file_shared(653)
  open_file_shared: fname = new_page_2.htm, share_mode = 8040, ofun = 1, mode = 755, oplock request = 3
[2001/11/08 13:48:38, 8] lib/util.c:is_in_path(1104)
  is_in_path: new_page_2.htm
[2001/11/08 13:48:38, 8] lib/util.c:is_in_path(1109)
  is_in_path: no name list.
[2001/11/08 13:48:38, 3] lib/util.c:unix_clean_name(389)
  unix_clean_name [new_page_2.htm]
[2001/11/08 13:48:38, 4] smbd/open.c:open_file_shared(782)
  calling open_file with flags=0x0 flags2=0x0 mode=0755
[2001/11/08 13:48:38, 10] smbd/open.c:fd_open(51)
  fd_open: name new_page_2.htm, flags = 0200 mode = 0755, fd = 19.
[2001/11/08 13:48:38, 2] smbd/open.c:open_file(214)
  joe opened file new_page_2.htm read=Yes write=No (numopen=1)
[2001/11/08 13:48:38, 10] smbd/open.c:open_file_shared(883)
  open_file_shared : share_mode = 8040
[2001/11/08 13:48:38, 8] lib/util.c:is_in_path(1104)
  is_in_path: new_page_2.htm
[2001/11/08 13:48:38, 8] lib/util.c:is_in_path(1109)
  is_in_path: no name list.
[2001/11/08 13:48:38, 5] smbd/oplock.c:set_file_oplock(184)
  set_file_oplock: granted oplock on file new_page_2.htm, dev = 800006, inode = 980948, file_id = 18, tv_sec = 3bead386, tv_usec = 4bdaf
[2001/11/08 13:48:38, 8] smbd/dosmode.c:dos_mode(123)
  dos_mode: new_page_2.htm
[2001/11/08 13:48:38, 8] lib/util.c:is_in_path(1104)
  is_in_path: new_page_2.htm
[2001/11/08 13:48:38, 8] lib/util.c:is_in_path(1109)
  is_in_path: no name list.
[2001/11/08 13:48:38, 8] smbd/dosmode.c:dos_mode(167)
  dos_mode returning a
[2001/11/08 13:48:38, 5] smbd/nttrans.c:reply_ntcreate_and_X(962)
  reply_ntcreate_and_X: fnum = 5908, open name = new_page_2.htm
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(278)
  size=103
  smb_com=0xa2
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=136
  smb_flg2=1
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(284)
  smb_tid=1
  smb_pid=568
  smb_uid=101
  smb_mid=4675
  smt_wct=34
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[0]=255 (0xFF)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[1]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[2]=5122 (0x1402)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[3]=279 (0x117)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[4]=128 (0x80)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[5]=32768 (0x8000)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[6]=36912 (0x9030)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[7]=34297 (0x85F9)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[8]=49512 (0xC168)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[9]=32769 (0x8001)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[10]=36912 (0x9030)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[11]=34297 (0x85F9)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[12]=49512 (0xC168)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[13]=32769 (0x8001)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[14]=36912 (0x9030)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[15]=34297 (0x85F9)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[16]=49512 (0xC168)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[17]=32769 (0x8001)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[18]=36912 (0x9030)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[19]=34297 (0x85F9)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[20]=49512 (0xC168)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[21]=8193 (0x2001)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[22]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[23]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[24]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[25]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[26]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[27]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[28]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[29]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[30]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[31]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[32]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[33]=0 (0x0)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(294)
  smb_bcc=0
[2001/11/08 13:48:38, 6] lib/util_sock.c:write_socket(558)
  write_socket(5,107)
[2001/11/08 13:48:38, 6] lib/util_sock.c:write_socket(561)
  write_socket(5,107) wrote 107
[2001/11/08 13:48:38, 10] lib/util_sock.c:read_smb_length_return_keepalive(600)
  got smb length of 41
[2001/11/08 13:48:38, 6] smbd/process.c:process_smb(854)
  got message type 0x0 of len 0x29
[2001/11/08 13:48:38, 3] smbd/process.c:process_smb(855)
  Transaction 79 of length 45
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(278)
  size=41
  smb_com=0x4
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=2055
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(284)
  smb_tid=1
  smb_pid=65279
  smb_uid=101
  smb_mid=4739
  smt_wct=3
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[0]=5908 (0x1714)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[1]=65535 (0xFFFF)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(289)
  smb_vwv[2]=65535 (0xFFFF)
[2001/11/08 13:48:38, 5] lib/util.c:show_msg(294)
  smb_bcc=0
[2001/11/08 13:48:38, 3] smbd/process.c:switch_message(662)
  switch message SMBclose (pid 5288)
[2001/11/08 13:48:38, 4] smbd/uid.c:change_to_user(118)
  change_to_user: Skipping user change - already user
[2001/11/08 13:48:38, 3] smbd/reply.c:reply_close(2998)
  close fd=19 fnum=5908 (numopen=1)
[2001/11/08 13:48:38, 10] locking/locking.c:del_share_entry(511)
  del_share_entry: num_share_modes = 1
[2001/11/08 13:48:38, 10] locking/locking.c:del_share_entry(522)
  del_share_entry: deleting entry 0
[2001/11/08 13:48:38, 10] smbd/close.c:close_normal_file(155)
  close_normal_file: share_entry_count = 0 for file new_page_2.htm
[2001/11/08 13:48:38, 10] locking/posix.c:posix_locking_close_file(1253)
  posix_locking_close_file: file new_page_2.htm has no outstanding locks.
[2001/11/08 13:48:38, 2] smbd/close.c:close_normal_file(206)
  joe closed file new_page_2.htm (numopen=0)
[2001/11/08 13:48:38, 5] smbd/files.c:file_free(339)
  freed files structure 5908 (1 used)

------------------------------------------------------------------------
 Scott Moomaw, Network Administrator              Scott at Bridgewater.edu
 Bridgewater College, IT Center
 Bridgewater, VA  22812
 Phone (540) 828 - 8000  x5437              FAX:  (540) 828 - 5493