files locked forever -- logs! :)

Thu Jun 21 15:22:21 GMT 2001

Hi,

After 7 hours of logging (1,5Gb logfile) finally the problem was
starting again.
Netscape communicator was "locked forever", nobody could start it
anymore...
The DenyMode listed with smbstatus was only 'DENY_WRITE'
for netscape.exe (and R/W=RDONLY, oplock=EXCLUSIVE+BATCH), IIRC.

Some parts of the log:
== A. THIS IS WHEN NETSCAPE STARTS OK ==
[2001/06/20 21:49:27, 10] lib/util.c:dump_data(1517)
  [000] 5C 69 6E 74 65 72 6E 65  74 5C 4E 65 74 73 63 61  \interne
t\Netsca
[2001/06/20 21:49:27, 10] lib/util.c:dump_data(1525)
  [010] 70 65 5C 43 6F 6D 6D 75  6E 69 63 61 74 6F 72 5C  pe\Commu
nicator\
[2001/06/20 21:49:27, 10] lib/util.c:dump_data(1525)
  [020] 50 72 6F 67 72 61 6D 5C  6E 65 74 73 63 61 70 65  Program\
netscape
[2001/06/20 21:49:27, 10] lib/util.c:dump_data(1525)
  [030] 2E 65 78 65 00                                    .exe.
[2001/06/20 21:49:27, 3] smbd/process.c:switch_message(650)
  switch message SMBntcreateX (pid 19998)
[2001/06/20 21:49:27, 4] smbd/uid.c:become_user(114)
  Skipping become_user - already user
[2001/06/20 21:49:27, 10] smbd/nttrans.c:map_create_disposition(395)
  map_create_disposition: Mapped create_disposition 1 to 1
[2001/06/20 21:49:27, 10] smbd/nttrans.c:get_filename(262)
  get_filename: data_offset = 87, data_len = 53, fname_len = 52
[2001/06/20 21:49:27, 10] smbd/nttrans.c:map_share_mode(482)
  map_share_mode: FILE_SHARE_DELETE requested. open_mode = 8000
[2001/06/20 21:49:27, 10] smbd/nttrans.c:map_share_mode(522)
  map_share_mode: Mapped desired access 20089, share access 7, file
attributes 80 to open_mode 8040
[2001/06/20 21:49:27, 5] smbd/filename.c:unix_convert(146)
  unix_convert called on file
"\internet\Netscape\Communicator\Program\netscape.exe"
[2001/06/20 21:49:27, 3] lib/util.c:unix_clean_name(384)
  unix_clean_name [/internet/Netscape/Communicator/Program/netscape.exe]

[2001/06/20 21:49:27, 5] smbd/mangle.c:is_8_3(338)
  Checking netscape.exe for 8.3
[2001/06/20 21:49:27, 3] smbd/dosmode.c:unix_mode(113)
  unix_mode(internet/Netscape/Communicator/Program/netscape.exe)
returning 0744
[2001/06/20 21:49:27, 5] smbd/files.c:file_new(107)
  allocated file structure 461, fnum = 4557 (46 used)
[2001/06/20 21:49:27, 10] smbd/open.c:open_file_shared(611)
  open_file_shared: fname =
internet/Netscape/Communicator/Program/netscape.exe, share_mode = 8040,
ofun = 1, mode = 744, oplock request = 3
[2001/06/20 21:49:27, 8] lib/util.c:is_in_path(1188)
  is_in_path: internet/Netscape/Communicator/Program/netscape.exe
[2001/06/20 21:49:27, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/20 21:49:27, 3] lib/util.c:unix_clean_name(384)
  unix_clean_name [internet/Netscape/Communicator/Program/netscape.exe]
[2001/06/20 21:49:27, 4] smbd/open.c:open_file_shared(740)
  calling open_file with flags=0x0 flags2=0x0 mode=0744
[2001/06/20 21:49:27, 10] smbd/open.c:fd_open(52)
  fd_open: name internet/Netscape/Communicator/Program/netscape.exe,
flags = 04000 mode = 0744, fd = 31.
[2001/06/20 21:49:27, 2] smbd/open.c:open_file(216)
  ADMIN opened file internet/Netscape/Communicator/Program/netscape.exe
read=Yes write=No (numopen=46)
[2001/06/20 21:49:27, 10] smbd/open.c:open_file_shared(833)
  open_file_shared : share_mode = 8040
[2001/06/20 21:49:27, 8] lib/util.c:is_in_path(1188)
  is_in_path: internet/Netscape/Communicator/Program/netscape.exe
[2001/06/20 21:49:27, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/20 21:49:27, 5] smbd/oplock.c:set_file_oplock(170)
  set_file_oplock: granted oplock on file
internet/Netscape/Communicator/Program/netscape.exe, dev = 305, inode =
1648344, tv_sec = 3b30fe47, tv_usec = 7f7e2
[2001/06/20 21:49:27, 8] smbd/dosmode.c:dos_mode(125)
  dos_mode: internet/Netscape/Communicator/Program/netscape.exe
[2001/06/20 21:49:27, 8] lib/util.c:is_in_path(1188)
  is_in_path: internet/Netscape/Communicator/Program/netscape.exe
[2001/06/20 21:49:27, 8] lib/util.c:is_in_path(1222)
  is_in_path: match not found
[2001/06/20 21:49:27, 8] smbd/dosmode.c:dos_mode(169)
  dos_mode returning a
[2001/06/20 21:49:27, 5] smbd/nttrans.c:reply_ntcreate_and_X(1013)
  reply_ntcreate_and_X: fnum = 4557, open name =
internet/Netscape/Communicator/Program/netscape.exe

== B. THIS IS WHEN NETSCAPE DOES NOT START ('file already in use
blabla') ==
[2001/06/21 14:41:43, 10] lib/util.c:dump_data(1517)
  [000] 5C 69 6E 74 65 72 6E 65  74 5C 4E 65 74 73 63 61  \interne
t\Netsca
[2001/06/21 14:41:43, 10] lib/util.c:dump_data(1525)
  [010] 70 65 5C 43 6F 6D 6D 75  6E 69 63 61 74 6F 72 5C  pe\Commu
nicator\
[2001/06/21 14:41:43, 10] lib/util.c:dump_data(1525)
  [020] 50 72 6F 67 72 61 6D 5C  6E 65 74 73 63 61 70 65  Program\
netscape
[2001/06/21 14:41:43, 10] lib/util.c:dump_data(1525)
  [030] 2E 65 78 65 00                                    .exe.
[2001/06/21 14:41:43, 3] smbd/process.c:switch_message(650)
  switch message SMBntcreateX (pid 8278)
[2001/06/21 14:41:43, 4] smbd/uid.c:become_user(114)
  Skipping become_user - already user
[2001/06/21 14:41:43, 10] smbd/nttrans.c:map_create_disposition(395)
  map_create_disposition: Mapped create_disposition 1 to 1
[2001/06/21 14:41:43, 10] smbd/nttrans.c:get_filename(262)
  get_filename: data_offset = 87, data_len = 53, fname_len = 53
[2001/06/21 14:41:43, 10] smbd/nttrans.c:map_share_mode(482)
  map_share_mode: FILE_SHARE_DELETE requested. open_mode = 8000
[2001/06/21 14:41:43, 10] smbd/nttrans.c:map_share_mode(522)
  map_share_mode: Mapped desired access 20, share access 5, file
attributes 0 to open_mode 8020
[2001/06/21 14:41:43, 5] smbd/filename.c:unix_convert(146)
  unix_convert called on file
"\internet\Netscape\Communicator\Program\netscape.exe"
[2001/06/21 14:41:43, 3] lib/util.c:unix_clean_name(384)
  unix_clean_name [/internet/Netscape/Communicator/Program/netscape.exe]

[2001/06/21 14:41:43, 5] smbd/mangle.c:is_8_3(338)
  Checking netscape.exe for 8.3
[2001/06/21 14:41:43, 3] smbd/dosmode.c:unix_mode(113)
  unix_mode(internet/Netscape/Communicator/Program/netscape.exe)
returning 0744
[2001/06/21 14:41:43, 5] smbd/files.c:file_new(107)
  allocated file structure 128, fnum = 4224 (1 used)
[2001/06/21 14:41:43, 10] smbd/open.c:open_file_shared(611)
  open_file_shared: fname =
internet/Netscape/Communicator/Program/netscape.exe, share_mode = 8020,
ofun = 1, mode = 744, oplock request = 3
[2001/06/21 14:41:43, 8] lib/util.c:is_in_path(1188)
  is_in_path: internet/Netscape/Communicator/Program/netscape.exe
[2001/06/21 14:41:43, 8] lib/util.c:is_in_path(1193)
  is_in_path: no name list.
[2001/06/21 14:41:43, 3] lib/util.c:unix_clean_name(384)
  unix_clean_name [internet/Netscape/Communicator/Program/netscape.exe]
[2001/06/21 14:41:43, 5] smbd/open.c:open_mode_check(496)
  open_mode_check: breaking oplock (3) on file
internet/Netscape/Communicator/Program/netscape.exe, dev = 305, inode =
1648344
[2001/06/21 14:41:43, 3] smbd/oplock.c:request_oplock_break(930)
  request_oplock_break: sending a oplock break message to pid 18071 on
port 2104 for dev = 305, inode = 1648344, tv_sec = 3b31cd15, tv_usec =
7554e
[2001/06/21 14:41:43, 0] smbd/oplock.c:receive_local_message(126)
  receive_local_message. Error in recvfrom. (Connection refused).
[2001/06/21 14:41:43, 0] smbd/oplock.c:request_oplock_break(1016)
  request_oplock_break: error in response received to oplock break
request to pid 18071 on port 2104 for dev = 305, inode = 1648344, tv_sec
= 3b31cd15, tv_usec = 7554e
  Error was (Connection refused).
[2001/06/21 14:41:43, 0] smbd/open.c:open_mode_check(509)
  open_mode_check: FAILED when breaking oplock (4015) on file
internet/Netscape/Communicator/Program/netscape.exe, dev = 305, inode =
1648344
[2001/06/21 14:41:43, 10] smbd/open.c:fd_open(52)
  fd_open: name internet/Netscape/Communicator/Program/netscape.exe,
flags = 04000 mode = 0744, fd = 18.
[2001/06/21 14:41:43, 2] smbd/open.c:open_file(216)
  nobody opened file internet/Netscape/Communicator/Program/netscape.exe
read=Yes write=No (numopen=1)
[2001/06/21 14:41:43, 4] smbd/open.c:open_file_shared(725)
  open_file_shared : share_mode deny - calling open_file with flags=0x0
flags2=0x0 mode=0744 returned 1
[2001/06/21 14:41:43, 5] smbd/files.c:file_free(306)
  freed files structure 4224 (0 used)
[2001/06/21 14:41:43, 3] smbd/error.c:error_packet(123)
  error string = Operation not permitted
[2001/06/21 14:41:43, 3] smbd/error.c:error_packet(141)
  error packet at line 945 cmd=162 (SMBntcreateX) eclass=1 ecode=32
[2001/06/21 14:41:43, 5] lib/util.c:show_msg(292)
  size=35
  smb_com=0xa2
  smb_rcls=1
  smb_reh=0
  smb_err=32
  smb_flg=136
  smb_flg2=1
[2001/06/21 14:41:43, 5] lib/util.c:show_msg(298)
  smb_tid=2
  smb_pid=868
  smb_uid=0
  smb_mid=12610
  smt_wct=0
[2001/06/21 14:41:43, 5] lib/util.c:show_msg(308)
  smb_bcc=0
[2001/06/21 14:41:43, 6] lib/util_sock.c:write_socket(560)
  write_socket(4,39)
[2001/06/21 14:41:43, 6] lib/util_sock.c:write_socket(563)
  write_socket(4,39) wrote 39
[2001/06/21 14:41:46, 3] smbd/sec_ctx.c:set_sec_ctx(310)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2001/06/21 14:41:46, 5] smbd/uid.c:unbecome_user(217)
  unbecome_user now uid=(0,0) gid=(0,0)
[2001/06/21 14:41:46, 6] param/loadparm.c:lp_file_list_changed(2144)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed
Jun 20 20:32:57 2001

=== END OF LOGDUMPS

I think somebody who knows the whole oplock stuff / sharemode blah would
see pretty fast what's wrong.
[little theory]
Looks to me like some client was granted an exclusive oplock and doesn't
respond on a oplock break request
when another client wants to open that file, IIRC samba should then
remove the oplock,
but it looks like something else happends, anyway... I'm not an expert,
I'm looking in the samba source code
for just two days or something.
[/little theory]

I hope somebody can look at it, since it's a bit difficult for me to
trace the error exactly (and to fix it).

If you need any more log-stuff (or other information), just mail me,

Thanks,

    Syzop.