[Samba] Debug file_new then open_file_ntcreate fails with doesn't exist
Matthew Schumacher
matt.s at aptalaska.net
Fri Jul 16 20:44:17 UTC 2021
On 7/16/21 12:12 PM, Jeremy Allison wrote:
>>
>> Anybody see this before or thoughts on work arounds? I'm running the
>> latest stable samba 4.14.6 in AD mode.
>
> We haven't seen that, it looks strange. I take it there's no
> other application running that could race and delete ?
>
> Can you check the recently release 4.15.rc1 to see if it's
> something that got fixed ? There have been *lots* of changes
> in the pathname area between 4.14.x -> 4.15.rc1.
I isolated it to make sure there wasn't a race and checked with
smbstatus to ensure nothing else is using the share.
Looks like the same issue with 4.15rc1 The create was called at
12:23:28.127137 and the open at 12:23:28.129007 which is only 2ms apart.
Since the samba process to service both requests is the same, it doesn't
seem like it's a samba issue, perhaps the filesystem is slow? The samba
server is virtualized in qemu.
Any suggestions on other stuff to look at will be helpful.
Matt
4.15rc1 logs below:
$ grep -B1 ReadOnly temp3
[2021/07/16 12:23:28.127137, 10, pid=6697, effective(1000, 10000),
real(1000, 0), class=smb2]
../../source3/smbd/smb2_create.c:732(smbd_smb2_create_send)
smbd_smb2_create_send: name [PartShare\partlib\DB2017\ReadOnlyMode.ini]
--
[2021/07/16 12:23:28.127166, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/filename.c:989(unix_convert)
unix_convert: Called on file [PartShare/partlib/DB2017/ReadOnlyMode.ini]
--
[2021/07/16 12:23:28.127218, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/filename.c:1174(unix_convert)
unix_convert: Begin: name [PartShare/partlib/DB2017/ReadOnlyMode.ini]
dirpath [PartShare/partlib/DB2017] name [ReadOnlyMode.ini]
[2021/07/16 12:23:28.127235, 5, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/filename.c:255(check_parent_exists)
check_parent_exists: name =
PartShare/partlib/DB2017/ReadOnlyMode.ini, dirpath =
PartShare/partlib/DB2017, start = ReadOnlyMode.ini
[2021/07/16 12:23:28.127247, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/mangle_hash2.c:413(is_mangled)
is_mangled ReadOnlyMode.ini ?
[2021/07/16 12:23:28.127258, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/mangle_hash2.c:352(is_mangled_component)
is_mangled_component ReadOnlyMode.ini (len 16) ?
[2021/07/16 12:23:28.127268, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/filename.c:863(unix_convert_step)
unix_convert_step: dirpath [PartShare/partlib/DB2017] name
[ReadOnlyMode.ini]
[2021/07/16 12:23:28.127279, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/filename.c:674(unix_convert_step_stat)
unix_convert_step_stat: smb_fname
[PartShare/partlib/DB2017/ReadOnlyMode.ini]
[2021/07/16 12:23:28.127293, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/mangle_hash2.c:413(is_mangled)
is_mangled ReadOnlyMode.ini ?
[2021/07/16 12:23:28.127304, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/mangle_hash2.c:352(is_mangled_component)
is_mangled_component ReadOnlyMode.ini (len 16) ?
--
[2021/07/16 12:23:28.127637, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/mangle_hash2.c:413(is_mangled)
is_mangled ReadOnlyMode.ini ?
[2021/07/16 12:23:28.127649, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/mangle_hash2.c:352(is_mangled_component)
is_mangled_component ReadOnlyMode.ini (len 16) ?
[2021/07/16 12:23:28.127660, 10, pid=6697, effective(1000, 10000),
real(1000, 0)]
../../source3/smbd/filename.c:658(unix_convert_step_search_fail)
unix_convert_step_search_fail: New file [ReadOnlyMode.ini]
[2021/07/16 12:23:28.127672, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/filename.c:1374(unix_convert)
unix_convert: Conversion finished
[PartShare/partlib/DB2017/ReadOnlyMode.ini] ->
[PartShare/partlib/DB2017/ReadOnlyMode.ini]
[2021/07/16 12:23:28.127686, 10, pid=6697, effective(1000, 10000),
real(1000, 0), class=vfs] ../../source3/smbd/vfs.c:1323(check_reduced_name)
check_reduced_name: check_reduced_name
[PartShare/partlib/DB2017/ReadOnlyMode.ini] [/data/shop]
[2021/07/16 12:23:28.127715, 10, pid=6697, effective(1000, 10000),
real(1000, 0), class=vfs] ../../source3/smbd/vfs.c:1388(check_reduced_name)
check_reduced_name realpath
[PartShare/partlib/DB2017/ReadOnlyMode.ini] ->
[/data/shop/PartShare/partlib/DB2017/ReadOnlyMode.ini]
[2021/07/16 12:23:28.127729, 5, pid=6697, effective(1000, 10000),
real(1000, 0), class=vfs] ../../source3/smbd/vfs.c:1493(check_reduced_name)
check_reduced_name: PartShare/partlib/DB2017/ReadOnlyMode.ini reduced
to /data/shop/PartShare/partlib/DB2017/ReadOnlyMode.ini
[2021/07/16 12:23:28.127741, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/filename.c:2027(filename_convert_internal)
filename_convert_internal:
[PartShare/partlib/DB2017/ReadOnlyMode.ini] does not exist, skipping
pathref fsp
[2021/07/16 12:23:28.127755, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/open.c:6118(create_file_default)
create_file_default: create_file: access_mask = 0x80 file_attributes
= 0x0, share_access = 0x7, create_disposition = 0x1 create_options =
0x200000 oplock_request = 0x0 private_flags = 0x0 ea_list = (nil), sd =
(nil), fname = PartShare/partlib/DB2017/ReadOnlyMode.ini
[2021/07/16 12:23:28.127770, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/open.c:5549(create_file_unixpath)
create_file_unixpath: create_file_unixpath: access_mask = 0x80
file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1
create_options = 0x200000 oplock_request = 0x0 private_flags = 0x0
ea_list = (nil), sd = (nil), fname =
PartShare/partlib/DB2017/ReadOnlyMode.ini
--
[2021/07/16 12:23:28.128664, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/files.c:1378(file_name_hash)
file_name_hash: /data/shop/PartShare/partlib/DB2017/ReadOnlyMode.ini
hash 0x2ab89022
--
[2021/07/16 12:23:28.128975, 5, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/dosmode.c:183(unix_mode)
unix_mode: unix_mode(PartShare/partlib/DB2017/ReadOnlyMode.ini)
returning 0660
[2021/07/16 12:23:28.128991, 10, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/open.c:3530(open_file_ntcreate)
open_file_ntcreate: fname=PartShare/partlib/DB2017/ReadOnlyMode.ini,
dos_attrs=0x0 access_mask=0x80 share_access=0x7 create_disposition = 0x1
create_options=0x200000 unix mode=0660 oplock_request=0 private_flags = 0x0
[2021/07/16 12:23:28.129007, 5, pid=6697, effective(1000, 10000),
real(1000, 0)] ../../source3/smbd/open.c:3608(open_file_ntcreate)
open_file_ntcreate: FILE_OPEN requested for file
PartShare/partlib/DB2017/ReadOnlyMode.ini and file doesn't exist.
More information about the samba
mailing list