Strange warnings after update to Duplicati 2.0.3.4_canary_2018-04-02

Support
1

I’ve got three backup jobs (identical source settings) which back up to three different backup destinations (locally attached USB drive, NAS-Share via SMB, S3 cloud storage). Duplicati is configured to run as a service (Windows 10 64-bit).

Starting with the upgrade from duplicati-2.0.2.20_canary_2018-02-27 to 2.0.3.4_canary_2018-04-02 all three jobs throw a warning after having otherwise obviously successfully completed the backup task. Strange: the corresponding log file doesn’t show any warning or error at all, so I’ve got no clue what the warning popup is about. As all three jobs show this behaviour, there’s obviously no issue with the backup targets, but rather with something else.

image

The log I provided below is from the last run of the job “KDW81 Wasabi”, which shows “Got 2 warning(s)” in the according popup.

I’d be very glad if anyone has some idea where to start.

Thanks.

DeletedFiles: 148
DeletedFolders: 24
ModifiedFiles: 294
ExaminedFiles: 97627
OpenedFiles: 537
AddedFiles: 243
SizeOfModifiedFiles: 775782317
SizeOfAddedFiles: 33354070
SizeOfExaminedFiles: 94029028190
SizeOfOpenedFiles: 817689586
NotProcessedFiles: 0
AddedFolders: 24
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults: null
DeleteResults:
DeletedSets:
Dryrun: False
MainOperation: Delete
CompactResults: null
ParsedResult: Success
EndTime: 06.04.2018 17:00:24 (1523026824)
BeginTime: 06.04.2018 17:00:04 (1523026804)
Duration: 00:00:19.4682728
Messages: [
2018-04-06 16:54:24 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-06 16:55:01 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-06 16:55:12 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (10,32 KB),
2018-04-06 16:56:03 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
2018-04-06 16:56:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
…
]
Warnings:
Errors:
BackendStatistics:
RemoteCalls: 14
BytesUploaded: 211171525
BytesDownloaded: 62112599
FilesUploaded: 9
FilesDownloaded: 3
FilesDeleted: 0
FoldersCreated: 0
RetryAttempts: 0
UnknownFileSize: 0
UnknownFileCount: 1
KnownFileCount: 4170
KnownFileSize: 101490202306
LastBackupDate: 06.04.2018 16:54:24 (1523026464)
BackupListCount: 232
TotalQuotaSpace: 0
FreeQuotaSpace: 0
AssignedQuotaSpace: -1
ReportedQuotaError: False
ReportedQuotaWarning: False
ParsedResult: Success
Messages: [
2018-04-06 16:54:24 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-06 16:55:01 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-06 16:55:12 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (10,32 KB),
2018-04-06 16:56:03 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
2018-04-06 16:56:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
…
]
Warnings:
Errors:
RepairResults: null
TestResults:
MainOperation: Test
Verifications: [
Key: duplicati-20180406T145424Z.dlist.zip.aes
Value: ,
Key: duplicati-i11f0fb9a8c9340f0982c5566eb58966b.dindex.zip.aes
Value: ,
Key: duplicati-ba28590cd464248508ddecafeba32f917.dblock.zip.aes
Value:
]
ParsedResult: Success
EndTime: 06.04.2018 17:00:36 (1523026836)
BeginTime: 06.04.2018 17:00:32 (1523026832)
Duration: 00:00:03.5908106
Messages: [
2018-04-06 16:54:24 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-06 16:55:01 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-06 16:55:12 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (10,32 KB),
2018-04-06 16:56:03 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
2018-04-06 16:56:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
…
]
Warnings:
Errors:
ParsedResult: Success
EndTime: 06.04.2018 17:00:36 (1523026836)
BeginTime: 06.04.2018 16:54:24 (1523026464)
Duration: 00:06:11.3943826
Messages: [
2018-04-06 16:54:24 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2018-04-06 16:55:01 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2018-04-06 16:55:12 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (10,32 KB),
2018-04-06 16:56:03 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
2018-04-06 16:56:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb42e5be336a04c58b7bdfd90de14522d.dblock.zip.aes (49,91 MB),
…
]
Warnings:
Errors:

2

Do you use after or before script? May be there are errors in them.

3

Very reasonable thought as I really use an after script to back up the local databases. Unfortunately, a test without the after script brings the very same warning, so the root cause has to be located somewhere else.

4

My guess is the warning is in one of the other log locations (it’s confusing, I know - but there are 4 different log areas).

If you could try running the “KDW81 Wasabi" job with the following parameters added you should find a detailed log file stored at <path> - that might help narrow down the issue.

  • --log-file=\<path> (the log file will be written to <path>
  • --log-file-log-level=Profiling (ALL detail will be sent to the log file, if that’s too much you could try “Warning”)

Be sure to remove those parameters after your test run is complete, otherwise you’ll eventually end up with a very bug log file. :slight_smile:

5

Thanks a lot, this helped me to nail it down. Well, the reason for the warning, anyway. Maybe not yet the root cause. I used your recommended parameters and got a 50 MB log file to play around with.

The very last log entry read like that:

2018-04-06 21:32:04 +02 - [Warning-Duplicati.Library.Modules.Builtin.RunScript-ScriptTimeout]: Execution of the script “C:\Scripts\Duplicati\duplicati_db_backup.bat” timed out

So I found the default script timeout value to be 60 seconds. After that, the script execution continues, but Duplicati doesn’t wait any longer for the script to complete but issues a warning instead. Too bad that this one doesn’t show up in the “regular” log.

But why does the database backup script suddenly take that much time to complete? I found the job sqlite databases to have been grown very huge - up to more than 1,6 GB each. So that’s why the database backup job now takes up to 10 minutes to get the databases backed up to the cloud storage instead of a few seconds as it took some weeks ago. After increasing the script timeout to 15 minutes in the global settings, the warnings were gone. :+1:

Is there anything known about massive database growth in the later Duplicati releases? And any way to shrink them down again, if possible at all?

Anyway: thanks again. It’s a pleasure to work with a community that supportive, skilled and helpful. Besides the product itselt, that’s why I like and recommend Duplicati.

6

Good catch! I’m not sure why that wouldn’t appear in the “regular” log - perhaps it’s in the global log (annoying, but at least it’s there) otherwise it may indeed be an unlogged error.

Not that I’m aware of (growth or shrinkage). I believe most of the database size is due to how file paths are stored, so if you’ve added a lot of (or long) paths that could make the database grow quite a bit.

Note that something as simple as renaming a path (even a case change on certain file systems) can basically “double” the paths being stored as they’re considered new paths - and the old paths still need to be kept until their “versions” age out. Of course thanks to deduplication the destination space doesn’t change much because the actual file CONTENTS haven’t change, so very little needs to be uploaded.

I’m glad to hear you like Duplicati enough to recommend it to others, thanks! But be sure to pat yourself on the back as well because you’re part of what makes this community so supportive. :grinning:

1 Like