TL;DR seems to be, which (if true) is worrisome because issues may increase as they become common.
Although I still can’t get the CIFS VFS: Send error in read = -4, I tried upgrading my Linux Mint 18.1 to see when any issues arose. Originally it was 4.4.0-197-generic. 18.3 stayed there, but gave an offer for 4.4.0-200-generic which I took. Still fine. 19 stayed there and stayed fine, then upgrade to 19.3 broke the Cinnamon desktop, which caused lots of headaches and basically wound up leaving VM nearly unuseable. Limping along, Update Manager gave an offer for kernel 5.4.0-62-generic. I took it, and the failures began…
$ mono /usr/lib/duplicati/Duplicati.CommandLine.exe backup file:///home/me/DuplicatiBackups/cifs/ /mnt/emptyfiles/ --backup-name=cifs --dbpath=/home/me/.config/Duplicati/NKKCFCKPXB.sqlite --encryption-module= --compression-module=zip --dblock-size=50mb --no-encryption=true --disable-module=console-password-input
Backup started at 1/17/2021 9:15:28 PM
Checking remote backup ...
Listing remote folder ...
Scanning local files ...
0 files need to be examined (0 bytes)
4195 files need to be examined (0 bytes) (still counting)
7958 files need to be examined (0 bytes) (still counting)
Error reported while accessing file: /mnt/emptyfiles/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/Installer/OSX/app-scripts/ => Interrupted system call
Error reported while accessing file: /mnt/emptyfiles/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/Tools/Commandline/RestoreFromPython/ => Interrupted system call
Error reported while accessing file: /mnt/emptyfiles/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/Duplicati/GUI/Duplicati.GUI.TrayIcon/SVGIcons/dark/ => Interrupted system call
Error reported while accessing file: /mnt/emptyfiles/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/Duplicati/Library/Backend/ => Interrupted system call
Error reported while accessing file: /mnt/emptyfiles/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/Duplicati/Library/Backend/GoogleServices/Properties/ => Interrupted system call
Error reported while accessing file: /mnt/emptyfiles/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/Duplicati/Library/Backend/OAuthHelper/Properties/ => Interrupted system call
9510 files need to be examined (53.24 MB)
8262 files need to be examined (53.24 MB)
6920 files need to be examined (53.24 MB)
5608 files need to be examined (53.24 MB)
4308 files need to be examined (53.24 MB)
2967 files need to be examined (53.24 MB)
1789 files need to be examined (51.95 MB)
Error reported while accessing file: /mnt/emptyfiles/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/duplicati-2.0.5.1-2.0.5.1_beta_2020-01-18/Installer/debian/debian/ => Interrupted system call
1551 files need to be examined (40.60 MB)
1478 files need to be examined (33.67 MB)
1334 files need to be examined (18.66 MB)
1024 files need to be examined (14.51 MB)
583 files need to be examined (8.53 MB)
294 files need to be examined (4.18 MB)
Uploading file (21.26 MB) ...
Uploading file (202.24 KB) ...
Uploading file (214.11 KB) ...
Checking remote backup ...
Listing remote folder ...
Verifying remote backup ...
Remote backup verification completed
Downloading file (214.11 KB) ...
Downloading file (202.24 KB) ...
Downloading file (21.26 MB) ...
0 files need to be examined (0 bytes)
Duration of backup: 00:01:25
Remote files: 3
Remote size: 21.66 MB
Total remote quota: 18.58 GB
Available remote quota: 4.22 GB
Files added: 11539
Files deleted: 0
Files changed: 0
Data uploaded: 21.66 MB
Data downloaded: 21.66 MB
Backup completed successfully!
$ dmesg -T | grep CIFS
[Sun Jan 17 21:14:42 2021] CIFS: Attempting to mount //127.0.0.1/emptyfiles
[Sun Jan 17 21:15:40 2021] CIFS VFS: Close unmatched open
[Sun Jan 17 21:15:41 2021] CIFS VFS: Close unmatched open
[Sun Jan 17 21:15:41 2021] CIFS VFS: Close unmatched open
[Sun Jan 17 21:15:41 2021] CIFS VFS: Close unmatched open
[Sun Jan 17 21:15:42 2021] CIFS VFS: Close unmatched open
[Sun Jan 17 21:15:42 2021] CIFS VFS: Close unmatched open
[Sun Jan 17 21:16:18 2021] CIFS VFS: Close unmatched open
Because it seemed like all the errors were on folders, I tested with just folders, then thinking that maybe folder errors prevented seeing the contents, added a file in each folder. It’s changed a bit, but current is:
perl -e ‘for ($n=0; $n < 1000; $n++) { $path = sprintf(“%04d”, $n); mkdir $path; open my $fh, “> $path/empty.txt” }’
(or it might be 100 or 10000 depending on difficulty of hitting it. This is still hard to hit with my test setup)
Testing is all on-VM with an emptyfiles folder shared by Samba and SMB3 mounted at /mnt/emptyfiles. What exactly does one have to do (without requiring special equipment) to hit more issues more easily?
Because the system was so broken, I thought I’d make a new VM, and tried some Ubuntu 20.10, but the error didn’t reproduce as well, so I made a fresh Linux Mint 19.3 VM and an error began happening again.
$ strace -f -tt -o /tmp/strace.log -C -y mono /usr/lib/duplicati/Duplicati.CommandLine.exe backup file:///home/me/DuplicatiBackups/cifs/ /mnt/emptyfiles/ --backup-name=cifs --dbpath=/home/me/.config/Duplicati/NKKCFCKPXB.sqlite --encryption-module= --compression-module=zip --dblock-size=50mb --no-encryption=true --disable-module=console-password-input --log-file=/tmp/cifs.log --log-file-log-level=verbose
had four errors after I took a 10000 folder test area and perturbed it a little by resetting up 1000 of them.
Error reported while accessing file: /mnt/emptyfiles/1145/ => Interrupted system call
Error reported while accessing file: /mnt/emptyfiles/8178/ => Interrupted system call
Error reported while accessing file: /mnt/emptyfiles/9252/ => Interrupted system call
Failed to read timestamp on "/mnt/emptyfiles/8902/" => Interrupted system call
Next level down was the Duplicati verbose log:
2021-01-20 07:29:25 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: /mnt/emptyfiles/1145/
System.IO.IOException: Interrupted system call
at System.IO.Enumeration.FileSystemEnumerator`1[TResult].FindNextEntry (System.Byte* entryBufferPtr, System.Int32 bufferLength) [0x0004c] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Enumeration.FileSystemEnumerator`1[TResult].MoveNext () [0x00054] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.Collections.Generic.LargeArrayBuilder`1[T].AddRange (System.Collections.Generic.IEnumerable`1[T] items) [0x0003d] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.Collections.Generic.EnumerableHelpers.ToArray[T] (System.Collections.Generic.IEnumerable`1[T] source) [0x00033] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.MonoLinqHelper.ToArray[T] (System.Collections.Generic.IEnumerable`1[T] source) [0x00000] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Directory.GetDirectories (System.String path, System.String searchPattern, System.IO.EnumerationOptions enumerationOptions) [0x00009] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Directory.GetDirectories (System.String path) [0x0000b] in <d13c8b563008422a8c5aaec0a74089cc>:0
at Duplicati.Library.Snapshots.SnapshotBase.ListFolders (System.String localFolderPath) [0x00000] in <f08558429eba42d081f51cfe1f70cf5a>:0
at Duplicati.Library.Utility.Utility+<EnumerateFileSystemEntries>d__20.MoveNext () [0x00113] in <b0ec73cdc8b845289fe2e9bdf696ccd0>:0
2021-01-20 07:30:27 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: /mnt/emptyfiles/8178/
System.IO.IOException: Interrupted system call
at System.IO.Enumeration.FileSystemEnumerator`1[TResult].FindNextEntry (System.Byte* entryBufferPtr, System.Int32 bufferLength) [0x0004c] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Enumeration.FileSystemEnumerator`1[TResult].MoveNext () [0x00054] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.Collections.Generic.LargeArrayBuilder`1[T].AddRange (System.Collections.Generic.IEnumerable`1[T] items) [0x0003d] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.Collections.Generic.EnumerableHelpers.ToArray[T] (System.Collections.Generic.IEnumerable`1[T] source) [0x00033] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.MonoLinqHelper.ToArray[T] (System.Collections.Generic.IEnumerable`1[T] source) [0x00000] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Directory.GetFiles (System.String path, System.String searchPattern, System.IO.EnumerationOptions enumerationOptions) [0x00009] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Directory.GetFiles (System.String path) [0x0000b] in <d13c8b563008422a8c5aaec0a74089cc>:0
at Duplicati.Library.Snapshots.SnapshotBase.ListFiles (System.String localFolderPath) [0x00000] in <f08558429eba42d081f51cfe1f70cf5a>:0
at Duplicati.Library.Utility.Utility+<EnumerateFileSystemEntries>d__20.MoveNext () [0x00213] in <b0ec73cdc8b845289fe2e9bdf696ccd0>:0
2021-01-20 07:30:39 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: /mnt/emptyfiles/9252/
System.IO.IOException: Interrupted system call
at System.IO.Enumeration.FileSystemEnumerator`1[TResult].FindNextEntry (System.Byte* entryBufferPtr, System.Int32 bufferLength) [0x0004c] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Enumeration.FileSystemEnumerator`1[TResult].MoveNext () [0x00054] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.Collections.Generic.LargeArrayBuilder`1[T].AddRange (System.Collections.Generic.IEnumerable`1[T] items) [0x0003d] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.Collections.Generic.EnumerableHelpers.ToArray[T] (System.Collections.Generic.IEnumerable`1[T] source) [0x00033] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.MonoLinqHelper.ToArray[T] (System.Collections.Generic.IEnumerable`1[T] source) [0x00000] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Directory.GetDirectories (System.String path, System.String searchPattern, System.IO.EnumerationOptions enumerationOptions) [0x00009] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.Directory.GetDirectories (System.String path) [0x0000b] in <d13c8b563008422a8c5aaec0a74089cc>:0
at Duplicati.Library.Snapshots.SnapshotBase.ListFolders (System.String localFolderPath) [0x00000] in <f08558429eba42d081f51cfe1f70cf5a>:0
at Duplicati.Library.Utility.Utility+<EnumerateFileSystemEntries>d__20.MoveNext () [0x00113] in <b0ec73cdc8b845289fe2e9bdf696ccd0>:0
2021-01-20 07:35:40 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-TimestampReadFailed]: Failed to read timestamp on "/mnt/emptyfiles/8902/"
System.IO.IOException: Interrupted system call
at System.IO.FileStatus.EnsureStatInitialized (System.ReadOnlySpan`1[T] path, System.Boolean continueOnError) [0x00039] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.FileStatus.GetLastWriteTime (System.ReadOnlySpan`1[T] path, System.Boolean continueOnError) [0x00000] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.FileSystemInfo.get_LastWriteTimeCore () [0x00011] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.FileSystemInfo.get_LastWriteTimeUtc () [0x00000] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.FileSystemInfo.get_LastWriteTime () [0x00000] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.FileSystem.GetLastWriteTime (System.String fullPath) [0x00009] in <d13c8b563008422a8c5aaec0a74089cc>:0
at System.IO.File.GetLastWriteTimeUtc (System.String path) [0x00006] in <d13c8b563008422a8c5aaec0a74089cc>:0
at Duplicati.Library.Snapshots.SnapshotBase.GetLastWriteTimeUtc (System.String localPath) [0x00000] in <f08558429eba42d081f51cfe1f70cf5a>:0
at Duplicati.Library.Main.Operation.Backup.MetadataPreProcess+<>c__DisplayClass2_0.<Run>b__0 (<>f__AnonymousType7`3[<Input>j__TPar,<StreamBlockChannel>j__TPar,<Output>j__TPar] self) [0x000f8] in <8f1de655bd1240739a78684d845cecc8>:0
A heuristic to find the four errors is below. Three were getdents to read directory entries, and one was an lstat to get file status. Heuristic method handles system calls which split into “unfinished” and “resumed”, but assumes the thread (first column) doesn’t intermix with getdents from other threads (if that happens, then you have to go looking manually, e.g. with less). In all cases a tgkill (not shown) did the interruption.
You can see from the man pages that neither getdents nor lstat are supposed to give EINTR, yet they did.
$ fgrep 'getdents' /tmp/strace.log | egrep -B 1 'getdents.*EINTR' | fgrep 'getdents'
13739 07:29:25.548372 getdents(16</mnt/emptyfiles/7983>, /* 0 entries */, 1048576) = 0
13737 07:29:25.598998 getdents(12</mnt/emptyfiles/1145>, 0x7f61ec0261d0, 1048576) = -1 EINTR (Interrupted system call)
13741 07:30:27.171411 getdents(16</mnt/emptyfiles/8178> <unfinished ...>
13741 07:30:27.203564 <... getdents resumed> , 0x7f61f80307d0, 1048576) = -1 EINTR (Interrupted system call)
13744 07:30:39.190608 getdents(16</mnt/emptyfiles/9252> <unfinished ...>
13744 07:30:39.226441 <... getdents resumed> , 0x5602c7c3b0e0, 1048576) = -1 EINTR (Interrupted system call)
$ egrep 'lstat.*EINTR' /tmp/strace.log
13736 07:35:40.582932 lstat("/mnt/emptyfiles/8902", 0x7f61e54fd2c0) = -1 EINTR (Interrupted system call)
$