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. */
Matthew Schumacher
2021-Jul-20 19:43 UTC
[Samba] Debug file_new then open_file_ntcreate fails with doesn't exist
On 7/16/21 2:25 PM, Jeremy Allison wrote:> 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. >> <snip> > Oh 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. */Hi Jermey, Thanks for looking at this. After fighting with it more, what I thought was the problem (some race condition with a file being read right after creation) didn't end up being the issue.? I noticed that whenever I restarted the linux server it would work again which is super odd because restarting samba wouldn't do anything to resolve it.? Given that the only thing that really changes with a reboot is handled by the kernel, I decided to upgrade the kernel from 4.19.171 to 5.10.52 thinking that the issue might be in the kernel.? Sure enough, the issue goes away. Do you by chance know of any kernel issues that could cause this? I'm not sure what I would be looking for in a kernel changelog that would affect samba like this. schu