Duplicati freezes during backup or fails with unknown error due to Remote (SSH) Disk Full

[arberg]

• I have searched open and closed issues for duplicates.
• I have searched the forum for related topics.

---

Issue

When Remote SSH runs out of disk-space, Duplicati fails by

1. either hanging
2. or giving an unknown error in the GUI with no clear cause, and nothing is written in the local-db logs (click logs in gui-error) but with something written in the external log-file (information level).

These two separate behaviors should probably be interpreted at two separate bugs (or more precisely: I'm pretty sure they require two separate code-changes).

Environment info

• Duplicati version: 2.0.6.3_beta_2021-06-17
• Operating system: Linux, docker, linuxserver/duplicati
• Backend: SSH, Linux

Steps to reproduce

Note I experience two different behaviors for the same underlying issue. Either it'll give me a GUI error as shown in the screenshot further down, or it will just hang in processing as ssh upload fails. Note that the GUI error happened on all my jobs that had previously succeeded (ie. first and following times backend ran full), and the hang-issue came after I recreated the local database (I didn't know it was an out-of-space error at that time).

1. Fill Remote
2. run backup with a (1GB?) file to put
3. Duplicati gets stuck in Processing in GUI on that file, while logs show as last line Backend event: Put - Started: . Also lsof indicates mono process still has open handles to the file being backed up. And the remote linux log says No space left on device

2022-02-02 10:00:02 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b54b54a6639f34f1281c35eeb81fb2838.dblock.zip.aes (147.03 MB)

Screenshots

Remote linux OS log (the log from the remote system we are uploading the backup to):
Feb 2 01:00:10 UnRaidBackup sftp-server[27869]: error: process_write: write: No space left on device

Debug log

Information level log from backup. Note that its the last few lines that are from this backup. The first lines probably indicate cleanup due to previous backups put-problems. It'll hang all night from my experience (forever?).

2022-02-02 09:56:01 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2022-02-02 09:56:03 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2022-02-02 09:56:15 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (57.16 KB)
2022-02-02 09:56:18 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-KeepIncompleteFile]: keeping protected incomplete remote file listed as Temporary: duplicati-20220201T220121Z.dlist.zip.aes
2022-02-02 09:56:18 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b36bf4e6d45bf4c54a283913a4ced8674.dblock.zip.aes
2022-02-02 09:56:18 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-Remove incomplete file]: removing incomplete remote file listed as Uploading: duplicati-bf91c0e827e6b4bf3835078dbac423491.dblock.zip.aes
2022-02-02 09:56:18 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-bf91c0e827e6b4bf3835078dbac423491.dblock.zip.aes (147.04 MB)
2022-02-02 09:56:18 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-bf91c0e827e6b4bf3835078dbac423491.dblock.zip.aes (147.04 MB)
2022-02-02 09:56:20 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-PromotingCompleteFile]: promoting uploaded complete file from Uploading to Uploaded: duplicati-ba5e43643fa744104b2120ffbb9716dcd.dblock.zip.aes
2022-02-02 09:56:20 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b6b38df471ac746e4bb386947590ed669.dblock.zip.aes
2022-02-02 09:56:20 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b994ec2902e8a42be9da555f1f84771af.dblock.zip.aes
2022-02-02 09:56:20 +01 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b23b8c12352da4765926c74d23ac60ec5.dblock.zip.aes
2022-02-02 09:56:20 +01 - [Information-Duplicati.Library.Main.Operation.Backup.UploadSyntheticFilelist-PreviousBackupFilelistUpload]: Uploading filelist from previous interrupted backup
2022-02-02 09:56:22 +01 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-ba5e43643fa744104b2120ffbb9716dcd.dblock.zip.aes
2022-02-02 09:56:22 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ief0607c9e2734cc28e96869940d95156.dindex.zip.aes (1.64 KB)
2022-02-02 09:56:23 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ief0607c9e2734cc28e96869940d95156.dindex.zip.aes (1.64 KB)
2022-02-02 10:00:02 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b54b54a6639f34f1281c35eeb81fb2838.dblock.zip.aes (147.03 MB)

Local logs when GUI shows error (but link to logs is empty)

Renci.SshNet.Common.SshException: Failure
  at Renci.SshNet.Sftp.SftpSession.RequestOpen (System.String path, Renci.SshNet.Sftp.Flags flags, System.Boolean nullOnError) [0x0008c] in <8c66a76a693c4e52b456ec0712c863dd>:0 
  at Renci.SshNet.SftpClient.InternalUploadFile (System.IO.Stream input, System.String path, Renci.SshNet.Sftp.Flags flags, Renci.SshNet.Sftp.SftpUploadAsyncResult asyncResult, System.Action`1[T] uploadCallback) [0x0004f] in <8c66a76a693c4e52b456ec0712c863dd>:0 
  at Renci.SshNet.SftpClient.UploadFile (System.IO.Stream input, System.String path, System.Boolean canOverride, System.Action`1[T] uploadCallback) [0x00017] in <8c66a76a693c4e52b456ec0712c863dd>:0 
  at Renci.SshNet.SftpClient.UploadFile (System.IO.Stream input, System.String path, System.Action`1[T] uploadCallback) [0x00000] in <8c66a76a693c4e52b456ec0712c863dd>:0 
  at Duplicati.Library.Backend.SSHv2.PutAsync (System.String remotename, System.IO.Stream stream, System.Threading.CancellationToken cancelToken) [0x00012] in <a59f77bd59444f6a92f1348e2a58cec6>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader.DoPut (Duplicati.Library.Main.Operation.Common.BackendHandler+FileEntryItem item, Duplicati.Library.Interface.IBackend backend, System.Threading.CancellationToken cancelToken) [0x003a4] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader+<>c__DisplayClass20_0.<UploadFileAsync>b__0 () [0x0010a] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader.DoWithRetry (System.Func`1[TResult] method, Duplicati.Library.Main.Operation.Common.BackendHandler+FileEntryItem item, Duplicati.Library.Main.Operation.Backup.BackendUploader+Worker worker, System.Threading.CancellationToken cancelToken) [0x0017c] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader.DoWithRetry (System.Func`1[TResult] method, Duplicati.Library.Main.Operation.Common.BackendHandler+FileEntryItem item, Duplicati.Library.Main.Operation.Backup.BackendUploader+Worker worker, System.Threading.CancellationToken cancelToken) [0x003a5] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader.UploadFileAsync (Duplicati.Library.Main.Operation.Common.BackendHandler+FileEntryItem item, Duplicati.Library.Main.Operation.Backup.BackendUploader+Worker worker, System.Threading.CancellationToken cancelToken) [0x000da] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader.UploadBlockAndIndexAsync (Duplicati.Library.Main.Operation.Backup.VolumeUploadRequest upload, Duplicati.Library.Main.Operation.Backup.BackendUploader+Worker worker, System.Threading.CancellationToken cancelToken) [0x00098] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader.<Run>b__13_0 (<>f__AnonymousType12`1[<Input>j__TPar] self) [0x00780] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.Backup.BackendUploader.<Run>b__13_0 (<>f__AnonymousType12`1[<Input>j__TPar] self) [0x007d7] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at CoCoL.AutomationExtensions.RunTask[T] (T channels, System.Func`2[T,TResult] method, System.Boolean catchRetiredExceptions) [0x000d5] in <9a758ff4db6c48d6b3d4d0e5c2adf6d1>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.FlushBackend (Duplicati.Library.Main.BackupResults result, CoCoL.IWriteChannel`1[T] uploadtarget, System.Threading.Tasks.Task uploader) [0x000f2] in <e60bc008dd1b454d861cfacbdd3760b9>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00cb2] in <e60bc008dd1b454d861cfacbdd3760b9>:0 

Possibly related issues

Note that none of these issues indicate remote disk full as the underlying cause of the issue.
#2968
#2351

Thoughts...

Idea: If possible it would be valuable to add remote free-space to information level log on backup start+stop. That would make debugging disk space issues easier.

[ts678]

The provided stack trace and

duplicati/Duplicati/Library/Backend/SSHv2/SSHv2Backend.cs

Lines 262 to 268 in 27ff8cd

	public Task PutAsync(string remotename, System.IO.Stream stream, CancellationToken cancelToken)
	{
	CreateConnection();
	ChangeDirectory(m_path);
	m_con.UploadFile(stream, remotename);
	return Task.FromResult(true);
	}

suggest this could be related to SSH.NET's SftpClient.UploadFile hangs indefinitely when server has run out of space #343.

Idea: If possible it would be valuable to add remote free-space to information level log

duplicati/Duplicati/Library/Backend/SSHv2/SSHv2Backend.cs

Line 37 in 27ff8cd

public class SSHv2 : IStreamingBackend, IRenameEnabledBackend

so does not implement

duplicati/Duplicati/Library/Interface/IQuotaEnabledBackend.cs

Lines 8 to 19 in beaf035

	/// <summary>
	/// Backends that support reporting quota should implement this interface
	/// </summary>
	public interface IQuotaEnabledBackend : IBackend
	{
	/// <summary>
	/// Gets information about the quota on this backend.
	/// This may return null if the particular host implementation
	/// does not support quotas, but the backend does.
	/// </summary>
	IQuotaInfo Quota { get; }
	}

which is seemingly the best call because SSH.NET doesn't appear to either, and this isn't really in the core specifications.
SFTP Standards shows SFTP v3 without it. Later little-used drafts and extensions added better space errors and metrics.

Until this can be looked into further, one advantage of not being a quota enabled backend is you can set limit yourself:

quota-size

This value can be used to set a known upper limit on the amount of space a backend has. If the backend reports the size itself, this value is ignored.

[duplicatibot]

This issue has been mentioned on Duplicati. There might be relevant details there:

https://forum.duplicati.com/t/quota-size-check-to-not-be-exceeded/17268/34