Matthew Schumacher
2021-Jul-16 20:44 UTC
[Samba] Debug file_new then open_file_ntcreate fails with doesn't exist
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.
Matthew Schumacher
2021-Jul-16 21:10 UTC
[Samba] Debug file_new then open_file_ntcreate fails with doesn't exist
On 7/16/21 1:44 PM, Matthew Schumacher via samba wrote:> 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.Tried a few more things: ??? strict sync = yes ??? sync always = yes ??? aio max threads = 1 Still get the same issue: [2021/07/16 13:07:54.393693,? 5, pid=2001, 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 13:07:54.393702, 10, pid=2001, 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 13:07:54.393712,? 5, pid=2001, 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. [2021/07/16 13:07:54.393735, 10, pid=2001, effective(1000, 10000), real(1000, 0)] ../../source3/smbd/open.c:6056(create_file_unixpath) ? create_file_unixpath: NT_STATUS_OBJECT_NAME_NOT_FOUND
Jeremy Allison
2021-Jul-16 21:22 UTC
[Samba] Debug file_new then open_file_ntcreate fails with doesn't exist
On Fri, Jul 16, 2021 at 01:44:17PM -0700, Matthew Schumacher via samba wrote:>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.Once the openat() called from source3/modules_vfs_default.c: result = openat(fsp_get_pathref_fd(dirfsp), smb_fname->base_name, flags, mode); with O_CREAT returns, the file *must* exist, slow filesystem or not. Can you do an strace on the smbd process whilst it's doing this call ?
Jeremy Allison
2021-Jul-16 21:25 UTC
[Samba] Debug file_new then open_file_ntcreate fails with doesn't exist
On Fri, Jul 16, 2021 at 01:44:17PM -0700, Matthew Schumacher via samba wrote:>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.iniOh hang on a minute. Look at that create_disposition = 0x1. This means: #define FILE_OPEN 1 /* File exists open. File not exist fail. */ So smbd is doing the right thing here. To create a new file, create_disposition must be one of either: #define FILE_CREATE 2 /* File exists fail. File not exist create. */ #define FILE_OPEN_IF 3 /* File exists open. File not exist create. */ #define FILE_OVERWRITE_IF 5 /* File exists overwrite. File not exist create. */