Backups suddenly broke with fileset errors and constraint violations after repair

Martin_Smith · August 6, 2024, 7:40am

I’ve been running Duplicati for some time now with no problems. It looks like a few days ago things went wrong.

There were no errors reported in the run on August 1st. But on August 4th I got this:

* 2024-08-04 00:01:15 +01 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error UserInformationException: Unexpected difference in fileset version 0: 01/08/2024 00:01:00 (database id: 53), found 60497 entries, but expected 60696

I read a bunch articles on the forum. I then ran repair on the database and then deleted version 0. I ran the backup again.

That now gets me constraint violations on a bunch of files when the backups run. From the verbose log it’s files like this:

[Warning-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-FailedToAddFile]: Failed while attempting to add unmodified file to database: D:\Media\Images\Weymouth & Portland April 2017\IMG_6572.CR2
code = Constraint (19), message = System.Data.SQLite.SQLiteException (0x800027AF): constraint failed
UNIQUE constraint failed: FilesetEntry.FilesetID, FilesetEntry.FileID

These files aren’t new and presumably have been backed up for months. They don’t seem to be unusual Windows paths or contain strange characters, well maybe except the ‘&’ sign in some but not all of them.

$ find . -name IMG_6572.* -ls | cat -v
281474977263210  12796 -rw-r--r--   1 martin   197121   13099324 Apr 22  2017 ./Weymouth\ &\ Portland\ April\ 2017/IMG_6572.CR2
281474977263211   3504 -rw-r--r--   1 martin   197121    3585123 Apr 22  2017 ./Weymouth\ &\ Portland\ April\ 2017/IMG_6572.JPG

Another example:

[Warning-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-FailedToAddFile]: Failed while attempting to add unmodified file to database: D:\Media\Images\Tankfest June 2018\IMG_7741.JPG
code = Constraint (19), message = System.Data.SQLite.SQLiteException (0x800027AF): constraint failed
UNIQUE constraint failed: FilesetEntry.FilesetID, FilesetEntry.FileID

Results from find command:

$ find . -name IMG_7741.* -ls | cat -v
281474977429145  10508 -rw-r--r--   1 martin   197121   10756482 Jun 30  2018 ./Tankfest\ June\ 2018/IMG_7741.CR2
281474977429146   2020 -rw-r--r--   1 martin   197121    2065364 Jun 30  2018 ./Tankfest\ June\ 2018/IMG_7741.JPG

I’m running 2.0.8.1_beta_2024-05-07 on Windows and I’m not sure what I should do to fix this.

Thanks,

Martin

ts678 · August 6, 2024, 5:35pm

Welcome to the forum @Martin_Smith

I couldn’t find any prior cases with this combination of errors, so this may take some debugging.

Is Linux or similar around somewhere, e.g. in commands you ran just above the Windows note?

Martin_Smith · August 6, 2024, 5:50pm

Thanks for the reply. Not running Linux on this machine, I just had a git bash shell open.

This is a reasonably large backup set (about 250GB in S3 at one of the infrequent access tiers with 50MB chunks) so I’m hoping I won’t have to start again.

I checked the drive for errors and the files it’s complaining about can be opened normally so I don’t think it’s an error in the filesystem.

Martin

ts678 · August 6, 2024, 6:25pm

Channel Pipeline describes the rather complex internal flow. I tried to find main path. It might be:

FileEnumerationProcess.cs → SourcePaths → MetadataPreProcess.cs → ProcessedFiles → FilePreFilterProcess.cs → AcceptedChangedFile → FileBlockProcessor.cs → StreamBlock → StreamBlockSplitter.cs → OutputBlocks → DataBlockProcessor.cs → BackendRequest

and your error message is from FilePreFilterProcess, so still pretty early before the reading of file.

I suppose you could try a log-file=<path> which by defalt would log the warning with a stack trace.

log-file-log-level=verbose will get individual source files, and maybe some further clues, although I guess we have at least a file name that’s upsetting it.

It will make a huge file, but you could try a log at profiling level, which will record things like below:

2024-08-06 05:25:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (757, 12839, 636811898376551414)
2024-08-06 05:25:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (757, 12839, 636811898376551414) took 0:00:00:00.000

Looking in the database might be necessary. Creating a bug report is sometimes enough, but the actual filenames are not in there (for privacy). You looking under direction might also be possible.

Help from a developer who knows the code well would help, but they’re scarce, and usually busy.

Martin_Smith · August 6, 2024, 7:11pm

I’ve got a stack trace from the verbose log. not sure how useful it is.

2024-08-06 08:11:41 +01 - [Warning-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-FailedToAddFile]: Failed while attempting to add unmodified file to database: D:\Media\Images\Tankfest June 2018\IMG_7741.JPG
code = Constraint (19), message = System.Data.SQLite.SQLiteException (0x800027AF): constraint failed
UNIQUE constraint failed: FilesetEntry.FilesetID, FilesetEntry.FileID
   at System.Data.SQLite.SQLite3.Reset(SQLiteStatement stmt)
   at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
   at System.Data.SQLite.SQLiteDataReader.NextResult()
   at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
   at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
   at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteNonQuery(IDbCommand self, Boolean writeLog, String cmd, Object[] values)
   at Duplicati.Library.Main.Database.LocalBackupDatabase.AddUnmodifiedFile(Int64 fileid, DateTime lastmodified, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.<RunOnMain>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<DoRunOnMain>d__2`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.<>c__DisplayClass1_0.<<Run>b__0>d.MoveNext()

ts678 · August 6, 2024, 9:42pm

It kind of confirms what was thought already, which is (probably) that one of these is happening:

github.com

duplicati/duplicati/blob/78ea50c8335772f2684ff39f8e44c22d2836322b/Duplicati/Library/Main/Operation/Backup/FilePreFilterProcess.cs#L101-L115


      
          // Avoid generating a new metadata blob if timestamp has not changed

          // and we only check for timestamp changes

          if (CHECKFILETIMEONLY && !timestampChanged && !isNewFile)

          {

              Logging.Log.WriteVerboseMessage(FILELOGTAG, "SkipCheckNoTimestampChange", "Skipped checking file, because timestamp was not updated {0}", e.Path);                                                

              try

              {

                  await database.AddUnmodifiedAsync(e.OldId, e.LastWrite);

              }

              catch (Exception ex)

              {

                  if (ex.IsRetiredException())

                      throw;

                  Logging.Log.WriteWarningMessage(FILELOGTAG, "FailedToAddFile", ex, "Failed while attempting to add unmodified file to database: {0}", e.Path);

              }

github.com

duplicati/duplicati/blob/78ea50c8335772f2684ff39f8e44c22d2836322b/Duplicati/Library/Main/Operation/Backup/FilePreFilterProcess.cs#L136-L155


      
          // Check if the file is new, or something indicates a change

          var filesizeChanged = filestatsize < 0 || e.LastFileSize < 0 || filestatsize != e.LastFileSize;

          if (isNewFile || timestampChanged || filesizeChanged || e.MetadataChanged)

          {

              Logging.Log.WriteVerboseMessage(FILELOGTAG, "CheckFileForChanges", "Checking file for changes {0}, new: {1}, timestamp changed: {2}, size changed: {3}, metadatachanged: {4}, {5} vs {6}", e.Path, isNewFile, timestampChanged, filesizeChanged, e.MetadataChanged, e.LastWrite, e.OldModified);

              await self.Output.WriteAsync(e);

          }

          else

          {

              Logging.Log.WriteVerboseMessage(FILELOGTAG, "SkipCheckNoMetadataChange", "Skipped checking file, because no metadata was updated {0}", e.Path);

              try

              {

                  await database.AddUnmodifiedAsync(e.OldId, e.LastWrite);

              }

              catch (Exception ex)

              {

                  Logging.Log.WriteWarningMessage(FILELOGTAG, "FailedToAddFile", ex, "Failed while attempting to add unmodified file to database: {0}", e.Path);

              }

              await self.ProgressChannel.WriteAsync(new ProgressEvent() { Filepath = e.Path, Length = filestatsize, Type = EventType.FileSkipped });

          }

The message is the same, but Verbose log would distinguish if you had one. There might be other ways, for example disable-filetime-check looks necessary to go down second path. Do you use it?

Martin_Smith · August 7, 2024, 6:21am

The options on this backup are --no-auto-compact and --no-backend-verification, which I needed for S3 at this storage tier (STANDARD_IA).

I changed the log level to profiling but I don’t see any extra information logged at the time the constraint violation warnings are logged.

Martin_Smith · August 7, 2024, 6:50am

Database file entries for one of the paths it complains about:

sqlite> select * from file where file.path like '%Tankfest June 2018%IMG_7743%';
28836|D:\Media\Images\Tankfest June 2018\IMG_7743.CR2|56835|28300
28837|D:\Media\Images\Tankfest June 2018\IMG_7743.JPG|56837|28301

And I think these are the file set entries:

sqlite> select * from filesetentry where fileid in (28836,28837) order by filesetid;
18|28836|636659454320000000
18|28837|636659454320000000
25|28836|636659454320000000
25|28837|636659454320000000
31|28836|636659454320000000
31|28837|636659454320000000
33|28836|636659454320000000
33|28837|636659454320000000
41|28836|636659454320000000
41|28837|636659454320000000
50|28836|636659454320000000
50|28837|636659454320000000
52|28836|636659454320000000
52|28837|636659454320000000
53|28836|636659454320000000
53|28837|636659454320000000

Martin_Smith · August 10, 2024, 11:02am

I’ve been looking at the fileset inconsistency. From the log and code it does two queries, a simple select and a complex join and expects to get the same answer and doesn’t for the latest fileset:

2024-08-10 00:01:15 +01 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Backup has failed with error: Unexpected difference in fileset version 0: 07/08/2024 06:56:59 (database id: 53), found 60603 entries, but expected 60654

However, if I take both queries from the log and run them from a sqllite client I do get the same number for both queries and it matches the 60654 value from the simpler query.

Martin_Smith · August 10, 2024, 11:48am

Trying to find old sqlite3 versions seems really difficult. By looking at the .net library it seems this corresponds to mysql 3.27.2?

I copied the database file to a linux machine running sqlite 3.45.1 on Fedora Core 40 and got the same answer (60654) as I did on Windows.

I then downloaded an RPM from around the same time as I believe corresponds to the .net library used by Duplicai. I couldn’t find 3.27.2 with rpmfind but I did get 3.26 for Fedora Core 30. If I run the same query with the binary from this file I get a different answer of 60602. Almost the same as the incorrect answer on Windows.

So I’m going to speculate that this is related to the sqlite version used being about 5 years old and is some bug that was since fixed.

Martin_Smith · August 10, 2024, 2:23pm

I’ve run a diff on the output produced by the two versions of sqlite and it includes some of the filenames that were giving trouble with the constraint violations.

I think it’s a reasonable hypothesis now.

ts678 · August 10, 2024, 9:45pm

You ought to at least get what Verbose would show you, as Profiling shows all lesser levels.

2024-08-03 20:20:34 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-SkipCheckNoMetadataChange]: Skipped checking file, because no metadata was updated C:\bin\rclone_wrap_random.log
2024-08-03 20:20:34 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (752, 20, 637332197784291173)

You can also see if somehow the same path is coming up twice in the same backup run.
Duplicati now works around a Windows quirk involving a trailing space or period in path.
That was causing this sort of constraint violation until the problem was identified for a fix.

If you mean System.Data.SQLite.dll is at 1.0.111.0, they document that as SQLite 3.28.0.
Version used in the 2.0.9* Canary series looks like 1.0.115.0 which is from SQLite 3.36.0.

That’s still 3 years old, and I don’t recall if I’ve heard a reason for it intentionally being old.
Regardless, different SQLite versions giving different answers is a very interesting finding.

Martin_Smith · August 11, 2024, 7:33am

I’ve now built a bunch of versions and the last one where I see the different answer is 3.31.1. After that point e.g. in 3.32 I get the same answer as expected.

[martin@pandora debug_duplicati]$ [martin@pandora debug_duplicati]$ 3.31.1/sqlite3 -readonly GORBXGWZAK.sqlite
SQLite version 3.31.1 2020-01-27 19:55:54
Enter ".help" for usage hints.
sqlite> .read query.sql
60602
sqlite> .q
[martin@pandora debug_duplicati]$ 3.32/sqlite3 -readonly GORBXGWZAK.sqlite
SQLite version 3.32.0 2020-05-22 17:46:16
Enter ".help" for usage hints.
sqlite> .read query.sql
60654
sqlite> .q

I don’t see any fixes in the release notes that would really explain this.

Martin_Smith · August 12, 2024, 8:08am

Right. I’ve now done what I probably should have done at the start and checked the database. It’s corrupted somehow.

SQLite version 3.45.1 2024-01-30 16:01:20
Enter ".help" for usage hints.
sqlite> .read pragma.sql
row not in PRIMARY KEY order for FilesetEntry
row 413104 missing from index nn_FilesetentryFile
row 413104 missing from index FilesetentryFileIdIndex
row 413105 missing from index nn_FilesetentryFile
row 413105 missing from index FilesetentryFileIdIndex
row 413106 missing from index nn_FilesetentryFile
row 413106 missing from index FilesetentryFileIdIndex
row 413107 missing from index nn_FilesetentryFile
row 413107 missing from index FilesetentryFileIdIndex
row 413108 missing from index nn_FilesetentryFile
row 413108 missing from index FilesetentryFileIdIndex
row 413109 missing from index nn_FilesetentryFile
row 413109 missing from index FilesetentryFileIdIndex
row 413110 missing from index nn_FilesetentryFile
row 413110 missing from index FilesetentryFileIdIndex
row 413111 missing from index nn_FilesetentryFile
row 413111 missing from index FilesetentryFileIdIndex
row 413112 missing from index nn_FilesetentryFile
row 413112 missing from index FilesetentryFileIdIndex
row 413113 missing from index nn_FilesetentryFile
row 413113 missing from index FilesetentryFileIdIndex
row 413114 missing from index nn_FilesetentryFile
row 413114 missing from index FilesetentryFileIdIndex
row 413115 missing from index nn_FilesetentryFile
row 413115 missing from index FilesetentryFileIdIndex
row 413116 missing from index nn_FilesetentryFile
row 413116 missing from index FilesetentryFileIdIndex
row 413117 missing from index nn_FilesetentryFile
row 413117 missing from index FilesetentryFileIdIndex
row 413118 missing from index nn_FilesetentryFile
row 413118 missing from index FilesetentryFileIdIndex
row 413119 missing from index nn_FilesetentryFile
row 413119 missing from index FilesetentryFileIdIndex
row 413120 missing from index nn_FilesetentryFile
row 413120 missing from index FilesetentryFileIdIndex
row 413121 missing from index nn_FilesetentryFile
row 413121 missing from index FilesetentryFileIdIndex
row 413122 missing from index nn_FilesetentryFile
row 413122 missing from index FilesetentryFileIdIndex
row 413123 missing from index nn_FilesetentryFile
row 413123 missing from index FilesetentryFileIdIndex
row 413124 missing from index nn_FilesetentryFile
row 413124 missing from index FilesetentryFileIdIndex
row 413125 missing from index nn_FilesetentryFile
row 413125 missing from index FilesetentryFileIdIndex
row 413126 missing from index nn_FilesetentryFile
row 413126 missing from index FilesetentryFileIdIndex
row 413127 missing from index nn_FilesetentryFile
row 413127 missing from index FilesetentryFileIdIndex
row 413128 missing from index nn_FilesetentryFile
row 413128 missing from index FilesetentryFileIdIndex
row 413129 missing from index nn_FilesetentryFile
row 413129 missing from index FilesetentryFileIdIndex
row 413130 missing from index nn_FilesetentryFile
row 413130 missing from index FilesetentryFileIdIndex
row 413131 missing from index nn_FilesetentryFile
row 413131 missing from index FilesetentryFileIdIndex
row 413132 missing from index nn_FilesetentryFile
row 413132 missing from index FilesetentryFileIdIndex
row 413133 missing from index nn_FilesetentryFile
row 413133 missing from index FilesetentryFileIdIndex
row 413134 missing from index nn_FilesetentryFile
row 413134 missing from index FilesetentryFileIdIndex
row 413135 missing from index nn_FilesetentryFile
row 413135 missing from index FilesetentryFileIdIndex
row 413136 missing from index nn_FilesetentryFile
row 413136 missing from index FilesetentryFileIdIndex
row 413137 missing from index nn_FilesetentryFile
row 413137 missing from index FilesetentryFileIdIndex
row 413138 missing from index nn_FilesetentryFile
row 413138 missing from index FilesetentryFileIdIndex
row 413139 missing from index nn_FilesetentryFile
row 413139 missing from index FilesetentryFileIdIndex
row 413140 missing from index nn_FilesetentryFile
row 413140 missing from index FilesetentryFileIdIndex
row 413141 missing from index nn_FilesetentryFile
row 413141 missing from index FilesetentryFileIdIndex
row 413142 missing from index nn_FilesetentryFile
row 413142 missing from index FilesetentryFileIdIndex
row 413143 missing from index nn_FilesetentryFile
row 413143 missing from index FilesetentryFileIdIndex
row 413144 missing from index nn_FilesetentryFile
row 413144 missing from index FilesetentryFileIdIndex
row 413145 missing from index nn_FilesetentryFile
row 413145 missing from index FilesetentryFileIdIndex
wrong # of entries in index nn_FilesetentryFile
wrong # of entries in index FilesetentryFileIdIndex

I can’t rebuild the index because it complains of constraint violations so it looks like I’ll have to recreate the database.

Martin_Smith · August 12, 2024, 8:43am

The recreate gave me two warnings so I think there is still something not quite right.

2024-08-12 09:14:07 +01 - [Warning-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FileEntryProcessingFailed]: Failed to process file-entry: D:\Media\Images\Tankfest June 2018\
SQLiteException: constraint failed
UNIQUE constraint failed: FilesetEntry.FilesetID, FilesetEntry.FileID
2024-08-12 09:14:07 +01 - [Warning-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FileEntryProcessingFailed]: Failed to process file-entry: D:\Media\Images\Test Pics\Canon Test\
SQLiteException: constraint failed
UNIQUE constraint failed: FilesetEntry.FilesetID, FilesetEntry.FileID

ts678 · August 12, 2024, 11:51am

That looks like the kind of thing that could come out during dlist file processing. This is where the information on the files are kept – dblock files are block data, and dindex is an index for a dblock.

Again, a verbose log might help, but even an information level log might help, or no log, if on CLI.

If there is a problem with some backup versions on the destination, the question is – which ones?

Direct restore from backup files is one way to look around in different versions, but may be harder.

The REPAIR command (IIRC, and at least for recreation) lets you pick versions you want it to get:

--version
By default, Duplicati will list and restore files from the most recent backup, use this option to select another item. You may enter multiple values separated with comma, and ranges using -, e.g. 0,2-4,7.

Since you’ve done some great deep diving so far, I’ll point to some other articles on the internals:

How the backup process works
Database and destination internals

Basically, this might wind up being bad (duplicate entry?) path information in a dlist filelist.json file.

I’m not suggesting going right for a hand-edit, e.g. “if” there’s only one bad version, maybe drop it.

Martin_Smith · August 18, 2024, 5:20pm

Things seem to have settled down now. Several backups have run with no errors or warnings. I think I’ll have to leave it there unless something else goes wrong.