This updates our logging framework from legacy freetext strings using
the `log` package to structured log entries using `log/slog`. I have
updated all INFO or higher level entries, but not yet DEBUG (😓)... So,
at a high level:
There is a slight change in log levels, effectively adding a new warning
level:
- DEBUG is still debug (ideally not for users but developers, though
this is something we need to work on)
- INFO is still info, though I've added more data here, effectively
making Syncthing more verbose by default (more on this below)
- WARNING is a new log level that is different from the _old_ WARNING
(more below)
- ERROR is what was WARNING before -- problems that must be dealt with,
and also bubbled as a popup in the GUI.
A new feature is that the logging level can be set per package to
something other than just debug or info, and hence I feel that we can
add a bit more things into INFO while moving some (in fact, most)
current INFO level warnings into WARNING. For example, I think it's
justified to get a log of synced files in INFO and sync failures in
WARNING. These are things that have historically been tricky to debug
properly, and having more information by default will be useful to many,
while still making it possible get close to told level of inscrutability
by setting the log level to WARNING. I'd like to get to a stage where
DEBUG is never necessary to just figure out what's going on, as opposed
to trying to narrow down a likely bug.
Code wise:
- Our logging object, generally known as `l` in each package, is now a
new adapter object that provides the old API on top of the newer one.
(This should go away once all old log entries are migrated.) This is
only for `l.Debugln` and `l.Debugf`.
- There is a new level tracker that keeps the log level for each
package.
- There is a nested setup of handlers, since the structure mandated by
`log/slog` is slightly convoluted (imho). We do this because we need to
do formatting at a "medium" level internally so we can buffer log lines
in text format but with separate timestamp and log level for the API/GUI
to consume.
- The `debug` API call becomes a `loglevels` API call, which can set the
log level to `DEBUG`, `INFO`, `WARNING` or `ERROR` per package. The GUI
is updated to handle this.
- Our custom `sync` package provided some debugging of mutexes quite
strongly integrated into the old logging framework, only turned on when
`STTRACE` was set to certain values at startup, etc. It's been a long
time since this has been useful; I removed it.
- The `STTRACE` env var remains and can be used the same way as before,
while additionally permitting specific log levels to be specified,
`STTRACE=model:WARN,scanner:DEBUG`.
- There is a new command line option `--log-level=INFO` to set the
default log level.
- The command line options `--log-flags` and `--verbose` go away, but
are currently retained as hidden & ignored options since we set them by
default in some of our startup examples and Syncthing would otherwise
fail to start.
Sample format messages:
```
2009-02-13 23:31:30 INF A basic info line (attr1="val with spaces" attr2=2 attr3="val\"quote" a=a log.pkg=slogutil)
2009-02-13 23:31:30 INF An info line with grouped values (attr1=val1 foo.attr2=2 foo.bar.attr3=3 a=a log.pkg=slogutil)
2009-02-13 23:31:30 INF An info line with grouped values via logger (foo.attr1=val1 foo.attr2=2 a=a log.pkg=slogutil)
2009-02-13 23:31:30 INF An info line with nested grouped values via logger (bar.foo.attr1=val1 bar.foo.attr2=2 a=a log.pkg=slogutil)
2009-02-13 23:31:30 WRN A warning entry (a=a log.pkg=slogutil)
2009-02-13 23:31:30 ERR An error (a=a log.pkg=slogutil)
```
---------
Co-authored-by: Ross Smith II <ross@smithii.com>
The sort package is still used in places that were not trivial to
change. Since Go 1.21 slices package can be uswed for sort. See
https://go.dev/doc/go1.21#slices
### Purpose
Make some progress with the migration to a more up-to-date syntax.
### Purpose
The `fs.Filesystem` interface contains two parts that cannot be
implemented externally because they are private:
* `filesystemWrapperType`: this PR changes `unwrapFilesystem` to
downcast to a specific concrete type
* `underlying`: this PR simply moves it to an unexported interface
### Testing
Regular tests pass.
This would have addressed a recent issue that arose when re-ordering our
"filesystem layers". Specifically moving the caseFilesystem to the
outermost layer. The previous cache included the filesystem, and as such
all the layers below. This isn't desirable (to put it mildly), as you
can create different variants of filesystems with different layers for
the same path and options. Concretely this did happen with the mtime
layer, which isn't always present. A test for the mtime related breakage
was added in #9687, and I intend to redo the caseFilesystem reordering
after this.
Ref: #9677
Followup to: #9687
This commit replaces `os.MkdirTemp` with `t.TempDir` in tests. The
directory created by `t.TempDir` is automatically removed when the test
and all its subtests complete.
Prior to this commit, temporary directory created using `os.MkdirTemp`
needs to be removed manually by calling `os.RemoveAll`, which is omitted
in some tests. The error handling boilerplate e.g.
defer func() {
if err := os.RemoveAll(dir); err != nil {
t.Fatal(err)
}
}
is also tedious, but `t.TempDir` handles this for us nicely.
Reference: https://pkg.go.dev/testing#T.TempDir
Signed-off-by: Eng Zer Jun <engzerjun@gmail.com>
This changes the cache to cache less things, yet retain the required
efficiency for our walk usecase. This uses less memory.
Specifically, instead of keeping result and child caches for each path
level, only keep a single cached child. In practice our operations are
depth-first, or almost depth-first, and then we retain the same hit
ratio for a smaller cache size.
I improved the benchmark so that it counts the Lstat and DirNames
operations performed, and they do not change significantly. The amount
of allocated memory is reduced by 20% and the walk itself is actually
slightly faster.
This also removes the clear based on number of cached names (as that is
not a thing any more) and the timer based clear (which was unused). This
means we'll retain the last cache state forever until it's cleared by a
write operation, but we did that before too and that state is now a lot
smaller...
The overhead compared to not using a casefs, for our typical "double
walk" (walk the tree then stat everything again) is 2x the dirnames we
would otherwise call, and no overhead on the stats (unchanged from old
implementation)
```
name old time/op new time/op delta
WalkCaseFakeFS100k/rawfs-8 306ms ± 1% 305ms ± 2% ~ (p=0.182 n=9+10)
WalkCaseFakeFS100k/casefs-8 579ms ± 5% 557ms ± 1% -3.77% (p=0.000 n=10+10)
name old B/entry new B/entry delta
WalkCaseFakeFS100k/rawfs-8 590 ± 0% 590 ± 0% ~ (all equal)
WalkCaseFakeFS100k/casefs-8 1.09k ± 0% 0.87k ± 0% -19.98% (p=0.000 n=10+10)
name old DirNames/entry new DirNames/entry delta
WalkCaseFakeFS100k/rawfs-8 0.51 ± 0% 0.51 ± 0% ~ (all equal)
WalkCaseFakeFS100k/casefs-8 1.02 ± 0% 1.02 ± 0% ~ (all equal)
name old DirNames/op new DirNames/op delta
WalkCaseFakeFS100k/rawfs-8 51.2k ± 0% 51.2k ± 0% ~ (all equal)
WalkCaseFakeFS100k/casefs-8 102k ± 0% 102k ± 0% ~ (all equal)
name old Lstat/entry new Lstat/entry delta
WalkCaseFakeFS100k/rawfs-8 3.02 ± 0% 3.02 ± 0% ~ (all equal)
WalkCaseFakeFS100k/casefs-8 3.02 ± 0% 3.02 ± 0% ~ (all equal)
name old Lstat/op new Lstat/op delta
WalkCaseFakeFS100k/rawfs-8 302k ± 0% 302k ± 0% ~ (all equal)
WalkCaseFakeFS100k/casefs-8 302k ± 0% 302k ± 0% ~ (all equal)
name old allocs/entry new allocs/entry delta
WalkCaseFakeFS100k/rawfs-8 15.7 ± 0% 15.7 ± 0% ~ (all equal)
WalkCaseFakeFS100k/casefs-8 27.5 ± 0% 26.1 ± 0% -5.09% (p=0.000 n=10+10)
name old ns/entry new ns/entry delta
WalkCaseFakeFS100k/rawfs-8 2.02k ± 1% 2.02k ± 2% ~ (p=0.163 n=9+10)
WalkCaseFakeFS100k/casefs-8 3.83k ± 5% 3.68k ± 1% -3.77% (p=0.000 n=10+10)
name old alloc/op new alloc/op delta
WalkCaseFakeFS100k/rawfs-8 89.2MB ± 0% 89.2MB ± 0% ~ (p=0.364 n=9+10)
WalkCaseFakeFS100k/casefs-8 164MB ± 0% 131MB ± 0% -19.97% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WalkCaseFakeFS100k/rawfs-8 2.38M ± 0% 2.38M ± 0% ~ (all equal)
WalkCaseFakeFS100k/casefs-8 4.16M ± 0% 3.95M ± 0% -5.05% (p=0.000 n=10+10)
```
With this change we emulate a case sensitive filesystem on top of
insensitive filesystems. This means we correctly pick up case-only renames
and throw a case conflict error when there would be multiple files differing
only in case.
This safety check has a small performance hit (about 20% more filesystem
operations when scanning for changes). The new advanced folder option
`caseSensitiveFS` can be used to disable the safety checks, retaining the
previous behavior on systems known to be fully case sensitive.
Co-authored-by: Jakob Borg <jakob@kastelo.net>
Marcus B SpencerandGitHub
Marcel MeyerandGitHub
Tommy van der VorstandGitHub
Simon FreiandGitHub
luzpazandGitHub
Eng Zer JunandGitHub
Audrius ButkeviciusandGitHub