Jeremy Allison
2021-Jul-16 19:12 UTC
[Samba] Debug file_new then open_file_ntcreate fails with doesn't exist
On Fri, Jul 16, 2021 at 11:16:47AM -0700, Matthew Schumacher via samba wrote:>Hello List, > >I have a windows application that blows up when I use it on samba. The >error it gives is the generic windows C++ Unhandled e06d7363h >Exception and sometimes invalid parameter, both which could be >anything. > >When I move the data to a real windows share, it works.? So, I turned >on debugging to try and figure it out and I see this: > > >[2021/07/16 09:50:33.003786,? 5, pid=4251, effective(1000, 10000), >real(1000, 0)] ../../source3/smbd/files.c:176(file_new) >? file_new: new file fnum 989106358 >[2021/07/16 09:50:33.003796, 10, pid=4251, effective(1000, 10000), >real(1000, 0)] ../../source3/smbd/files.c:1290(file_name_hash) >? file_name_hash: /data/shop/PartShare/partlib/DB2017/ReadOnlyMode.ini >hash 0x2ab89022 >[2021/07/16 09:50:33.003806,? 5, pid=4251, effective(1000, 10000), >real(1000, 0)] ../../source3/smbd/dosmode.c:182(unix_mode) >? unix_mode: unix_mode(PartShare/partlib/DB2017/ReadOnlyMode.ini) >returning 0660 >[2021/07/16 09:50:33.003815, 10, pid=4251, effective(1000, 10000), >real(1000, 0)] ../../source3/smbd/open.c:3558(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 09:50:33.003838,? 5, pid=4251, effective(1000, 10000), >real(1000, 0)] ../../source3/smbd/open.c:3636(open_file_ntcreate) >? open_file_ntcreate: FILE_OPEN requested for file >PartShare/partlib/DB2017/ReadOnlyMode.ini and file doesn't exist. >[2021/07/16 09:50:33.003860, 10, pid=4251, effective(1000, 10000), >real(1000, 0)] ../../source3/smbd/open.c:6086(create_file_unixpath) >? create_file_unixpath: NT_STATUS_OBJECT_NAME_NOT_FOUND > >It looks like the application is wanting to create >/data/shop/PartShare/partlib/DB2017/ReadOnlyMode.ini then immediately >open it, but the open fails.? That would make sense why the thing >blows up with an unhandled exception if there wasn't any error >checking around open file given that we just created it. > >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.
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.