That was my question about the old DB, so apparently something killed 3838716.
Because File is a view, I “think” that delete is by by DELETE FROM “FileLookup”.
I see four of those in the source, and am wishing there was a profiling log to help.
Maybe first show “Verify files” button complains now. It likely will, but we know why.
Make a manual copy of the database to reduce risk if fix attempt makes this worse.
You could then either try an ambitious fix by inserting the File row that was missing
(which may break if it’s missing because something it needs for that file is missing),
or just make FilesetEntry forget it knows about that log file that sounds unessential.
I don’t see anything in Fileset table that says how many FilesetEntry rows it has, so
deleting a row will probably be tolerated. You can then see if Verify files gets happy.
That’s not quite the end of it (but a great start), as a dlist file is a fileset, with its info. Database and destination internals but dlist files can be recreated if DB is correct…
Verify Files on live DB
Result: Same error as when the backup job runs, as expected
Unexpected difference in fileset version 10: 5/18/2023 5:00:00 AM (database id: 1415), found 261396 entries, but expected 261397
Backup live DB
Insert file data into the tables behind the File view.
insert into FileLookup ('ID','PrefixID','Path','BlocksetID','MetadataID')
values ('3838716','2644','error.log.1','4425412','3450857');
insert into PathPrefix ('ID','Prefix')
values ('2644','/source/appdata/nextcloud/log/nginx/');
I did get a unique constraint error on the insert into PathPrefix, which means the record was already there. After the insert, I confirmed that File now returns a record for ID 3838716
Verify Files on (now updated) live DB
Result: No Errors (yay!)
Here’s the log:
2023-06-03 09:05:21 -07 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started
2023-06-03 09:08:29 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()
2023-06-03 09:08:35 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (11.31 KB)
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-20230601T120000Z.dlist.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-20230601T120001Z.dlist.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-KeepIncompleteFile]: keeping protected incomplete remote file listed as Uploading: duplicati-20230601T135119Z.dlist.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b3912d0b569d74c62b3e48be7ac1b00d1.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b9c6a7ef0b3c449edbf195cd1a63ccc88.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b858cfb78758449fdb83c34b9282990e6.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bd0199f4ab44b4afc8e94dad3586aa3a0.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b34b6dccf300a4c988590097259fbf2e2.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b4d1364017905452dbddfeb6514be80a4.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-bcdd76b24ebd4443e89a3354a6e1c4493.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b939783651c554f6f9f2280cde208ebeb.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b89724d7d268b4524aae59d5935a67adc.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b0ffc984226d44787b36a8a306d5f7a73.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-bd9a7a9b797b44d679e0504a206e9b2f0.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b703fc0543baa4144a9c673efe997cc8b.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-ba3ef80326d0944e58c8992dcdc8765b5.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bf0d1da39d20947e1be79c684b5fd3af5.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-be7f7442b77834d0c9434874fe3658e93.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b17050c7e6ef74786b11e150065bf6295.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b1d1d33272d154013ab2a29e225b48868.dblock.zip.aes
2023-06-03 09:08:37 -07 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-b161db2eda6a648209d0bb34b3aeb5d1d.dblock.zip.aes
2023-06-03 09:10:03 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20230309T120000Z.dlist.zip.aes (17.57 MB)
2023-06-03 09:10:05 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20230309T120000Z.dlist.zip.aes (17.57 MB)
2023-06-03 09:10:05 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i729cef3fe0cf4610bbbda8f8abe174ca.dindex.zip.aes (86.58 KB)
2023-06-03 09:10:05 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i729cef3fe0cf4610bbbda8f8abe174ca.dindex.zip.aes (86.58 KB)
2023-06-03 09:10:48 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b7664945f46234275b929b31769cc0f33.dblock.zip.aes (50.07 MB)
2023-06-03 09:10:51 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b7664945f46234275b929b31769cc0f33.dblock.zip.aes (50.07 MB)
Kind of your call, however you just made it through something similar to its pre-backup verification.
One good thing to do if you don’t do it regularly is to see if database recreates from the destination.
I know you have backup of DB, but testing recreate may also add confidence that restore will work.
If you decide to do this, you can move your DB aside again (keep track of which is which). Repair.
Seeing no database, this will recreate one, ideally from dlist files, then dindex, and no dblock files.
You could watch in About → Show log → Live → Information, or Verbose if you want more details.
Alternatively, watch the progress bar. Anything past 70% is dblock files, and past 90% can get lots.
EDIT:
Testing restore occasionally is also too. You don’t want to find out too late that restores don’t work.
People who don’t backup the DB can do partial DB recreates with Direct restore from backup files.
Your case is different. You probably have a backup DB that can backup, but can it restore as well?
Or if you prefer not to be cautious, I guess you can just see if backup runs. Regarding dlist files, it appears that your last one is May 31, and nothing went up since then, so maybe nothing needs fix.
Progress bar moves left to right. If it goes past 90% it’s doing an exhaustive search for missing blocks. Probably ought to give the user the choice to just give up at that point, but you can always kill process.
EDIT:
From a B2 time and cost point of view, dlist and dindex files should be small and cheap. Dblock not so.
This will probably take awhile. That might make you happy with the decision to backup the database…
Got it. I’ll go ahead and try the Database recreate and see what happens. If it’s successful, am I safe to proceed with running a backup at that point?
Nothings ever guaranteed, especially after having done manual fixups that make some assumptions.
You would probably be able to do a backup though. You can decide which DB to use. The recreated database will be smaller because it has fewer logs. Maybe you want history or maybe you like space.
Are the logs the same as what gets written to the duplicati.log file? If so, I’ve got those going into Graylog for storage and searchability.
I do test file restores every few months or so, and they have always been fine. Do you specifically mean restoring a Duplicati database and seeing if Duplicati still works with the restored database?
There’s no file of that name unless you set one up with log-file, and if you did, what level did you pick? Presumably not Profiling like I’d like. Ideally it also has profile-all-database-queries, so is huge.
The logs in the database are the job logs under job’s Show log. General is used most. Remote exists.
Testing of any sort is good. Restoring database from DB backup probably gives little extra information.
Restoring in Direct restore from backup files tests recreate some. Actual DB recreate tests that better, however for extra caution you can rename the database yourself, then do Repair. Recreate button will delete the database without making a copy, which leaves you in a bad spot if database recreation fails.
One interesting test would be to try to restore the version of the log file that you think you put back, as possibly some bit of it is missing. If you test that, use no-local-blocks to prevent its use of local blocks:
Duplicati will attempt to use data from source files to minimize the amount of downloaded data. Use this option to skip this optimization and only use remote data.
I’m not sure how thorough the usual Duplicati tests are, e.g. if they test all blocks for all versions of all files. That would be a slow thing. I did create a Python script to try to test, if you’d like to play with one.
This is sort of a sanity test on missing blocks by reading dlist and dindex files. Missing block can make database recreate stress out and search hard (that last 90% described), or might make file restore fail.
I don’t recall setting up log-file, but I’m using the linuxserver.io container, so maybe it’s something configured by default in their container. Is there a config file where that option is set globally? Where would I find that? I’m fairly certain it’s set to Information level.
In any case, looks like the logs in the database have a lot of statistics about how that job ran, how many files it touched, deleted, etc, as well as the log messages that I’m seeing in duplicati.log. I think I’m OK with proceeding without that detail (assuming the backup job works).
Regarding the Repair/Recreate that I’m running now, it was able to pull all 25 of the dlist files, and then it began humming away at the dindex files. It was proceeding quite rapidly until about 30 minutes ago.
Per job would be the Advanced options linked in you quoting me. Global could be in Settings, or in Duplicati.Server.exe options --log-file and maybe --log-level if they chose to do Information.
Launch of the server in Docker depends on the launch system, but ps can probably reveal options.
It should be pretty clear after looking at the file content.
Probably, although this is just the first pass (from 70% on progress bar). Worse is third pass from 90%.
IIRC @gpatel-fr is more familiar with the code in GetMissingBlockListVolumes. Can you read its work?
As a side note, I’ve been abusing a database by hand-editing good inter-table references to bad ones.
I then run Verify files to see if the problem got detected. So far, it’s hit or miss. Metadata is worse.
This was my concern about just putting back a row that went missing. Did that create bad references?
Got any background in foreign key constraints? That might have prevented even that initial corruption.
Whether or not there would be a big performance loss, or transaction plan might break is a question…
Right now it looks like it’s processing one dblock file every 30 minutes. It has 620 dblock files to process. That’s about 13 days to get through the first pass… that’s not going to work.
If I’ve been following along correctly, I believe I understand that it SHOULD be able to rebuild the database using the dlist files along with the dindex files… do I have that right? If so, the fact that it’s now processing the dblock files indicates that something wasn’t right with the dlist/dindex files, right?
Can you help me understand what it is that wasn’t right with the dlist/dindex files that’s causing it to go through the dblock files?
I think that’s the intention. I’m trying to recall if there are any “typical” exceptions though.
I routinely rebuild my database without getting dblock downloads for whatever it’s worth.
That’s disappointing, and would be worth an investigation if there’s a volunteer to do so.
Your backup is a bit oversized for the 100 KB blocksize default, but not horrendously so.
You’re at about 5 million blocks and should be at 1 million as too many blocks gets slow.
Not instantly. It’s in the code I pointed to where I was hoping someone can read the SQL.
From an initial attempt, it might be a blocklist problem, perhaps missing data in index file.
The reference I linked earlier talk about blocklists. They enumerate the blocks of a file by
giving a concatenation of the 32 byte SHA-256 hashes. A blocklist is itself a block, so will
be found in a dblock file. To avoid reading a dblock file, a copy is also normally in dindex. index-file-policy can avoid that, but it seems a bad idea, and possibly nobody chooses to.
Or I might be misreading the SQL or its context. SQL that I’m looking at at the moment is:
SELECT "BlocklistHash"."Hash"
FROM "BlocklistHash"
LEFT OUTER JOIN "BlocksetEntry" ON "BlocksetEntry"."Index" = ("BlocklistHash"."Index" * 3200)
AND "BlocksetEntry"."BlocksetID" = "BlocklistHash"."BlocksetID"
WHERE "BlocksetEntry"."BlocksetID" IS NULL
which seems happy on your DB bug report database, so issue might be solely for recreate.
EDIT: I have an idea of what that SQL might be trying to do, but really we need someone to
figure out the entire recreate code to understand the process and especially dblock phases.
This is the work I was thinking of. Can you help explain what’s up with the three passes of dblock downloading, what each pass looks at to decide to start, and what happens to end dblock reads?
EDIT: I’m somewhat familiar with file formats, and described them in my Developer category topic
after building the missing-block-checking Python script I mentioned. I don’t know Duplicati doings.
I do have github, but I’m afraid I’m clueless as to how I would implement this in my environment. As I mentioned, I’m running the linuxserver.io docker container. Is that something you could help with?
Current status of the rebuild: block 8 of 620. I don’t think it’s worth it to let it keep running. How can I kill it?
I don’t use Docker, but I suppose you could docker exec in, find Duplicati or mono, and do the kill.
Wouldn’t restarting the container also kill everything inside and restart (unlike a VM that can save)?
I clicked the (X) in the progress bar, and that allowed me to stop the job, so I think we’re good.
I think I’m going to just set up a new bucket in B2 and start a new backup job in Duplicati so at least I’m getting daily backups again.
I have to admit, I’m disheartened to know that regardless of the status of my local database, the fact that it can’t be rebuilt from the remote data seems to indicate that my remote data is damaged in some way. If the remote data is damaged, and the local database is meant to be a representation of the remote data, then what does that mean for a worst-case scenario of having to do a full restore (even with a database backup)?
Not all the way I’m afraid. You can extract the binaries (.zip version) from the Mac package and unpack them in your container. Setting the env variables is something I’m a bit hazy but I think it can be done in the docker-compose thingy. I’m not sure if changing the docker-compose does not trigger a rebuild of the container negating the first move (since unzipping a zip into the container patches it). I think that you are running a Duplicati version where the database would be compatible with the modified binaries.
I have no clue about the memory allocation involved in the second env variable. I presume that Docker may involve restricting memory allocation by the container, so possibly asking for a lot of memory for the Sql engine could overwhelm the container limitations. If so possibly asking for less could be a way, or foregoing it completely. Having more memory for the Sql engine is good for speed but having better queries should at least doing something.
Possibly a way could be to recreate the database on another computer. I said that I am doubting the hardware you are using and I am still concerned. Lot of seemingly unrelated problems happening just like that is suspicious. Do you use server-class hardware with Ecc memory ?
That might also give a more comfortable environment to look at any issue.
Working within the limited amount of stuff in a container makes life harder.
Its timing is explainable if this is the first recreate attempt ever, or in awhile.
I’d note that this backup appears to go back to 2019, so has history – plus
possible damage from bugs fixed since 2.0.4.3_beta_2018-11-28 went out.
If Canary was ever run (what’s this been on anyway), risk gets even bigger.
will clear out any old hidden damage, while we keep working on old backup.
Every time I try reading recreate code, I find it hard, so I wouldn’t mind help.
If anyone could post a general summary, that would be useful to understand.