With canary 2.0.3.2 there is a new log system that improves on the previous system in a number of ways.
The previous version uses a single --log-level to control the shared log level, and the option --verbose as a mix of setting --log-level=verbose and --full-results.
The new log system removes the --verbose option and deprecates the --log-level. Instead there are two new options --console-log-level and --log-file-log-level which gives control over which messages are shown where. For now, --log-level sets both these, but the option will eventually be removed.
Internally the log system has been updated to include the source of each log message, as well as a (mostly) unique ID for each log message.
An example of log contents is shown here (--log-file-log-level=Profiling):
2018-03-16 09:34:01 +01 - [Verbose-Duplicati.Library.Main.Operation.BackupHandler.FileEntry-NewFile]: New file /source/file1
2018-03-16 09:34:01 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
2018-03-16 09:34:01 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 0:00:00:00.000
2018-03-16 09:34:01 +01 - [Verbose-Duplicati.Library.Main.Operation.BackupHandler.FileEntry-AddDirectory]: Adding directory /source/subfolder/
2018-03-16 09:34:01 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
2018-03-16 09:34:01 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 0:00:00:00.000
2018-03-16 09:34:01 +01 - [Verbose-Duplicati.Library.Main.Operation.BackupHandler.FileEntry-CheckFileForChanges]: Checking file for changes /source/subfolder/file2, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 9/18/2017 8:24:19 AM vs 1/1/0001 12:00:00 AM
2018-03-16 09:34:01 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ?
2018-03-16 09:34:01 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = ? AND "Size" = ? took 0:00:00:00.000
2018-03-16 09:34:01 +01 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid();
2018-03-16 09:34:01 +01 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid(); took 0:00:00:00.000
2018-03-16 09:34:01 +01 - [Verbose-Duplicati.Library.Main.Operation.BackupHandler.FileEntry-NewFile]: New file /source/subfolder/file2
This quickly adds up to a large number of lines, even though we are only looking at a few files in this example. To solve this there are now two new log-filter options: --console-log-filter and --log-file-log-filter that operate on the log-tag, which is what you see in the example between the hard brackets as [<level>-<source>-<id>].
These filters take precedence over the log-level and can be used to suppress or include individual log messages.
If you would like to only see what new files are added (second and last line in the example above) you can set the filter to --log-file-log-filter=+*-NewFile, meaning, always include log messages where the log-tag ends with -NewFile. If you add this filter, it ignores the log-level setting for messages that match the filter, allowing you to selectively include messages from other log levels.
For an example of the reverse situation, where you have a log-level but want to exclude certain messages, consider the above output, where you don’t want the messages for the timer started, but do want the time the commands took (respectively lines 2 and 3 from the example).
In this case you can keep the --log-file-log-level=Profiling and add --log-file-log-filter=-Profiling-Timer.Begin-* (notice the leading minus -in the filter). This will remove all the Timer.Begin messages, but otherwise keep the output as-is.
The filters support multiple wildcards * as well as multiple single character wildcards ?. For advanced uses, regular expressions are also supported by enclosing the filter in hard brackets, for example: --log-file-log-filter=+[.*-NewFile]. Multiple filters can be supplied using : or ; as separators, and individual filters can be applied to console and log-file simultaneously.
An example of multiple mixed filters:
--log-file-log-filter=-[[^-]*-Timer\.Begin];+*-NewFile;-*-AddDirectory;+[.*]
Happy logging!
