Bug 1780802

Is it just about the logs or is there a more substantial issue?
Is the configured "recycle" work as expected when windows/mac clients remove files?
A minimal way to reproduce with windows client would help as well.

The deleted files are moved to the recycle folder as expected, but the flood of errors being written in the log creates a performance problem. 

The clients when backing up files to the server via SAMBA delete the changed files before copying the new ones. That happens at different 1h intervals and the server gets high IOWAIT during this process affecting its usage.

You should be able to reproduce the error using the SMB.CONF on my first message. You copy a file from the Windows client to the SAMBA server and then delete it. You should then see the error both on the SAMBA log and using JOURNALCTL -xe.

Hello,

I tried to repro the issue with Window's client, but cannot.

**************samba server**********************
# testparm 
Load smb config files from /etc/samba/smb.conf
Loaded services file OK.
Server role: ROLE_STANDALONE

Press enter to see a dump of your service definitions

# Global parameters
[global]
	hostname lookups = Yes
	load printers = No
	log file = /var/log/samba/samba.log.%m
	max log size = 50
	netbios name = PIXIES
	security = USER
	server string = Samba Server Version %v
	unix extensions = No
	fruit:nfs_aces = no
	fruit:aapl = yes
	idmap config * : backend = tdb


[myshare]
	comment = User Files
	create mask = 0774
	delete veto files = Yes
	directory mask = 0775
	force create mode = 0774
	force directory mode = 0775
	path = /share
	read only = No
	veto files = /.AppleDB/.AppleDouble/.AppleDesktop/:2eDS_Store/Network Trash Folder/Temporary Items/TheVolumeSettingsFolder/.@__thumb/.@__desc/:2e*/.@__qini/.@upload_cache/.@qsys/.digest/
	vfs objects = catia fruit streams_xattr recycle
	recycle:minsize = 1
	recycle:exclude = *.tmp,*.temp,*.o,*.obj,~$*,*.~??,~*.*,*.TMP,*.TEMP,lock.*,.~lock.*,LOCK.*,*.lock,*.~lock,*.LNK,*.lnk,*.ldb,._*
	recycle:touch = yes
	recycle:versions = yes
	recycle:keeptree = yes
	recycle:directory_mode = 2775
	recycle:repository = @RecycleBin
	fruit:resource = file
	fruit:metadata = stream
	fruit:locking = none
	fruit:encoding = native
	fruit:aapl = yes
********************************************************


************Window's client************************
//<ip-address>/myshare
username: WORKGROUP/fred
password: 

Deleted screenshot.png from /share
***************************************************


****************samba server***********************
# ls -ltr /var/log/samba/
total 6864
drwx------. 3 root root    4096 Jan 14 18:33 cores
-rw-r--r--. 1 root root     164 Mar  3 06:21 samba.log.smbd
-rw-r--r--. 1 root root       0 Mar  3 06:22 samba.log.10.65.232.56
-rw-r--r--. 1 root root     170 Mar  3 06:23 samba.log.windows2008-2
# cat samba.log.windows2008-2
[2020/03/03 06:23:53.230909,  0] ../../source3/modules/vfs_recycle.c:242(recycle_get_file_size)
  recycle: stat for ./._screenshot.png returned No such file or directory
# 

>Size of file 'samba.log.windows2008-2' remains 170 bytes only
****************************************************

Am I missing something. I am using:samba-4.10.8-0.fc30.x86_64

No you are not missing anything. You managed to reproduce the problem.

You are getting the same error message on your log that I mentioned on my OP:

# cat samba.log.windows2008-2
[2020/03/03 06:23:53.230909,  0] ../../source3/modules/vfs_recycle.c:242(recycle_get_file_size)
  recycle: stat for ./._screenshot.png returned No such file or directory

You've only got 1 line (and a small log file) because you deleted only 1 file, but if you have multiple users replacing or deleting thousands of files on this share this log and your journal (journalctl) will be flooded with errors.

Thanks for the details, looking at the code in recycle_get_file_size(), it currently calls DEBUG(0), so I guess making it DEBUG(1) would solve it. But it is not clear to me yet, why is it looking for "._filename" and fails to find it, but then the recycling works well anyway.
Could you set debug level to 10, delete one file and attach the log, thanks.

Dear LP,

I believe the problem with this DEBUG statement "recycle: stat for ./._screenshot.png returned No such file or directory"

This debug log:
# cat samba.log.windows2008-2
[2020/03/03 06:23:53.230909,  0] ../../source3/modules/vfs_recycle.c:242(recycle_get_file_size)
  recycle: stat for ./._screenshot.png returned No such file or directory

Debug log is generated from Here:
source3/modules/vfs_recycle.c
static off_t recycle_get_file_size(vfs_handle_struct *handle,
                                       const struct smb_filename *smb_fname)
{
        struct smb_filename *smb_fname_tmp = NULL;
        off_t size;

        smb_fname_tmp = cp_smb_filename(talloc_tos(), smb_fname);
        if (smb_fname_tmp == NULL) {
                size = (off_t)0;
                goto out;
        }

        if (SMB_VFS_STAT(handle->conn, smb_fname_tmp) != 0) {
                DEBUG(0,("recycle: stat for %s returned %s\n",
                         smb_fname_str_dbg(smb_fname_tmp), strerror(errno)));
                size = (off_t)0;
                goto out;
        }

        size = smb_fname_tmp->st.st_ex_size;
 out:
        TALLOC_FREE(smb_fname_tmp);
        return size;
}

Logic i understand:
a. recycle_get_file_size() tries to get sizeof file(smb_fname)
b. SMB_VFS_STAT() tries tries to find the file VFS_FIND, and cannot find.


How can we avoid this log?
- [As you mentioned] but if you have multiple users replacing or deleting thousands of files on this share this log and your journal (journalctl) will be flooded with errors.
- so, if 1000's users are connected and some files gets deleted/recreated even with log level (not set) or log level=0 this log will be generated.
Way-1: not use vfs object = recycle
way-2: Remove the log completely from source code
Way-3: Change the DEBUG-LEVEL of log to 1 or may be higher, so that at log level=0 its log is not seen?

Are we on same page?

Created attachment 1667765 [details]
Samba log - File delete

I've attached the log after deleting the file /share/samba/backup/temp/example.txt.

I don't fully understand all the steps, but looking at the extract below it seems that vfs_fruit is deleting the streams before vfs_recycle therefore vfs_recycle can't find the file (temp/._example.txt).


[2020/03/05 12:32:58.843553, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for temp/example.txt
[2020/03/05 12:32:58.843572, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:5368(fruit_streaminfo)
  fruit_streaminfo: Path [temp/example.txt]
[2020/03/05 12:32:58.843600, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for temp/example.txt
[2020/03/05 12:32:58.843614, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for temp/example.txt
[2020/03/05 12:32:58.843632, 10, pid=54521, effective(1002, 1001), real(1002, 0)] ../source3/smbd/trans2.c:326(get_ea_names_from_file)
  get_ea_names_from_file: ea_namelist size = 15
[2020/03/05 12:32:58.843648, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for temp/example.txt
[2020/03/05 12:32:58.843662, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:1669(ad_get_internal)
  ad_get(rsrc) called for temp/example.txt
[2020/03/05 12:32:58.843675, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:1259(ad_open)
  ad_open: Path [temp/example.txt] type [rsrc]
[2020/03/05 12:32:58.843690, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:1687(ad_get_internal)
  ad_get_internal: ad_open [temp/example.txt] error [No such file or directory]
[2020/03/05 12:32:58.843709, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:1703(ad_get_internal)
  ad_get(rsrc) for temp/example.txt returning -1
[2020/03/05 12:32:58.843723, 10, pid=54521, effective(1002, 1001), real(1002, 0)] ../source3/smbd/close.c:190(delete_all_streams)
  delete_all_streams found 1 streams
[2020/03/05 12:32:58.843750, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:47(recycle_repository)
  recycle: repository = @RecycleBin
[2020/03/05 12:32:58.843767, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for temp/._example.txt
[2020/03/05 12:32:58.843780,  0, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:243(recycle_get_file_size)
  recycle: stat for temp/._example.txt returned No such file or directory
[2020/03/05 12:32:58.843851, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:136(recycle_maxsize)
  recycle: maxsize = 0
[2020/03/05 12:32:58.843865, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:148(recycle_minsize)
  recycle: minsize = 1
[2020/03/05 12:32:58.843876,  3, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:515(recycle_unlink)
  recycle: File temp/._example.txt lowers minimum recycle size, purging...
[2020/03/05 12:32:58.843893, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:47(recycle_repository)
  recycle: repository = @RecycleBin
[2020/03/05 12:32:58.843908, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for temp/example.txt
[2020/03/05 12:32:58.843923, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:136(recycle_maxsize)
  recycle: maxsize = 0
[2020/03/05 12:32:58.843935, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:148(recycle_minsize)
  recycle: minsize = 1
[2020/03/05 12:32:58.843947, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:547(recycle_unlink)
  recycle: fname = temp/example.txt
[2020/03/05 12:32:58.843959, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:549(recycle_unlink)
  recycle: fpath = temp
[2020/03/05 12:32:58.843970, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:551(recycle_unlink)
  recycle: base = example.txt
[2020/03/05 12:32:58.843999, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:102(recycle_exclude)
  recycle: exclude = *.tmp ...

[2020/03/05 12:32:58.844029, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:113(recycle_exclude_dir)
  recycle: exclude_dir =  ...
[2020/03/05 12:32:58.844043, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:58(recycle_keep_dir_tree)
  recycle_bin: keeptree = True
[2020/03/05 12:32:58.844056, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for @RecycleBin/temp
[2020/03/05 12:32:58.844086, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:576(recycle_unlink)
  recycle: Directory already exists
[2020/03/05 12:32:58.844099, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:605(recycle_unlink)
  recycle: recycled file name: @RecycleBin/temp/example.txt
[2020/03/05 12:32:58.844116, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for @RecycleBin/temp/example.txt
[2020/03/05 12:32:58.844137, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for @RecycleBin/temp/example.txt
[2020/03/05 12:32:58.844160, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:636(recycle_unlink)
  recycle: Moving temp/example.txt to @RecycleBin/temp/example.txt
[2020/03/05 12:32:58.844219, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:80(recycle_touch)
  recycle: touch = True
[2020/03/05 12:32:58.844251, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=recycle] ../source3/modules/vfs_recycle.c:91(recycle_touch_mtime)
  recycle: touch_mtime = False
[2020/03/05 12:32:58.844265, 10, pid=54521, effective(1002, 1001), real(1002, 0), class=fruit] ../source3/modules/vfs_fruit.c:4765(fruit_stat)
  fruit_stat called for @RecycleBin/temp/example.txt

(In reply to LP from comment #12)
> Created attachment 1667765 [details]
> Samba log - File delete

From the logs it looks like the error occurs due to vfs_fruit, and shouldn't happen otherwise, so i don't think the error level should change, rather we need to understand if 'fruit' and 'recycle' can work together.

Taking a closer look, this is not supported.  The manpage of fvs_fruit clearly states "This module is not stackable other than described in this manpage.", which are vfs_streams_xattr and vfs_catia. So it isn't supported with vsf_recycle, which explains the errors.

Can this information be confirmed upstream? 

These modules are currently used stacked up by several providers on their appliances (e.g. Synology, FreeNAS, Qnap, UnRAID).

Guenther also points out there were some changes around vfs_fruit in recent versions, i'll ask upstream.

Discussed upstream, this is just a log issue indeed. Ralph fixed it in master so it will be in samba v4.13, let me know if that's ok.

Thank you for checking upstream. I'm glad to hear it's not a serious problem and it has a simple fix.

Is this going to be patched on RHEL/CentOS when the patch is released upstream? The most up-to-date version is still 4.9.1-10, so I don't expect 4.13 to be released on RHEL/CentOS any time soon.

(In reply to LP from comment #20)

Ok then, I'll ask to include the log patch in release branches.

(In reply to Isaac Boukris from comment #21)
> (In reply to LP from comment #20)
> 
> Ok then, I'll ask to include the log patch in release branches.

Thank you Isaac. Much appreciated.

The log fix had been applied upstream and will be included in the next 4.11 and 4.12 minor versions as well.
Let me know if we can close this bug.

(In reply to Isaac Boukris from comment #23)
> The log fix had been applied upstream and will be included in the next 4.11
> and 4.12 minor versions as well.
> Let me know if we can close this bug.

Thank you Isaac. RHEL/CentOS are still running 4.9. Do you know when this fixes will filter through to RHEL/CentOS 7?

Yes, please you can close this bug.

(In reply to LP from comment #24)
> (In reply to Isaac Boukris from comment #23)
> > The log fix had been applied upstream and will be included in the next 4.11
> > and 4.12 minor versions as well.
> > Let me know if we can close this bug.
> 
> Thank you Isaac. RHEL/CentOS are still running 4.9. Do you know when this
> fixes will filter through to RHEL/CentOS 7?

Can't tell for sure, but older upstream branches are in security only mode.

> Yes, please you can close this bug.

Thanks!