Bug 1780802 - vfs_recycle can't handle ._ AppleDouble files (vfs_fruit)
Summary: vfs_recycle can't handle ._ AppleDouble files (vfs_fruit)
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: samba
Version: 7.7
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: Isaac Boukris
QA Contact: Andrej Dzilský
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-12-07 01:41 UTC by LP
Modified: 2020-03-24 19:07 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-03-24 19:07:45 UTC
Target Upstream Version:


Attachments (Terms of Use)
Samba log - File delete (1.18 MB, text/plain)
2020-03-05 13:36 UTC, LP
no flags Details


Links
System ID Priority Status Summary Last Updated
Samba Project 14316 None None None 2020-03-06 11:50:43 UTC

Description LP 2019-12-07 01:41:39 UTC
My log files are being flooded with errors like the ones below whenever a Mac or Windows client delete files from a Samba share.

--- Mac client ---

[2019/07/26 14:02:26.182564,  0] ../source3/modules/vfs_recycle.c:243(recycle_get_file_size)
  recycle: stat for Chris_Mac/._videos.docx returned No such file or directory

[2019/07/26 14:02:27.186472,  0] ../source3/modules/vfs_recycle.c:243(recycle_get_file_size)
  recycle: stat for Chris_Mac/._Pollay.pdf returned No such file or directory

[2019/07/26 15:52:11.165328,  0] ../source3/modules/vfs_recycle.c:243(recycle_get_file_size)
  recycle: stat for temp/._checklist.pdf returned No such file or directory

--- Windows client ---

[2019/09/04 11:45:53.923258,  0] ../source3/modules/vfs_recycle.c:243(recycle_get_file_size)
  recycle: stat for LF/._Cent OS.one returned No such file or directory

I tried without success different options for fruit:metadata and fruit:resource. I've also researched the order of vfs modules and it seems I'm using them in the correct order.

I'm including the Global and Share sections of my SMB.CONF files below.

Regards,
LP

=======

Clients Mac OS 10.14.5 and Windows 10.1909


**** SMB.CONF ***

[global]
;       Most Windows systems default to WORKGROUP
        workgroup = WORKGROUP
        server string = Samba Server Version %v
        netbios name = PIXIES

        interfaces = lo 192.168.0.0/24
        hosts allow = 127. 192.168.0.
        hostname lookups = yes

        log file = /var/log/samba/samba.log.%m
        max log size = 50

        security = user
        passdb backend = tdbsam
        guest account = nobody
        load printers = no

        fruit:aapl = yes
        fruit:nfs_aces = no
        unix extensions = no

[User]
        comment = User Files
        path = /share/samba/user
        directory mask = 0775
        create mask = 0774
        force directory mode = 0775
        force create mode = 0774
        writable = yes
        browseable = yes
        guest ok = no
        write list = @home
        valid users = @home, macuser, pcuser

        veto files = /.AppleDB/.AppleDouble/.AppleDesktop/:2eDS_Store/Network Trash Folder/Temporary Items/TheVolumeSettingsFolder/.@__thumb/.@__desc/:2e*/.@__qini/.@upload_cache/.@qsys/.digest/
        delete veto files = yes

        vfs objects = catia fruit streams_xattr recycle
        ea support = yes
        fruit:aapl = yes
        fruit:encoding = native
        fruit:locking = none
        fruit:metadata = stream
        fruit:resource = file

        recycle:repository = @RecycleBin
        recycle:directory_mode = 2775
        recycle:keeptree = yes
        recycle:versions = yes
        recycle:touch = yes
        recycle:exclude = *.tmp,*.temp,*.o,*.obj,~$*,*.~??,~*.*,*.TMP,*.TEMP,lock.*,.~lock.*,LOCK.*,*.lock,*.~lock,*.LNK,*.lnk,*.ldb,._*
        recycle:minsize = 1

Version-Release number of selected component (if applicable):
Name        : samba
Arch        : x86_64
Version     : 4.9.1
Release     : 10.el7_7

Comment 2 Isaac Boukris 2020-01-02 10:12:10 UTC
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.

Comment 3 LP 2020-02-27 18:11:04 UTC
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.

Comment 4 amitkuma 2020-03-03 12:30:11 UTC
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

Comment 5 LP 2020-03-03 13:54:12 UTC
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.

Comment 6 Isaac Boukris 2020-03-04 12:14:15 UTC
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.

Comment 8 amitkuma 2020-03-05 10:52:42 UTC
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?

Comment 12 LP 2020-03-05 13:36:02 UTC
Created attachment 1667765 [details]
Samba log - File delete

Comment 13 LP 2020-03-05 13:37:22 UTC
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

Comment 14 Isaac Boukris 2020-03-05 13:42:53 UTC
(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.

Comment 15 Isaac Boukris 2020-03-05 14:54:50 UTC
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.

Comment 17 LP 2020-03-05 16:15:55 UTC
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).

Comment 18 Isaac Boukris 2020-03-05 16:29:47 UTC
Guenther also points out there were some changes around vfs_fruit in recent versions, i'll ask upstream.

Comment 19 Isaac Boukris 2020-03-10 10:04:45 UTC
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.

Comment 20 LP 2020-03-10 10:50:59 UTC
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.

Comment 21 Isaac Boukris 2020-03-11 11:04:51 UTC
(In reply to LP from comment #20)

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

Comment 22 LP 2020-03-11 11:09:31 UTC
(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.

Comment 23 Isaac Boukris 2020-03-19 07:47:26 UTC
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.

Comment 24 LP 2020-03-23 07:41:53 UTC
(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.

Comment 25 Isaac Boukris 2020-03-24 19:07:45 UTC
(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!


Note You need to log in before you can comment on or make changes to this bug.