Duplicati lock up

Xavron · June 21, 2021, 7:58pm

Just got this. Not much time on analyzing but at least with

Operation Put with file duplicati-ib4e6856fa8a6408e9c406330441f0f2c.dindex.zip.aes attempt 6 of 6 failed with message: disk I/O error disk I/O error

It is exiting from DoWithRetry() with an Exception thrown:

if (retryCount == m_options.NumberOfRetries)
    throw;

Finally {} block runs and for loop exits

if (cancelToken.IsCancellationRequested)
    return false;

github.com

duplicati/duplicati/blob/master/Duplicati/Library/Main/Operation/Backup/BackendUploader.cs#L313


      
          

              return await DoWithRetry(async () =>

              {

                  if (item.IsRetry)

                      await RenameFileAfterErrorAsync(item).ConfigureAwait(false);

                  await DoPut(item, worker.Backend, cancelToken).ConfigureAwait(false);

              },

              item, worker, cancelToken).ConfigureAwait(false);

          }

          

          private async Task<bool> DoWithRetry(Func<Task> method, FileEntryItem item, Worker worker, CancellationToken cancelToken)

          {

              item.IsRetry = false;

              var retryCount = 0;

          

              for (retryCount = 0; retryCount <= m_options.NumberOfRetries; retryCount++)

              {

                  if (m_options.RetryDelay.Ticks != 0 && retryCount != 0)

                  {

                      var delay = Library.Utility.Utility.GetRetryDelay(m_options.RetryDelay, retryCount, m_options.RetryWithExponentialBackoff);

                      await Task.Delay(delay).ConfigureAwait(false);

The sync UI never exits despite that and 6 out of 6 fails. Nothing else shows up in the current logs after that.

From there I will need further logs and/or locate code that will stop the sync. Depending on where that’s done at.

Additional. This tracks back to:

case DuplicatiOperation.Backup: in /Server/Runner where it starts but the log for it exiting is never reached. Exception log there also doesn’t appear to show up.

Xavron · June 22, 2021, 12:25pm

Third issue here to track from me. So at least three or four causing the end result so far.

This backup is still “running” and the UI speed is only slightly dropping but its very far past the normal completion time and doesn’t appear to really be doing anything.

Current end of log with UI stuck far past normal backup times...
CommitAddBlockToOutputFlush took 0:00:00:01.640
Starting - CommitAddBlockToOutputFlush

DoPut() ends: Backend event: Put - Completed: duplicati-i85dd6ff4d4944abeb0e50d8edf8cb677.dindex.zip.aes (30.62 KB)

CommitAfterUpload: CommitAfterUpload took 0:00:00:00.046…

DoWithRetry() returns from UploadFileAsync() with finally {} block executing

File changed, adding dir, etc until CommitAddBlockToOutputFlush then
CommitAddBlockToOutputFlush took and that’s it.

I will not be adding more to this thread until I find something that solves these.

PaulHop · June 22, 2021, 1:15pm

Sorry Xavron, I’m snowed under at the moment (more than usual) with tight timelines… I’ll get back to this thread when I can but it will be at least a few days.

Xavron · June 26, 2021, 10:39pm

No problem

In the mean time, I narrowed down one problem point to what looks like the final issue for that one anyway. Testing a test fix and don’t really want to post anything until I can confirm a fix works and the problem is as suspected.

Don’t know how it will relate to others. Could only hope it solves all of them but probably won’t. Could cause another problem lol.

Xavron · August 1, 2021, 10:27pm

Edit - scratch that. It just happened of course after I post no longer being able to reproduce it lol.

This is first occurrence during a backup and where its last seen in my logs (last entry for 31 minutes): duplicati/DataBlockProcessor.cs at master · duplicati/duplicati · GitHub

Preceded by a bunch of loops through the while loop there then CommitAddBlockToOutputFlush & CommitAddBlockToOutputFlush took and then hits that Exception.

31 minutes later it does a few of these: Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched:

The transfer rate continues to drop for hours with no other UI movement.

Also, the code execution according to the logs goes from:
var newBlock = await database.AddBlockAsync(b.HashKey, b.Size, blockvolume.VolumeID);
b.TaskCompletion.TrySetResult(newBlock);

And then right to

catch (Exception ex)

This is also going back to another issue I noticed. The throwing of an Exception is going right back to duplicati/BackupHandler.cs at master · duplicati/duplicati · GitHub

The Task.WhenAll() may not be dealing with Exceptions in a useful way for that.

Either way, the Duplicati gets into a broken state right here.

Xavron · August 2, 2021, 2:47pm

(Edit - The actual Exception when Duplicati gets stuck is “Disk I/O error” in most if not all recent cases (not related to the below Exception seen). Currently drilling down into that Exception reason further and attempt some changes to see how Duplicati responds. Though the below one appears to at least be passable so far from what I can see. The I/O error is not with current code.)

Definitely Duplicati is using CoCoL project here which is throwing Exceptions (still waiting to see what the Exception is when it gets messed up).

PaulHop above also highlights a line with CoCoL showing in his run through with this on his side Duplicati lock up - #30 by PaulHop

An error I see matches what’s found here:

github.com

kenkendk/cocol/blob/028e3497300e3c2b4c3447c2940fe83765d3deb5/src/CoCoL/Exceptions.cs

using System;
#if !DISABLE_SERIALIZATION
using System.Runtime.Serialization;
#endif

namespace CoCoL
{
	/// <summary>
	/// Exception which is thrown when attempting to access a retired channel
	/// </summary>
#if !DISABLE_SERIALIZATION
	[Serializable]
#endif
	public class RetiredException : Exception
	{
        /// <summary>
        /// The name of the channel that is retired
        /// </summary>
        public string ChannelName { get; private set; }

This file has been truncated. show original

github.com

duplicati/duplicati/blob/beaf03562fdcf4425e962085bdf7175d6a465f49/Duplicati/Library/Main/Operation/Backup/Channels.cs

//  Copyright (C) 2015, The Duplicati Team
//  http://www.duplicati.com, info@duplicati.com
//
//  This library is free software; you can redistribute it and/or modify
//  it under the terms of the GNU Lesser General Public License as
//  published by the Free Software Foundation; either version 2.1 of the
//  License, or (at your option) any later version.
//
//  This library is distributed in the hope that it will be useful, but
//  WITHOUT ANY WARRANTY; without even the implied warranty of
//  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
//  Lesser General Public License for more details.
//
//  You should have received a copy of the GNU Lesser General Public
//  License along with this library; if not, write to the Free Software
//  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
using System;
using CoCoL;

namespace Duplicati.Library.Main.Operation.Backup

This file has been truncated. show original

Xavron · August 4, 2021, 2:44am

Alright so 100% reproducible now. Just throw an Exception in the while loop here duplicati/DataBlockProcessor.cs at master · duplicati/duplicati · GitHub

eg

var newBlock = await database.AddBlockAsync(b.HashKey, b.Size, blockvolume.VolumeID);
throw new Exception("Disk I/O error");

and the UI gets completely stuck and the code stops executing beyond what looks like some little itty bitty possibility of code in any other threads outside of there that can. But this completely breaks Duplicati so anything else that just might run is of no importance.

Unfortunately CoCoL is thrown in the mix which might be the problem. Almost seems like some weird issue between CoCoL, Exception throwing, and Task.WhenAll() use.

Throwing an Exception should not cause the code to stop executing but that’s exactly what it appears to do since nothing appears to happen after it.

I will have to try to write CoCoL out of it.

Xavron · August 4, 2021, 5:50am

Partially solved! Not CoCoL. Apparently, adding a timeout to WhenAll() allows the UI to continue and the backup to finish albeit in my test as a failed backup but at least it frees up the UI.

So halfway there lol

Updates added to here for now:

A test to improve Disk i/o error’s bad effect has proven successful (timeout not necessary with this one): Backup fails but completes within normal incremental backup time of a few minutes. Next time the backup runs, it is successful. Both unblock the UI. Still needs further testing.

Two steps to go at this time. To find out the real reason why that error is being thrown (if its SQL or an actual disk problem but either way Duplicati must deal with it) and to make sure all tasks have check and exit’s to the tasks where needed so WhenAll()'s use isn’t horribly negative when an Exception is thrown unexpectedly.

Could be mistaken at the moment but the disk i/o error is looking like at least one cause is by Duplicati in the block processing for use with the sqlite db. Will have to run some tests.
Definitely looks like it should be the code. Disk i/o error appears with Duplicati’s backup rename event of two of its backup files along with the sqlite-journal in there also (in other words it affects Duplicati’s own stuff and also next backup runs fine so its going to be very interesting).

Xavron · August 9, 2021, 11:57am

WhenAll() UI blocking issue, I’m now attaching to this on github Backup job hangs in the middle of the work · Issue #3683 · duplicati/duplicati · GitHub

The “Disk i/o error” am still waiting for Duplicati to rename files which it appears to be connected to. No rename, no “Disk i/o error”. Have a possible fix in testing for that, but until it happens again (its taking its good old time now when I want it most), can’t be sure as the fix may require a bit more.

Either way, happy to see two long standing bad issues (people complained about both of these years ago) with Duplicati coming to an end.

Updates attached to this:

The disk i/o error appearance changed when I added the attempted fix. It is definitely throwing at that spot but seemingly unknowingly now. Spotted another log after that where it throws the error then later during the same backup its all of a sudden working again. So this one will take a bit of time between waiting and testing. But looks like this is what causes the renaming to be tried as the log now shows it comes before that.
Latest log shows it happened with CommitAfterUpload. Upload was successful so the info should be committed to the db just fine. The db also works fine. I’m currently working on the theory of a race condition with lower performance hardware based on what I see happening in the logs compared to a higher performance one. That could take much longer. Did notice someone years ago felt it was file accessibility but it is not that (I tried to force that and it didn’t cause this issue) - I tested the same setup here as the other computer and it doesn’t happen here. Duplicati should deal with it anyway.
Have to put this on pause for now. Technically, its “solved” for me though with the various checks I have it. Just don’t know to what extent. Its at least not to the extent that I want it solved. The backup does complete “successfully” but haven’t looked to see what that actually fully means with the checks alone. Still, Duplicati now works like it should instead of the way it is for everyone else.

Xavron · September 29, 2021, 1:12pm

Further on the disk i/o error (normally seen as causing the lock up for me):

Looks to be only caused by very specific files (and only those files) such as Duplicati db in /AppData on certain systems as far as I can tell. One system doesn’t ever seem to have a problem backing it up but the other one often throws disk i/o on it and that’s one error thrown during the WhenAll() that causes the total lockup of the Duplicati UI.

I intend to look into why certain files do that as there’s probably something Duplicati should be looking at so as to not attempt to back it up, or in the worst case it should at least throw the disk i/o error, then remove that file from the backup and continue - since there’s a ton of stuff in the code here, it would take me a while to sort through what exactly needs to be done, and so I may not go that far with this.

For now, just blocking the files where this happens such as Duplicati’s AppData folder from the backup, appears to fix the situation until a better way to handle it is implemented. I have backups running without anything bad showing up for well over a week now and that wasn’t possible before.

Theory: At least with Duplicati’s db file, it could in theory be getting into a situation where its attempting to write and read the file at the same time. Perhaps with a slow enough system (eg the one where its happening for me), it runs into a problem and disk i/o error gets thrown. Could include or be another difference such as larger backups that I didn’t duplicate on other systems without the problem.

ts678 · September 29, 2021, 2:28pm

Thanks for continuing to look into this. There have been some forum reports where having Duplicati NOT try to back up its own database area (I guess that’s what you mean) has been suggested. It’s pointless trying to backup the database from the running job, because it’ll be instantly obsolete. It might also suffer some weird interactions (as I think you’re suggesting) where it interferes with itself over something like DB file access…

warwickmm · September 29, 2021, 4:06pm

There was a brief attempt at ignoring Duplicati database files here:

github.com/duplicati/duplicati

Always exclude job-specific database files from backup

duplicati:master ← warwickmm:always_exclude_job_database

opened 06:05PM - 11 Dec 20 UTC

warwickmm

+109 -8

This excludes job-specific SQLite files from the backup. There is no benefit to… backing these up, and if the database needs to restored, it should be recreated from the backend files to ensure consistency. The files being excluded are: * The job-specific database file (`<database>`) * The database rollback journals (`<database>-journal`) * Write-ahead Log (WAL) files (`<database>-wal`) * Shared-memory files (`<database>-shm`) According to the [documentation](https://www.sqlite.org/draft/atomiccommit.html#_the_super_journal_file), the super journal file does not have a naming convention that is part of the specification. As such, we do not exclude it: > The next step in a multi-file commit is the creation of a "super-journal" file. The name of the super-journal file is the same name as the original database filename (the database that was opened using the sqlite3_open() interface, not one of the ATTACHed auxiliary databases) with the text "-mjHHHHHHHH" appended where HHHHHHHH is a random 32-bit hexadecimal number. The random HHHHHHHH suffix changes for every new super-journal. > > (Nota bene: The formula for computing the super-journal filename given in the previous paragraph corresponds to the implementation as of SQLite version 3.5.0. But this formula is not part of the SQLite specification and is subject to change in future releases.) We cannot use filters to unconditionally exclude these files, as there exists code paths where filters containing both includes and excludes have a tendency to include unmatched paths, which is probably the safer thing to do if a path is not matched by any (include or exclude) filter. This fixes #1797 and #4308.