DESIGN: Logging policies

jkowalski · October 28, 2021, 3:53am

Please see the proposed design of logging policies and leave your feedback on GitHub:

DESIGN: Logging policies

opened 03:51AM - 28 Oct 21 UTC

enhancement ux

Currently we're lacking a systematic approach to logging of upload progress. I p…ropose we leverage the mechanism of policies to define how snapshot creation is logged. ## Policy format We would define a new type of policy with flags that specify what level of detail gets logged for all snapshots, separately for files and directories: ```jsonc { "logging": { "directories" { "enabled": true|false, // whether to log directory information "timings": true|false, // wil log how long uploads take "deduplication": true|false // will log when a file is deduplicated, fully or partially "compression": true|false, // will log compression method and ratio used "objectID": true|false, // will log object IDs for directories, "actions": true|false // log actions as they are executed, "ignored: true|false // log when directories are ignored }, "entries": { "enabled": true|false, // whether to log directory entries "timings": true|false, // wil log how long uploads take "caching": true|false, // will log when we are able to leverage previous snapshot to avoid caching a file "metadata": true|false, // will log things like file size, mtime, "deduplication": true|false // will log when a file is deduplicated, fully or partially "compression": true|false, // will log compression method and ratio used "objectID": true|false, // will log object IDs for all entries "ignored: true|false // log when non-directories are ignored } } } ``` ## Log output For each log entry we will emit ``` DIRECTORY /path/to/dir <details> FILE /path/to/file <details> SYMLINK /path/to/symlink <details> ERROR /path/to/entry <error details> ``` The `details` will be structural and item-dependent - based on appropriate flags defined in the policy: DIRECTORY /path/to/directory: size:9010815132 files:266941 symlinks:0 dirs:69693, compression:23%, deduplication:12%, duration:120s objectID:k7c35f67845b954968cf2562f61e11cd6 FILE /path/to/file: size:9010815132 mtime:2021-10-27T20:17:45Z duration:120s compression-algorithm:pgzip compression:23% deduplication:100% objectID:7c35f67845b954968cf2562f61e11cd6 Depending on `logDirectories` and `logEntries` we will log: * `logging.directories.enabled == false && logging.entries.enabled == false` - nothing is logged * `logging.directories.enabled == true && logging.entries.enabled == false` - one line per directory is logged with statistics after the directory has finished processing, no file information, children are logged before the parents: ``` DIRECTORY /path/to/directory1: size:100 duration:5s DIRECTORY /path/to/directory2: size:200 duration:120s DIRECTORY /path/to: size:300 duration:125s DIRECTORY /path: size:300 duration:125s ``` * ``logging.directories.enabled == false && logging.entries.enabled == true` -only files are logged, no directory summaries ``` FILE /path/to/directory1/file1: size:100 duration:5s FILE /path/to/directory1/file2: size:150 duration:12s FILE /path/to/directory2/file1: size:200 duration:120s SYMLINK /path/to/directory2/link3: duration:0s ``` * `logging.directories.enabled == true && logging.entries.enabled == true` - both directories and files are logged with directory summary following all files in it: ``` FILE /path/to/directory1/file1: size:100 duration:5s FILE /path/to/directory1/file2: size:150 duration:12s DIRECTORY /path/to/directory1: size:250 duration:14s FILE /path/to/directory2/file1: size:200 duration:120s DIRECTORY /path/to/directory2: size:200 duration:120s DIRECTORY /path/to/empty-directory2: size:0 duration:0s DIRECTORY /path/to: size:450 duration:125s DIRECTORY /path: size:450 duration:125s ``` ## Hierarchical policies Same as everywhere else, policies will scopes to `global`, `host`, `user@host` or `user@host:/path` and the most specific match defines the behavior for each folder. ## Default policy The default policy will only emit basic directory-level summary and not other entries: ``` { "logging": { "directories": { "enabled": true, "timings": true, }, "entries": { "enabled": false, }, } } ``` ## CLI We will expose a new set of tri-state flags for each of the policy fields with values `true`, `false`, and `inherit`, just like when dealing with other boolean policy flags: ``` kopia policy set <target> \ --log-directories true|false|inherit \ --log-directory-timings true|false|inherit \ --log-directory-object-ids true|false|inherit \ --log-entries true|false|inherit \ --log-entry-timings true|false|inherit \ --log-entry-object-ids true|false|inherit \ ... ``` The value `inherit` indicates that a particular policy value is not emitted in JSON at all and will be inherited from the parent policy. ## Simplified CLI flags We may also introduce high-level helper flags: `--log-directory-info` and `--log-entry-info` which can be `none`, `minimal`, `full` or something similar to quickly set/unset related flags together. Examples: ``` # globally enable minimal logging for all directories, but not files: kopia policy set --global --log-directory-info=minimal --log-entry-info=none # prevent logging from one particular directory kopia policy set /hidden/directory --log-directory-info=none --log-entry-info=none # more detailed logging from one particular directory kopia policy set /detailed/directory --log-directory-info=full --log-entry-info=full ```

kopanla · October 28, 2021, 4:44am

This looks good. I think it will be very useful. Thanks for considering this.

There does not seem any flag for errors/warnings? For example, I might want to see errors, but not warnings (if there is such a distinction).

Regarding

The default policy will only emit basic directory-level summary and not other entries

IMO the default should include errors, and it should also include info on ignored folders/files (helps debugging ignore/include patterns).

Regarding

log when [non-]directories are ignored

It would be also great (if possible) to include the reason (“policy or a kopiaignore file, etc”).

On the UI we see a lot of “entry not cached” messages. This pollutes the log IMO and should be excluded by default.

Topic		Replies	Views
V0.9.5 bug new logging feature Support	2	267	November 9, 2021
"Improve logging" Feature Requests	1	437	October 28, 2021
Upcoming changes to snapshot creation flow in Kopia UI Announcements	5	814	March 9, 2021
Kopia UI Improvement Ideas General	6	842	June 7, 2021
Documenting policy options General	4	1382	December 20, 2021

DESIGN: Logging policies

Related topics