More warnings I can't see the reason for - 2.0.4.1_experimental_2018-11-08

Support
1

Sorry if I’m being thick, but can someone PLEASE tell me why I got a warning from the backup log below? IMO it is absolutely imperative that warning reports are improved for the “common man”, otherwise it’s just FUD

14 Nov 2018 18:02: Result
DeletedFiles: 0

DeletedFolders: 0

ModifiedFiles: 31

ExaminedFiles: 12935

OpenedFiles: 46

AddedFiles: 15

SizeOfModifiedFiles: 64940070

SizeOfAddedFiles: 173756

SizeOfExaminedFiles: 8877123436

SizeOfOpenedFiles: 65277554

NotProcessedFiles: 0

AddedFolders: 0

TooLargeFiles: 0

FilesWithError: 0

ModifiedFolders: 0

ModifiedSymlinks: 0

AddedSymlinks: 0

DeletedSymlinks: 0

PartialBackup: False

Dryrun: False

MainOperation: Backup

CompactResults:

    DeletedFileCount: 0

    DownloadedFileCount: 0

    UploadedFileCount: 0

    DeletedFileSize: 0

    DownloadedFileSize: 0

    UploadedFileSize: 0

    Dryrun: False

    MainOperation: Compact

    ParsedResult: Success

    Version: 2.0.4.1 (2.0.4.1_experimental_2018-11-08)

    EndTime: 14/11/2018 18:02:08 (1542218528)

    BeginTime: 14/11/2018 18:01:44 (1542218504)

    Duration: 00:00:24.5076408

    Messages: [

        2018-11-14 18:00:00 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

        2018-11-14 18:01:14 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

        2018-11-14 18:01:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (899 bytes),

        2018-11-14 18:01:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

        2018-11-14 18:01:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

...

    ]

    Warnings: []

    Errors: []

    BackendStatistics:

        RemoteCalls: 8

        BytesUploaded: 4371959

        BytesDownloaded: 5778471

        FilesUploaded: 3

        FilesDownloaded: 3

        FilesDeleted: 0

        FoldersCreated: 0

        RetryAttempts: 0

        UnknownFileSize: 0

        UnknownFileCount: 0

        KnownFileCount: 902

        KnownFileSize: 9521533214

        LastBackupDate: 14/11/2018 18:00:00 (1542218400)

        BackupListCount: 442

        TotalQuotaSpace: 0

        FreeQuotaSpace: 0

        AssignedQuotaSpace: -1

        ReportedQuotaError: False

        ReportedQuotaWarning: False

        ParsedResult: Success

        Version: 2.0.4.1 (2.0.4.1_experimental_2018-11-08)

        Messages: [

            2018-11-14 18:00:00 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

            2018-11-14 18:01:14 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

            2018-11-14 18:01:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (899 bytes),

            2018-11-14 18:01:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

            2018-11-14 18:01:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

...

        ]

        Warnings: []

        Errors: []

DeleteResults:

    DeletedSets: []

    Dryrun: False

    MainOperation: Delete

    ParsedResult: Success

    Version: 2.0.4.1 (2.0.4.1_experimental_2018-11-08)

    EndTime: 14/11/2018 18:02:08 (1542218528)

    BeginTime: 14/11/2018 18:01:41 (1542218501)

    Duration: 00:00:27.5833027

    Messages: [

        2018-11-14 18:00:00 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

        2018-11-14 18:01:14 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

        2018-11-14 18:01:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (899 bytes),

        2018-11-14 18:01:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

        2018-11-14 18:01:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

...

    ]

    Warnings: []

    Errors: []

RepairResults: null

TestResults:

    MainOperation: Test

    Verifications: [

        Key: duplicati-20181114T180000Z.dlist.zip.aes

        Value: [],

        Key: duplicati-i9fd71e2fa0134173a9cf9e51f05faf0d.dindex.zip.aes

        Value: [],

        Key: duplicati-b3120f225794c4e84afefec84620182ab.dblock.zip.aes

        Value: []

    ]

    ParsedResult: Success

    Version: 2.0.4.1 (2.0.4.1_experimental_2018-11-08)

    EndTime: 14/11/2018 18:02:17 (1542218537)

    BeginTime: 14/11/2018 18:02:11 (1542218531)

    Duration: 00:00:06.2549310

    Messages: [

        2018-11-14 18:00:00 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

        2018-11-14 18:01:14 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

        2018-11-14 18:01:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (899 bytes),

        2018-11-14 18:01:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

        2018-11-14 18:01:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

...

    ]

    Warnings: []

    Errors: []

ParsedResult: Success

Version: 2.0.4.1 (2.0.4.1_experimental_2018-11-08)

EndTime: 14/11/2018 18:02:17 (1542218537)

BeginTime: 14/11/2018 18:00:00 (1542218400)

Duration: 00:02:17.9463207

Messages: [

    2018-11-14 18:00:00 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,

    2018-11-14 18:01:14 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),

    2018-11-14 18:01:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (899 bytes),

    2018-11-14 18:01:27 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

    2018-11-14 18:01:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8719e5a61b8c48a7b0b2e4d365fcca1c.dblock.zip.aes (2.87 MB),

...

]

Warnings: []

Errors: []
1 Like
2

What warnings do you see?

All the lines say Warnings: [ ], meaning “empty list”.
All ParsedResult say Success.

3

I don’t see any, but the GUI flagged it with/as a warning. That’s my point!

4

I suspect the warning that was flagged is a “global” warning which don’t always get placed in the Job specific logs (like you’ve shown above).

If you go to Main menu -> About -> Show Log do you see any warnings on that page that correspond with your job run time?

5

Sorry, those logs seem to have got messed up when I installed 2.04.04 and subsequently had to reinstall 2.04.02 - there is a gap beteen Nov 1 and today.

Assuming you are correct, for GUI users like me Duplicati needs a better warning mechanism - I would never have thought to look other than in the job logs as that is where the program takes me when I click on the Windows warning popup.

6

Yeah, there are some discussions about how to better handle the logging.

Another unfortunate side effect of how the logs are currently handled (which is to save them in the system or job-specific databases) is that if somebody does a database Recreate (delete & create) then they lose all the logs that MIGHT have helped identify the source of the initial issue. :frowning:

7

I had done a database recreate, which now explains for me why my logs disappeared!

Duplicati seems to record most everything via sqlite databases, so why can’t you have one per job for logs and that is kept separate from any recreate; other than perhaps a marker to record the recreation. I appreciate that (my) ignorance is bliss and I’m certainly not trying to tell you how to program as I haven’t the first clue.

8

Well, sometimes a programmer can get so far into the weeds that they don’t see simple solutions that non-programmers can see. But in this instance I don’t think that’s the case. :slight_smile:

Using a database to store all the job info (and logs) makes sure things stay together and don’t have to be managed individually. Taking it to extremes, in theory we don’t need a database at all - we could store everything in 18 different text files for each job. But it would be slower and harder to manage, hence the database.

What would probably be a more simple “solution” for this would be to include a warning in the GUI such that when somebody chooses to do a database Recreate they are told something like “Please note that recreating the database will ERASE all logs currently associated with the job so take that into account you are currently debugging an issue.”

Even better would be an option to export the current database log items to text files.

And "bestes"t would be to preserve the job log so it can be imported into the recreated database. :smiley:

As far as your initial issue, the “Show” button used to be much better at bringing up the appropriate log for the message being reported. Unfortunately, a rewrite of the logging process a few months ago broke a lot of those links between the button and the appropriate log. We just haven’t had the (prioritized) time to look at fixing them. :frowning:

9

Thanks for the detailed explanation :ok_hand:

10

Is Duplicati a log management application or the backup application? It is usually much better to have logs stored separately, so they are protected from DB corruption or application issue - exactly when they are really needed, to troubleshoot and understand what happened. Having logs in internal DB prevents other tools, designed to collect/archive/monitor logs from working.

I use Duplicati via command line, without web UI - and this logging issue one of the reasons for that…

11

For better or worse, Duplicati backup relies on databases, and I suspect backup (not logs) was focus start. Total history isn’t known to me, but this offered a glimpse of history and the potential future to a nice log UI. Database is again probably necessary for a pretty future, but when that fails and you just need something:

Some logs survive recreate, for example logs sent by notification, or if someone is running a –log-file log on the server always or on the job (crank detail level as high as desired), but alternative logs need extra setup.

Some of this is preference. Some people are asking for better GUI, or better notifications and reporting (FYI there are many third-party efforts to build on even the existing notifications), but to your point for those who sometimes like text files, I use glogg - the fast, smart log explorer on a huge text log file I always keep going (partly because I sometimes check out reported issues on the system, and having the heavy logging helps). The default –log-file-log-level of Warning might be reasonably compact, and suit some people’s preference.

12

The problem with logs is always that you need to store them, but most of the time you do not need them.

In other words you pay a cost (disk storage, cpu time, etc) all the time, but most of the time you just throw it away.

Storing everything all the time quickly grows out of control and makes it hard to find what you need. Throwing things away reduces this overhead, but increases the possibility that you do not have the information that you need.

The logs stored in the database are only related to backend operations. That was done to debug cases where the backend is broken. I have seen multiple cases where the file is uploaded correctly, but then later has disappeared. I added logging of remote operations as that is somewhat a low volume of messages, but crucial in finding flaws in the program vs. flaws in the destination.

The results of each operation are also stored, because that is a small amount of extra data, and gets truncated if there are many warnings.

I did not anticipate that we would need a “recreate database” button, so the idea was to store all logging information in one place. I still hope we can figure out the last problems that cause broken database, so we can avoid users resorting to recreate as a part of the normal backup flow.

13

I want to be able to easily find and identify the causes of warnings - having to look in different places needs changing IMO. Looking at backup logs that caused warnings only to find no warning in them is not a great system.

A log database was an off-the-cuff suggestion. I don’t care about the mechanism so long as there is one place to look - txt file if must, but an database may offer an opportunity for better/more informative reporting.

14

I agree with both points. Currently there are at least two places to look, and that is confusing because no-one can remember what goes where.