feat: switch logging framework (#10220)
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>
This commit is contained in:
Jakob Borg
co-authored by
Ross Smith II
Ross Smith II
parent
49462448d0
commit
836045ee87
@@ -7,7 +7,7 @@
|
||||
package discover
|
||||
|
||||
import (
|
||||
stdsync "sync"
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"github.com/syncthing/syncthing/lib/protocol"
|
||||
@@ -34,7 +34,7 @@ type cachedError interface {
|
||||
|
||||
type cache struct {
|
||||
entries map[protocol.DeviceID]CacheEntry
|
||||
mut stdsync.Mutex
|
||||
mut sync.Mutex
|
||||
}
|
||||
|
||||
func newCache() *cache {
|
||||
|
||||
@@ -6,8 +6,6 @@
|
||||
|
||||
package discover
|
||||
|
||||
import (
|
||||
"github.com/syncthing/syncthing/lib/logger"
|
||||
)
|
||||
import "github.com/syncthing/syncthing/internal/slogutil"
|
||||
|
||||
var l = logger.DefaultLogger.NewFacility("discover", "Remote device discovery")
|
||||
var l = slogutil.NewAdapter("Remote device discovery")
|
||||
|
||||
+13
-11
@@ -14,15 +14,17 @@ import (
|
||||
"errors"
|
||||
"fmt"
|
||||
"io"
|
||||
"log/slog"
|
||||
"net"
|
||||
"net/http"
|
||||
"net/url"
|
||||
"strconv"
|
||||
stdsync "sync"
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"golang.org/x/net/http2"
|
||||
|
||||
"github.com/syncthing/syncthing/internal/slogutil"
|
||||
"github.com/syncthing/syncthing/lib/connections/registry"
|
||||
"github.com/syncthing/syncthing/lib/dialer"
|
||||
"github.com/syncthing/syncthing/lib/events"
|
||||
@@ -181,12 +183,12 @@ func (c *globalClient) Lookup(ctx context.Context, device protocol.DeviceID) (ad
|
||||
|
||||
resp, err := c.queryClient.Get(ctx, qURL.String())
|
||||
if err != nil {
|
||||
l.Debugln("globalClient.Lookup", qURL, err)
|
||||
slog.DebugContext(ctx, "globalClient.Lookup", "url", qURL, slogutil.Error(err))
|
||||
return nil, err
|
||||
}
|
||||
if resp.StatusCode != http.StatusOK {
|
||||
resp.Body.Close()
|
||||
l.Debugln("globalClient.Lookup", qURL, resp.Status)
|
||||
slog.DebugContext(ctx, "globalClient.Lookup", "url", qURL, "status", resp.Status)
|
||||
err := errors.New(resp.Status)
|
||||
if secs, atoiErr := strconv.Atoi(resp.Header.Get("Retry-After")); atoiErr == nil && secs > 0 {
|
||||
err = &lookupError{
|
||||
@@ -238,7 +240,7 @@ func (c *globalClient) Serve(ctx context.Context) error {
|
||||
} else if timerResetCount == maxAddressChangesBetweenAnnouncements {
|
||||
// Yet only do it if we haven't had to reset maxAddressChangesBetweenAnnouncements times in a row,
|
||||
// so if something is flip-flopping within 2 seconds, we don't end up in a permanent reset loop.
|
||||
l.Warnf("Detected a flip-flopping listener")
|
||||
slog.ErrorContext(ctx, "Detected a flip-flopping listener", slog.String("server", c.server))
|
||||
c.setError(errors.New("flip flopping listener"))
|
||||
// Incrementing the count above 10 will prevent us from warning or setting the error again
|
||||
// It will also suppress event based resets until we've had a proper round after announceErrorRetryInterval
|
||||
@@ -273,27 +275,27 @@ func (c *globalClient) sendAnnouncement(ctx context.Context, timer *time.Timer)
|
||||
// The marshal doesn't fail, I promise.
|
||||
postData, _ := json.Marshal(ann)
|
||||
|
||||
l.Debugf("%s Announcement: %v", c, ann)
|
||||
slog.DebugContext(ctx, "send announcement", "server", c.server, "announcement", ann)
|
||||
|
||||
resp, err := c.announceClient.Post(ctx, c.server, "application/json", bytes.NewReader(postData))
|
||||
if err != nil {
|
||||
l.Debugln(c, "announce POST:", err)
|
||||
slog.DebugContext(ctx, "announce POST", "server", c.server, slogutil.Error(err))
|
||||
c.setError(err)
|
||||
timer.Reset(announceErrorRetryInterval)
|
||||
return
|
||||
}
|
||||
l.Debugln(c, "announce POST:", resp.Status)
|
||||
slog.DebugContext(ctx, "announce POST", "server", c.server, "status", resp.Status)
|
||||
resp.Body.Close()
|
||||
|
||||
if resp.StatusCode < 200 || resp.StatusCode > 299 {
|
||||
l.Debugln(c, "announce POST:", resp.Status)
|
||||
slog.DebugContext(ctx, "announce POST", "server", c.server, "status", resp.Status)
|
||||
c.setError(errors.New(resp.Status))
|
||||
|
||||
if h := resp.Header.Get("Retry-After"); h != "" {
|
||||
// The server has a recommendation on when we should
|
||||
// retry. Follow it.
|
||||
if secs, err := strconv.Atoi(h); err == nil && secs > 0 {
|
||||
l.Debugln(c, "announce Retry-After:", secs, err)
|
||||
slog.DebugContext(ctx, "server sets retry-after", "server", c.server, "seconds", secs)
|
||||
timer.Reset(time.Duration(secs) * time.Second)
|
||||
return
|
||||
}
|
||||
@@ -309,7 +311,7 @@ func (c *globalClient) sendAnnouncement(ctx context.Context, timer *time.Timer)
|
||||
// The server has a recommendation on when we should
|
||||
// reannounce. Follow it.
|
||||
if secs, err := strconv.Atoi(h); err == nil && secs > 0 {
|
||||
l.Debugln(c, "announce Reannounce-After:", secs, err)
|
||||
slog.DebugContext(ctx, "announce sets reannounce-after", "server", c.server, "seconds", secs)
|
||||
timer.Reset(time.Duration(secs) * time.Second)
|
||||
return
|
||||
}
|
||||
@@ -424,7 +426,7 @@ func (c *idCheckingHTTPClient) Post(ctx context.Context, url, ctype string, data
|
||||
|
||||
type errorHolder struct {
|
||||
err error
|
||||
mut stdsync.Mutex // uses stdlib sync as I want this to be trivially embeddable, and there is no risk of blocking
|
||||
mut sync.Mutex // uses stdlib sync as I want this to be trivially embeddable, and there is no risk of blocking
|
||||
}
|
||||
|
||||
func (e *errorHolder) setError(err error) {
|
||||
|
||||
@@ -14,6 +14,7 @@ import (
|
||||
"errors"
|
||||
"fmt"
|
||||
"io"
|
||||
"log/slog"
|
||||
"net"
|
||||
"net/url"
|
||||
"strconv"
|
||||
@@ -23,6 +24,7 @@ import (
|
||||
"google.golang.org/protobuf/proto"
|
||||
|
||||
"github.com/syncthing/syncthing/internal/gen/discoproto"
|
||||
"github.com/syncthing/syncthing/internal/slogutil"
|
||||
"github.com/syncthing/syncthing/lib/beacon"
|
||||
"github.com/syncthing/syncthing/lib/events"
|
||||
"github.com/syncthing/syncthing/lib/protocol"
|
||||
@@ -54,7 +56,7 @@ const (
|
||||
|
||||
func NewLocal(id protocol.DeviceID, addr string, addrList AddressLister, evLogger events.Logger) (FinderService, error) {
|
||||
c := &localClient{
|
||||
Supervisor: suture.New("local", svcutil.SpecWithDebugLogger(l)),
|
||||
Supervisor: suture.New("local", svcutil.SpecWithDebugLogger()),
|
||||
myID: id,
|
||||
addrList: addrList,
|
||||
evLogger: evLogger,
|
||||
@@ -176,7 +178,7 @@ func (c *localClient) recvAnnouncements(ctx context.Context) error {
|
||||
continue
|
||||
}
|
||||
if len(buf) < 4 {
|
||||
l.Debugf("discover: short packet from %s", addr.String())
|
||||
slog.DebugContext(ctx, "received short packet", "address", addr.String())
|
||||
continue
|
||||
}
|
||||
|
||||
@@ -188,25 +190,25 @@ func (c *localClient) recvAnnouncements(ctx context.Context) error {
|
||||
case v13Magic:
|
||||
// Old version
|
||||
if !warnedAbout[addr.String()] {
|
||||
l.Warnf("Incompatible (v0.13) local discovery packet from %v - upgrade that device to connect", addr)
|
||||
slog.ErrorContext(ctx, "Incompatible (v0.13) local discovery packet - upgrade that device to connect", slogutil.Address(addr))
|
||||
warnedAbout[addr.String()] = true
|
||||
}
|
||||
continue
|
||||
|
||||
default:
|
||||
l.Debugf("discover: Incorrect magic %x from %s", magic, addr)
|
||||
slog.DebugContext(ctx, "Incorrect magic", "magic", magic, "address", addr)
|
||||
continue
|
||||
}
|
||||
|
||||
var pkt discoproto.Announce
|
||||
err := proto.Unmarshal(buf[4:], &pkt)
|
||||
if err != nil && !errors.Is(err, io.EOF) {
|
||||
l.Debugf("discover: Failed to unmarshal local announcement from %s (%s):\n%s", addr, err, hex.Dump(buf[4:]))
|
||||
slog.DebugContext(ctx, "Failed to unmarshal local announcement", "address", addr, slogutil.Error(err), "packet", hex.Dump(buf[4:]))
|
||||
continue
|
||||
}
|
||||
|
||||
id, _ := protocol.DeviceIDFromBytes(pkt.Id)
|
||||
l.Debugf("discover: Received local announcement from %s for %s", addr, id)
|
||||
slog.DebugContext(ctx, "Received local announcement", "address", addr, "device", id)
|
||||
|
||||
var newDevice bool
|
||||
if !bytes.Equal(pkt.Id, c.myID[:]) {
|
||||
|
||||
+14
-16
@@ -13,18 +13,20 @@ import (
|
||||
"context"
|
||||
"crypto/tls"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"slices"
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"github.com/thejerf/suture/v4"
|
||||
|
||||
"github.com/syncthing/syncthing/internal/slogutil"
|
||||
"github.com/syncthing/syncthing/lib/config"
|
||||
"github.com/syncthing/syncthing/lib/connections/registry"
|
||||
"github.com/syncthing/syncthing/lib/events"
|
||||
"github.com/syncthing/syncthing/lib/protocol"
|
||||
"github.com/syncthing/syncthing/lib/stringutil"
|
||||
"github.com/syncthing/syncthing/lib/svcutil"
|
||||
"github.com/syncthing/syncthing/lib/sync"
|
||||
)
|
||||
|
||||
// The Manager aggregates results from multiple Finders. Each Finder has
|
||||
@@ -53,7 +55,7 @@ type manager struct {
|
||||
|
||||
func NewManager(myID protocol.DeviceID, cfg config.Wrapper, cert tls.Certificate, evLogger events.Logger, lister AddressLister, registry *registry.Registry) Manager {
|
||||
m := &manager{
|
||||
Supervisor: suture.New("discover.Manager", svcutil.SpecWithDebugLogger(l)),
|
||||
Supervisor: suture.New("discover.Manager", svcutil.SpecWithDebugLogger()),
|
||||
myID: myID,
|
||||
cfg: cfg,
|
||||
cert: cert,
|
||||
@@ -62,7 +64,6 @@ func NewManager(myID protocol.DeviceID, cfg config.Wrapper, cert tls.Certificate
|
||||
registry: registry,
|
||||
|
||||
finders: make(map[string]cachedFinder),
|
||||
mut: sync.NewRWMutex(),
|
||||
}
|
||||
m.Add(svcutil.AsService(m.serve, m.String()))
|
||||
return m
|
||||
@@ -89,7 +90,7 @@ func (m *manager) addLocked(identity string, finder Finder, cacheTime, negCacheT
|
||||
entry.token = &token
|
||||
}
|
||||
m.finders[identity] = entry
|
||||
l.Infoln("Using discovery mechanism:", identity)
|
||||
slog.Info("Using discovery mechanism", "identity", identity)
|
||||
}
|
||||
|
||||
func (m *manager) removeLocked(identity string) {
|
||||
@@ -100,11 +101,11 @@ func (m *manager) removeLocked(identity string) {
|
||||
if entry.token != nil {
|
||||
err := m.Supervisor.Remove(*entry.token)
|
||||
if err != nil {
|
||||
l.Warnf("removing discovery %s: %s", identity, err)
|
||||
slog.Warn("Failed to remove discovery mechanism", slog.String("identity", identity), slogutil.Error(err))
|
||||
}
|
||||
}
|
||||
delete(m.finders, identity)
|
||||
l.Infoln("Stopped using discovery mechanism: ", identity)
|
||||
slog.Info("Stopped using discovery mechanism", "identity", identity)
|
||||
}
|
||||
|
||||
// Lookup attempts to resolve the device ID using any of the added Finders,
|
||||
@@ -117,8 +118,7 @@ func (m *manager) Lookup(ctx context.Context, deviceID protocol.DeviceID) (addre
|
||||
|
||||
if cacheEntry.found && time.Since(cacheEntry.when) < finder.cacheTime {
|
||||
// It's a positive, valid entry. Use it.
|
||||
l.Debugln("cached discovery entry for", deviceID, "at", finder)
|
||||
l.Debugln(" cache:", cacheEntry)
|
||||
slog.DebugContext(ctx, "Found cached discovery entry", "device", deviceID, "finder", finder, "entry", cacheEntry)
|
||||
addresses = append(addresses, cacheEntry.Addresses...)
|
||||
continue
|
||||
}
|
||||
@@ -127,7 +127,7 @@ func (m *manager) Lookup(ctx context.Context, deviceID protocol.DeviceID) (addre
|
||||
if !cacheEntry.found && valid {
|
||||
// It's a negative, valid entry. We should not make another
|
||||
// attempt right now.
|
||||
l.Debugln("negative cache entry for", deviceID, "at", finder, "valid until", cacheEntry.when.Add(finder.negCacheTime), "or", cacheEntry.validUntil)
|
||||
slog.DebugContext(ctx, "Negative cache entry", "device", deviceID, "finder", finder, "until1", cacheEntry.when.Add(finder.negCacheTime), "until2", cacheEntry.validUntil)
|
||||
continue
|
||||
}
|
||||
|
||||
@@ -136,8 +136,7 @@ func (m *manager) Lookup(ctx context.Context, deviceID protocol.DeviceID) (addre
|
||||
|
||||
// Perform the actual lookup and cache the result.
|
||||
if addrs, err := finder.Lookup(ctx, deviceID); err == nil {
|
||||
l.Debugln("lookup for", deviceID, "at", finder)
|
||||
l.Debugln(" addresses:", addrs)
|
||||
slog.DebugContext(ctx, "Got finder result", "device", deviceID, "finder", finder, "address", addrs)
|
||||
addresses = append(addresses, addrs...)
|
||||
finder.cache.Set(deviceID, CacheEntry{
|
||||
Addresses: addrs,
|
||||
@@ -161,8 +160,7 @@ func (m *manager) Lookup(ctx context.Context, deviceID protocol.DeviceID) (addre
|
||||
addresses = stringutil.UniqueTrimmedStrings(addresses)
|
||||
slices.Sort(addresses)
|
||||
|
||||
l.Debugln("lookup results for", deviceID)
|
||||
l.Debugln(" addresses: ", addresses)
|
||||
slog.DebugContext(ctx, "Final lookup results", "device", deviceID, "addresses", addresses)
|
||||
|
||||
return addresses, nil
|
||||
}
|
||||
@@ -262,7 +260,7 @@ func (m *manager) CommitConfiguration(_, to config.Configuration) (handled bool)
|
||||
}
|
||||
gd, err := NewGlobal(srv, m.cert, m.addressLister, m.evLogger, m.registry)
|
||||
if err != nil {
|
||||
l.Warnln("Global discovery:", err)
|
||||
slog.Warn("Failed to initialize global discovery", slogutil.Error(err))
|
||||
continue
|
||||
}
|
||||
|
||||
@@ -279,7 +277,7 @@ func (m *manager) CommitConfiguration(_, to config.Configuration) (handled bool)
|
||||
if _, ok := m.finders[v4Identity]; !ok {
|
||||
bcd, err := NewLocal(m.myID, fmt.Sprintf(":%d", to.Options.LocalAnnPort), m.addressLister, m.evLogger)
|
||||
if err != nil {
|
||||
l.Warnln("IPv4 local discovery:", err)
|
||||
slog.Warn("Failed to initialize IPv4 local discovery", slogutil.Error(err))
|
||||
} else {
|
||||
m.addLocked(v4Identity, bcd, 0, 0)
|
||||
}
|
||||
@@ -290,7 +288,7 @@ func (m *manager) CommitConfiguration(_, to config.Configuration) (handled bool)
|
||||
if _, ok := m.finders[v6Identity]; !ok {
|
||||
mcd, err := NewLocal(m.myID, to.Options.LocalAnnMCAddr, m.addressLister, m.evLogger)
|
||||
if err != nil {
|
||||
l.Warnln("IPv6 local discovery:", err)
|
||||
slog.Warn("Failed to initialize IPv6 local discovery", slogutil.Error(err))
|
||||
} else {
|
||||
m.addLocked(v6Identity, mcd, 0, 0)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user