diff --git a/bittorrent/bittorrent.go b/bittorrent/bittorrent.go index 689427e..ad66eb7 100644 --- a/bittorrent/bittorrent.go +++ b/bittorrent/bittorrent.go @@ -13,8 +13,7 @@ import ( "net/netip" "github.com/pkg/errors" - - "github.com/sot-tech/mochi/pkg/log" + "github.com/rs/zerolog" ) // PeerIDLen is length of peer id field in bytes @@ -126,6 +125,13 @@ type Scrape struct { Incomplete uint32 } +func (s Scrape) MarshalZerologObject(e *zerolog.Event) { + e.Stringer("infoHash", s.InfoHash). + Uint32("snatches", s.Snatches). + Uint32("complete", s.Complete). + Uint32("incomplete", s.Incomplete) +} + // Peer represents the connection details of a peer that is returned in an // announce response. type Peer struct { @@ -181,13 +187,11 @@ func (p Peer) RawString() string { return string(b) } -// LogFields renders the current peer as a set of Logrus fields. -func (p Peer) LogFields() log.Fields { - return log.Fields{ - "id": p.ID, - "ip": p.Addr(), - "port": p.Port(), - } +func (p Peer) MarshalZerologObject(e *zerolog.Event) { + e.Stringer("id", p.ID). + Stringer("address", p.Addr()). + Uint16("port", p.Port()) + } // Equal reports whether p and x are the same. diff --git a/bittorrent/params.go b/bittorrent/params.go index 61dc425..964c884 100644 --- a/bittorrent/params.go +++ b/bittorrent/params.go @@ -6,7 +6,7 @@ import ( "strconv" "strings" - "github.com/sot-tech/mochi/pkg/log" + "github.com/rs/zerolog" ) // Params is used to fetch (optional) request parameters from an Announce. @@ -31,6 +31,8 @@ type Params interface { // For a request of the form "/announce?port=1234" this would return // "port=1234" RawQuery() string + + zerolog.LogObjectMarshaler } var ( @@ -151,7 +153,6 @@ func parseQuery(query string) (q *QueryParams, err error) { // But frontends record these errors to prometheus, which generates // a lot of time series. // We log it here for debugging instead. - log.Debug("failed to unescape query param key", log.Err(err)) return nil, ErrInvalidQueryEscape } value, err = url.QueryUnescape(value) @@ -160,7 +161,6 @@ func parseQuery(query string) (q *QueryParams, err error) { // But frontends record these errors to prometheus, which generates // a lot of time series. // We log it here for debugging instead. - log.Debug("failed to unescape query param value", log.Err(err)) return nil, ErrInvalidQueryEscape } @@ -210,3 +210,7 @@ func (qp *QueryParams) RawPath() string { func (qp *QueryParams) RawQuery() string { return qp.query } + +func (qp QueryParams) MarshalZerologObject(e *zerolog.Event) { + e.Str("path", qp.path).Str("query", qp.query) +} diff --git a/bittorrent/request.go b/bittorrent/request.go index a095109..d76294d 100644 --- a/bittorrent/request.go +++ b/bittorrent/request.go @@ -6,7 +6,7 @@ import ( "sort" "time" - "github.com/sot-tech/mochi/pkg/log" + "github.com/rs/zerolog" ) // RequestAddress wrapper for netip.Addr with Provided flag. @@ -16,6 +16,10 @@ type RequestAddress struct { Provided bool } +func (a RequestAddress) MarshalZerologObject(e *zerolog.Event) { + e.Stringer("address", a.Addr).Bool("provided", a.Provided) +} + // Validate checks if netip.Addr is valid and not unspecified (0.0.0.0) func (a RequestAddress) Validate() bool { return a.IsValid() && !a.IsUnspecified() @@ -38,6 +42,12 @@ func (a RequestAddress) String() string { // connection information about peer type RequestAddresses []RequestAddress +func (aa RequestAddresses) MarshalZerologArray(a *zerolog.Array) { + for _, addr := range aa { + a.Object(addr) + } +} + func (aa RequestAddresses) Len() int { return len(aa) } @@ -89,6 +99,14 @@ func (aa RequestAddresses) GetFirst() netip.Addr { return a } +type Peers []Peer + +func (p Peers) MarshalZerologArray(a *zerolog.Array) { + for _, peer := range p { + a.Object(peer) + } +} + // RequestPeer is bundle of peer ID, provided or // determined addresses and net port type RequestPeer struct { @@ -97,9 +115,15 @@ type RequestPeer struct { RequestAddresses } +func (rp RequestPeer) MarshalZerologObject(e *zerolog.Event) { + e.Stringer("id", rp.ID). + Array("addresses", rp.RequestAddresses). + Uint16("port", rp.Port) +} + // Peers constructs array of Peer-s with the same ID and Port // for every RequestAddress array. -func (rp RequestPeer) Peers() (peers []Peer) { +func (rp RequestPeer) Peers() (peers Peers) { for _, a := range rp.RequestAddresses { peers = append(peers, Peer{ ID: rp.ID, @@ -125,21 +149,18 @@ type AnnounceRequest struct { Params } -// LogFields renders the current response as a set of log fields. -func (r AnnounceRequest) LogFields() log.Fields { - return log.Fields{ - "event": r.Event, - "infoHash": r.InfoHash, - "compact": r.Compact, - "eventProvided": r.EventProvided, - "numWantProvided": r.NumWantProvided, - "numWant": r.NumWant, - "left": r.Left, - "downloaded": r.Downloaded, - "uploaded": r.Uploaded, - "peers": r.RequestPeer, - "params": r.Params, - } +func (r AnnounceRequest) MarshalZerologObject(e *zerolog.Event) { + e.Stringer("event", r.Event). + Stringer("infoHash", r.InfoHash). + Bool("compact", r.Compact). + Bool("eventProvided", r.EventProvided). + Bool("numWantProvided", r.NumWantProvided). + Uint32("numWant", r.NumWant). + Uint64("left", r.Left). + Uint64("downloaded", r.Downloaded). + Uint64("uploaded", r.Uploaded). + Object("peers", r.RequestPeer). + Object("params", r.Params) } // AnnounceResponse represents the parameters used to create an announce @@ -150,19 +171,25 @@ type AnnounceResponse struct { Incomplete uint32 Interval time.Duration MinInterval time.Duration - IPv4Peers []Peer - IPv6Peers []Peer + IPv4Peers Peers + IPv6Peers Peers } -// LogFields renders the current response as a set of log fields. -func (r AnnounceResponse) LogFields() log.Fields { - return log.Fields{ - "compact": r.Compact, - "complete": r.Complete, - "interval": r.Interval, - "minInterval": r.MinInterval, - "ipv4Peers": r.IPv4Peers, - "ipv6Peers": r.IPv6Peers, +func (r AnnounceResponse) MarshalZerologObject(e *zerolog.Event) { + e.Bool("compact", r.Compact). + Uint32("complete", r.Complete). + Uint32("incomplete", r.Incomplete). + Dur("interval", r.Interval). + Dur("minInterval", r.MinInterval). + Array("ipv4Peers", r.IPv4Peers). + Array("ipv6Peers", r.IPv6Peers) +} + +type InfoHashes []InfoHash + +func (i InfoHashes) MarshalZerologArray(a *zerolog.Array) { + for _, ih := range i { + a.Str(ih.String()) } } @@ -171,16 +198,21 @@ type ScrapeRequest struct { // RequestAddresses not used in internal logic, // but MAY be used in middleware (per-ip block etc.) RequestAddresses - InfoHashes []InfoHash + InfoHashes InfoHashes Params Params } -// LogFields renders the current response as a set of log fields. -func (r ScrapeRequest) LogFields() log.Fields { - return log.Fields{ - "ip": r.RequestAddresses, - "infoHashes": r.InfoHashes, - "params": r.Params, +func (r ScrapeRequest) MarshalZerologObject(e *zerolog.Event) { + e.Array("addresses", r.RequestAddresses). + Array("infoHashes", r.InfoHashes). + Object("params", r.Params) +} + +type Scrapes []Scrape + +func (s Scrapes) MarshalZerologArray(a *zerolog.Array) { + for _, scrape := range s { + a.Object(scrape) } } @@ -189,12 +221,9 @@ func (r ScrapeRequest) LogFields() log.Fields { // The Scrapes must be in the same order as the InfoHashes in the corresponding // ScrapeRequest. type ScrapeResponse struct { - Files []Scrape + Files Scrapes } -// LogFields renders the current response as a set of Logrus fields. -func (sr ScrapeResponse) LogFields() log.Fields { - return log.Fields{ - "files": sr.Files, - } +func (sr ScrapeResponse) MarshalZerologObject(e *zerolog.Event) { + e.Array("scrapes", sr.Files) } diff --git a/cmd/mochi/main.go b/cmd/mochi/main.go index 0a9e05d..ea027b5 100644 --- a/cmd/mochi/main.go +++ b/cmd/mochi/main.go @@ -9,7 +9,6 @@ import ( "strings" "syscall" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" "github.com/sot-tech/mochi/frontend/http" @@ -55,19 +54,19 @@ func (r *Run) Start(ps storage.PeerStorage) error { r.sg = stop.NewGroup() if len(cfg.MetricsAddr) > 0 { - log.Info("starting metrics server", log.Fields{"addr": cfg.MetricsAddr}) + log.Info().Str("addr", cfg.MetricsAddr).Msg("starting metrics server") r.sg.Add(metrics.NewServer(cfg.MetricsAddr)) } else { - log.Info("metrics disabled because of empty address") + log.Info().Msg("metrics disabled because of empty address") } if ps == nil { - log.Info("starting storage", log.Fields{"name": cfg.Storage.Name}) + log.Info().Str("name", cfg.Storage.Name).Msg("starting storage") ps, err = storage.NewStorage(cfg.Storage.Name, cfg.Storage.Config) if err != nil { return fmt.Errorf("failed to create storage: %w", err) } - log.Info("started storage", ps) + log.Info().Object("config", ps).Msg("started storage") } r.storage = ps @@ -83,7 +82,7 @@ func (r *Run) Start(ps storage.PeerStorage) error { r.logic = middleware.NewLogic(cfg.AnnounceInterval, cfg.MinAnnounceInterval, r.storage, preHooks, postHooks) if len(cfg.HTTPConfig) > 0 { - log.Info("starting HTTP frontend", cfg.HTTPConfig) + log.Info().Object("config", cfg.HTTPConfig).Msg("starting HTTP frontend") httpFE, err := http.NewFrontend(r.logic, cfg.HTTPConfig) if err == nil { r.sg.Add(httpFE) @@ -93,7 +92,7 @@ func (r *Run) Start(ps storage.PeerStorage) error { } if len(cfg.UDPConfig) > 0 { - log.Info("starting UDP frontend", cfg.UDPConfig) + log.Info().Object("config", cfg.HTTPConfig).Msg("starting UDP frontend") udpFE, err := udp.NewFrontend(r.logic, cfg.UDPConfig) if err == nil { r.sg.Add(udpFE) @@ -116,18 +115,18 @@ func combineErrors(prefix string, errs []error) error { // Stop shuts down an instance of Conf. func (r *Run) Stop(keepPeerStore bool) (storage.PeerStorage, error) { - log.Debug("stopping frontends and metrics server") + log.Debug().Msg("stopping frontends and metrics server") if errs := r.sg.Stop().Wait(); len(errs) != 0 { return nil, combineErrors("failed while shutting down frontends", errs) } - log.Debug("stopping logic") + log.Debug().Msg("stopping logic") if errs := r.logic.Stop().Wait(); len(errs) != 0 { return nil, combineErrors("failed while shutting down middleware", errs) } if !keepPeerStore { - log.Debug("stopping peer store") + log.Debug().Msg("stopping peer store") if errs := r.storage.Stop().Wait(); len(errs) != 0 { return nil, combineErrors("failed while shutting down peer store", errs) } @@ -140,7 +139,7 @@ func (r *Run) Stop(keepPeerStore bool) (storage.PeerStorage, error) { // RootRunCmdFunc implements a Cobra command that runs an instance of Conf // and handles reloading and shutdown via process signals. func RootRunCmdFunc(cmd *cobra.Command, _ []string) error { - configFilePath, err := cmd.Flags().GetString("config") + configFilePath, err := cmd.Flags().GetString(configArg) if err != nil { return err } @@ -156,7 +155,7 @@ func RootRunCmdFunc(cmd *cobra.Command, _ []string) error { for { select { case <-reload.Done(): - log.Info("reloading; received reload signal") + log.Info().Msg("reloading; received reload signal") peerStore, err := r.Stop(true) if err != nil { return err @@ -166,7 +165,7 @@ func RootRunCmdFunc(cmd *cobra.Command, _ []string) error { return err } case <-shutdown.Done(): - log.Info("shutting down; received shutdown signal") + log.Info().Msg("shutting down; received shutdown signal") if _, err := r.Stop(false); err != nil { return err } @@ -176,56 +175,60 @@ func RootRunCmdFunc(cmd *cobra.Command, _ []string) error { } } -// RootPreRunCmdFunc handles command line flags for the Run command. -func RootPreRunCmdFunc(cmd *cobra.Command, _ []string) error { - noColors, err := cmd.Flags().GetBool("nocolors") +const ( + appName = "mochi" + logOutArg = "logOut" + logLevelArg = "logLevel" + logPrettyArg = "logPretty" + logColorsArg = "logColored" + configArg = "config" +) + +// configureLogger handles command line flags for the logger. +func configureLogger(cmd *cobra.Command, _ []string) (err error) { + var out, lvl string + var pretty, colored bool + + flags := cmd.Flags() + + out, err = flags.GetString(logOutArg) if err != nil { return err } - if noColors { - log.SetFormatter(&logrus.TextFormatter{DisableColors: true}) - } - jsonLog, err := cmd.Flags().GetBool("json") + lvl, err = flags.GetString(logLevelArg) if err != nil { return err } - if jsonLog { - log.SetFormatter(&logrus.JSONFormatter{}) - log.Info("enabled JSON logging") - } - debugLog, err := cmd.Flags().GetBool("debug") + pretty, err = flags.GetBool(logPrettyArg) if err != nil { return err } - if debugLog { - log.SetDebug(true) - log.Info("enabled debug logging") + + colored, err = cmd.Flags().GetBool(logColorsArg) + if err != nil { + return err } - return nil -} - -// RootPostRunCmdFunc handles clean up of any state initialized by command line -// flags. -func RootPostRunCmdFunc(_ *cobra.Command, _ []string) error { - return nil + return log.ConfigureLogger(out, lvl, pretty, colored) } func main() { rootCmd := &cobra.Command{ - Use: "mochi", - Short: "BitTorrent Tracker", - Long: "A customizable, multi-protocol BitTorrent Tracker", - PersistentPreRunE: RootPreRunCmdFunc, - RunE: RootRunCmdFunc, - PersistentPostRunE: RootPostRunCmdFunc, + Use: appName, + Short: "BitTorrent Tracker", + Long: "A customizable, multi-protocol BitTorrent Tracker", + PersistentPreRunE: configureLogger, + RunE: RootRunCmdFunc, } - rootCmd.PersistentFlags().Bool("debug", false, "enable debug logging") - rootCmd.PersistentFlags().Bool("json", false, "enable json logging") - rootCmd.PersistentFlags().Bool("nocolors", runtime.GOOS == "windows", "disable log coloring") + flags := rootCmd.PersistentFlags() + + flags.String(logOutArg, "", "output for logging, might be 'stderr', 'stdout' of file path. 'stderr' if not set") + flags.String(logLevelArg, "info", "logging level (trace, debug, info, warn, error, fatal, panic). 'warn' if not set") + flags.Bool(logPrettyArg, false, "enable log pretty print. used only if 'logOut' set to 'stdout' or 'stderr'. if not set, log outputs json)") + flags.Bool(logColorsArg, runtime.GOOS == "windows", "enable log coloring. used only if set 'logPretty'") rootCmd.Flags().String("config", "/etc/mochi.yaml", "location of configuration file") @@ -234,6 +237,6 @@ func main() { } if err := rootCmd.Execute(); err != nil { - log.Fatal("failed when executing root cobra command: " + err.Error()) + log.Fatal().Err(err).Msg("failed while executing root command") } } diff --git a/frontend/http/frontend.go b/frontend/http/frontend.go index 656f428..dcb8da9 100644 --- a/frontend/http/frontend.go +++ b/frontend/http/frontend.go @@ -20,6 +20,8 @@ import ( "github.com/sot-tech/mochi/pkg/stop" ) +var logger = log.NewLogger("http frontend") + // Config represents all of the configurable options for an HTTP BitTorrent // Frontend. type Config struct { @@ -38,29 +40,6 @@ type Config struct { ParseOptions } -// LogFields renders the current config as a set of Logrus fields. -func (cfg Config) LogFields() log.Fields { - return log.Fields{ - "addr": cfg.Addr, - "httpsAddr": cfg.HTTPSAddr, - "readTimeout": cfg.ReadTimeout, - "writeTimeout": cfg.WriteTimeout, - "idleTimeout": cfg.IdleTimeout, - "enableKeepAlive": cfg.EnableKeepAlive, - "tlsCertPath": cfg.TLSCertPath, - "tlsKeyPath": cfg.TLSKeyPath, - "announceRoutes": cfg.AnnounceRoutes, - "scrapeRoutes": cfg.ScrapeRoutes, - "pingRoutes": cfg.PingRoutes, - "enableRequestTiming": cfg.EnableRequestTiming, - "allowIPSpoofing": cfg.AllowIPSpoofing, - "realIPHeader": cfg.RealIPHeader, - "maxNumWant": cfg.MaxNumWant, - "defaultNumWant": cfg.DefaultNumWant, - "maxScrapeInfoHashes": cfg.MaxScrapeInfoHashes, - } -} - // Default config constants. const ( defaultReadTimeout = 2 * time.Second @@ -77,20 +56,21 @@ func (cfg Config) Validate() Config { if cfg.ReadTimeout <= 0 { validcfg.ReadTimeout = defaultReadTimeout - log.Warn("falling back to default configuration", log.Fields{ - "name": "http.ReadTimeout", - "provided": cfg.ReadTimeout, - "default": validcfg.ReadTimeout, - }) + logger.Warn(). + Str("name", "http.ReadTimeout"). + Dur("provided", cfg.ReadTimeout). + Dur("default", validcfg.ReadTimeout). + Msg("falling back to default configuration") + } if cfg.WriteTimeout <= 0 { validcfg.WriteTimeout = defaultWriteTimeout - log.Warn("falling back to default configuration", log.Fields{ - "name": "http.WriteTimeout", - "provided": cfg.WriteTimeout, - "default": validcfg.WriteTimeout, - }) + logger.Warn(). + Str("name", "http.WriteTimeout"). + Dur("provided", cfg.WriteTimeout). + Dur("default", validcfg.WriteTimeout). + Msg("falling back to default configuration") } if cfg.IdleTimeout <= 0 { @@ -98,11 +78,11 @@ func (cfg Config) Validate() Config { if cfg.EnableKeepAlive { // If keepalive is disabled, this configuration isn't used anyway. - log.Warn("falling back to default configuration", log.Fields{ - "name": "http.IdleTimeout", - "provided": cfg.IdleTimeout, - "default": validcfg.IdleTimeout, - }) + logger.Warn(). + Str("name", "http.IdleTimeout"). + Dur("provided", cfg.IdleTimeout). + Dur("default", validcfg.IdleTimeout). + Msg("falling back to default configuration") } } @@ -178,7 +158,7 @@ func NewFrontend(logic frontend.TrackerLogic, c conf.MapConfig) (*Frontend, erro if cfg.Addr != "" { go func() { if err := f.serveHTTP(router, false); err != nil { - log.Fatal("failed while serving http", log.Err(err)) + logger.Fatal().Err(err).Str("proto", "http").Msg("failed while serving") } }() } @@ -186,7 +166,7 @@ func NewFrontend(logic frontend.TrackerLogic, c conf.MapConfig) (*Frontend, erro if cfg.HTTPSAddr != "" { go func() { if err := f.serveHTTP(router, true); err != nil { - log.Fatal("failed while serving https", log.Err(err)) + logger.Fatal().Err(err).Str("proto", "https").Msg("failed while serving") } }() } @@ -194,7 +174,7 @@ func NewFrontend(logic frontend.TrackerLogic, c conf.MapConfig) (*Frontend, erro return f, nil } -// Stop provides a thread-safe way to shutdown a currently running Frontend. +// Stop provides a thread-safe way to shut down a currently running Frontend. func (f *Frontend) Stop() stop.Result { stopGroup := stop.NewGroup() diff --git a/frontend/http/writer.go b/frontend/http/writer.go index 79a785e..8b194be 100644 --- a/frontend/http/writer.go +++ b/frontend/http/writer.go @@ -9,7 +9,6 @@ import ( "github.com/anacrolix/torrent/bencode" "github.com/sot-tech/mochi/bittorrent" - "github.com/sot-tech/mochi/pkg/log" ) // WriteError communicates an error to a BitTorrent client over HTTP. @@ -19,13 +18,13 @@ func WriteError(w http.ResponseWriter, err error) { if errors.As(err, &clientErr) { message = clientErr.Error() } else { - log.Error("http: internal error", log.Err(err)) + logger.Error().Err(err).Msg("http: internal error") } if err = bencode.NewEncoder(w).Encode(map[string]any{ "failure reason": message, }); err != nil { - log.Error("unable to encode message", log.Err(err)) + logger.Error().Err(err).Msg("unable to encode message") } } diff --git a/frontend/options.go b/frontend/options.go index 093e6a4..ce5b955 100644 --- a/frontend/options.go +++ b/frontend/options.go @@ -2,6 +2,8 @@ package frontend import "github.com/sot-tech/mochi/pkg/log" +var logger = log.NewLogger("frontend configurator") + // ParseOptions is the configuration used to parse an Announce Request. // // If AllowIPSpoofing is true, IPs provided via params will be used. @@ -18,29 +20,29 @@ func (op ParseOptions) Validate() ParseOptions { valid := op if op.MaxNumWant <= 0 { valid.MaxNumWant = defaultMaxNumWant - log.Warn("falling back to default configuration", log.Fields{ - "name": "MaxNumWant", - "provided": op.MaxNumWant, - "default": valid.MaxNumWant, - }) + logger.Warn(). + Str("name", "MaxNumWant"). + Uint32("provided", op.MaxNumWant). + Uint32("default", valid.MaxNumWant). + Msg("falling back to default configuration") } if op.DefaultNumWant <= 0 { valid.DefaultNumWant = defaultDefaultNumWant - log.Warn("falling back to default configuration", log.Fields{ - "name": "DefaultNumWant", - "provided": op.DefaultNumWant, - "default": valid.DefaultNumWant, - }) + logger.Warn(). + Str("name", "DefaultNumWant"). + Uint32("provided", op.DefaultNumWant). + Uint32("default", valid.DefaultNumWant). + Msg("falling back to default configuration") } if op.MaxScrapeInfoHashes <= 0 { valid.MaxScrapeInfoHashes = defaultMaxScrapeInfoHashes - log.Warn("falling back to default configuration", log.Fields{ - "name": "MaxScrapeInfoHashes", - "provided": op.MaxScrapeInfoHashes, - "default": valid.MaxScrapeInfoHashes, - }) + logger.Warn(). + Str("name", "MaxScrapeInfoHashes"). + Uint32("provided", op.MaxScrapeInfoHashes). + Uint32("default", valid.MaxScrapeInfoHashes). + Msg("falling back to default configuration") } return valid } diff --git a/frontend/udp/connection_id.go b/frontend/udp/connection_id.go index f8bcd5a..de5df66 100644 --- a/frontend/udp/connection_id.go +++ b/frontend/udp/connection_id.go @@ -81,14 +81,22 @@ func (g *ConnectionIDGenerator) Generate(ip netip.Addr, now time.Time) []byte { g.scratch = g.mac.Sum(g.scratch) copy(g.connID[4:8], g.scratch[:4]) - log.Debug("generated connection ID", log.Fields{"ip": ip, "now": now, "connID": g.connID}) + log.Debug(). + Stringer("ip", ip). + Time("now", now). + Bytes("connID", g.connID). + Msg("generated connection ID") return g.connID } // Validate validates the given connection ID for an IP and the current time. func (g *ConnectionIDGenerator) Validate(connectionID []byte, ip netip.Addr, now time.Time, maxClockSkew time.Duration) bool { ts := time.Unix(int64(binary.BigEndian.Uint32(connectionID[:4])), 0) - log.Debug("validating connection ID", log.Fields{"connID": connectionID, "ip": ip, "ts": ts, "now": now}) + log.Debug(). + Stringer("ip", ip). + Time("ts", ts).Time("now", now). + Bytes("connID", g.connID). + Msg("validating connection ID") if now.After(ts.Add(ttl)) || ts.After(now.Add(maxClockSkew)) { return false } diff --git a/frontend/udp/connection_id_test.go b/frontend/udp/connection_id_test.go index edc44b2..90f1022 100644 --- a/frontend/udp/connection_id_test.go +++ b/frontend/udp/connection_id_test.go @@ -57,7 +57,11 @@ func simpleNewConnectionID(ip netip.Addr, now time.Time, key string) []byte { // this is just in here because logging impacts performance and we benchmark // this version too. - log.Debug("manually generated connection ID", log.Fields{"ip": ip, "now": now, "connID": buf}) + log.Debug(). + Stringer("ip", ip). + Time("now", now). + Bytes("connID", buf). + Msg("manually generated connection ID") return buf } diff --git a/frontend/udp/frontend.go b/frontend/udp/frontend.go index 4d4451b..724719e 100644 --- a/frontend/udp/frontend.go +++ b/frontend/udp/frontend.go @@ -23,6 +23,8 @@ import ( "github.com/sot-tech/mochi/pkg/timecache" ) +var logger = log.NewLogger("udp frontend") + var allowedGeneratedPrivateKeyRunes = []rune("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890") // Config represents all of the configurable options for a UDP BitTorrent @@ -35,20 +37,6 @@ type Config struct { frontend.ParseOptions } -// LogFields renders the current config as a set of Logrus fields. -func (cfg Config) LogFields() log.Fields { - return log.Fields{ - "addr": cfg.Addr, - "privateKey": cfg.PrivateKey, - "maxClockSkew": cfg.MaxClockSkew, - "enableRequestTiming": cfg.EnableRequestTiming, - "allowIPSpoofing": cfg.AllowIPSpoofing, - "maxNumWant": cfg.MaxNumWant, - "defaultNumWant": cfg.DefaultNumWant, - "maxScrapeInfoHashes": cfg.MaxScrapeInfoHashes, - } -} - // Validate sanity checks values set in a config and returns a new config with // default values replacing anything that is invalid. // @@ -64,7 +52,11 @@ func (cfg Config) Validate() Config { } validcfg.PrivateKey = string(pkeyRunes) - log.Warn("UDP private key was not provided, using generated key", log.Fields{"key": validcfg.PrivateKey}) + log.Warn(). + Str("name", "UDP.PrivateKey"). + Str("provided", ""). + Str("key", validcfg.PrivateKey). + Msg("falling back to default configuration") } validcfg.ParseOptions = cfg.ParseOptions.Validate() @@ -111,7 +103,7 @@ func NewFrontend(logic frontend.TrackerLogic, c conf.MapConfig) (*Frontend, erro f.wg.Add(1) go func() { if err := f.serve(); err != nil { - log.Fatal("failed while serving udp", log.Err(err)) + logger.Fatal().Err(err).Str("proto", "udp").Msg("failed while serving") } }() @@ -157,7 +149,7 @@ func (t *Frontend) serve() error { // Check to see if we need to shutdown. select { case <-t.closing: - log.Debug("udp serve() received shutdown signal") + log.Debug().Msg("serve received shutdown signal") return nil default: } diff --git a/go.mod b/go.mod index 67b26a7..e36c2fd 100644 --- a/go.mod +++ b/go.mod @@ -3,6 +3,7 @@ module github.com/sot-tech/mochi go 1.18 require ( + code.cloudfoundry.org/go-diodes v0.0.0-20220420211542-53509ccdf174 github.com/SermoDigital/jose v0.9.2-0.20180104203859-803625baeddc github.com/anacrolix/torrent v1.42.0 github.com/go-redis/redis/v8 v8.11.5 @@ -12,7 +13,8 @@ require ( github.com/mitchellh/mapstructure v1.5.0 github.com/pkg/errors v0.9.1 github.com/prometheus/client_golang v1.12.1 - github.com/sirupsen/logrus v1.8.1 + github.com/rs/zerolog v1.26.1 + github.com/sirupsen/logrus v1.6.0 github.com/spf13/cobra v1.4.0 github.com/stretchr/testify v1.7.1 gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b @@ -33,6 +35,7 @@ require ( github.com/huandu/xstrings v1.3.2 // indirect github.com/inconshreveable/mousetrap v1.0.0 // indirect github.com/klauspost/cpuid/v2 v2.0.12 // indirect + github.com/konsorten/go-windows-terminal-sequences v1.0.3 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.1 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect github.com/prometheus/client_model v0.2.0 // indirect diff --git a/go.sum b/go.sum index 55c6f9f..7c765ff 100644 --- a/go.sum +++ b/go.sum @@ -30,6 +30,8 @@ cloud.google.com/go/storage v1.5.0/go.mod h1:tpKbwo567HUNpVclU5sGELwQWBDZ8gh0Zeo cloud.google.com/go/storage v1.6.0/go.mod h1:N7U0C8pVQ/+NIKOBQyamJIeKQKkZ+mxpohlUTyfDhBk= cloud.google.com/go/storage v1.8.0/go.mod h1:Wv1Oy7z6Yz3DshWRJFhqM/UCfaWIRTdp0RXyy7KQOVs= cloud.google.com/go/storage v1.10.0/go.mod h1:FLPqc6j+Ki4BU591ie1oL6qBQGu2Bl/tZ9ullr3+Kg0= +code.cloudfoundry.org/go-diodes v0.0.0-20220420211542-53509ccdf174 h1:Ht2zKWftukU3F3ACIdE8asNhso3DgHPzaCDO2K5SWmA= +code.cloudfoundry.org/go-diodes v0.0.0-20220420211542-53509ccdf174/go.mod h1:HLP7HKUU1eqMAGMk247yT91tDDi4xxnehkyXh6hGcr0= crawshaw.io/iox v0.0.0-20181124134642-c51c3df30797/go.mod h1:sXBiorCo8c46JlQV3oXPKINnZ8mcqnye1EkVkqsectk= crawshaw.io/sqlite v0.3.2/go.mod h1:igAO5JulrQ1DbdZdtVq48mnZUBAPOeFzer7VhDWNtW4= dmitri.shuralyov.com/gpu/mtl v0.0.0-20190408044501-666a987793e9/go.mod h1:H6x//7gZCb22OMCxBHrMx7a5I7Hp++hsVxbQ4BYO7hU= @@ -92,6 +94,7 @@ github.com/chzyer/readline v0.0.0-20180603132655-2972be24d48e/go.mod h1:nSuG5e5P github.com/chzyer/test v0.0.0-20180213035817-a1ea475d72b1/go.mod h1:Q3SI9o4m/ZMnBNeIyt5eFwwo7qiLfzFZmjNmxjkiQlU= github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDkc90ppPyw= github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGXZJjfX53e64911xZQV5JYwmTeXPW+k8Sc= +github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/cpuguy83/go-md2man/v2 v2.0.1/go.mod h1:tgQtvFlXSQOSOSIRvRPT7W67SCa46tRHOmNcaadrF8o= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -133,6 +136,7 @@ github.com/go-logfmt/logfmt v0.5.1/go.mod h1:WYhtIu8zTZfxdn5+rREduYbwxfcBr/Vr6KE github.com/go-redis/redis/v8 v8.11.5 h1:AcZZR7igkdvfVmQTPnu9WE37LRrO/YrBH5zWyjDC0oI= github.com/go-redis/redis/v8 v8.11.5/go.mod h1:gREzHqY1hg6oD9ngVRbLStwAWKhA0FEgq8Jd4h5lpwo= github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ= github.com/gogo/protobuf v1.2.0/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q= @@ -226,6 +230,7 @@ github.com/klauspost/cpuid/v2 v2.0.4/go.mod h1:FInQzS24/EEf25PyTYn52gqo7WaD8xa02 github.com/klauspost/cpuid/v2 v2.0.12 h1:p9dKCg8i4gmOxtv35DvrYoWqYzQrvEVdjQ762Y0OqZE= github.com/klauspost/cpuid/v2 v2.0.12/go.mod h1:g2LTdtYhdyuGPqyWyv7qRAmj1WBqxuObKfj5c0PQa7c= github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ= +github.com/konsorten/go-windows-terminal-sequences v1.0.3 h1:CE8S1cTafDpPvMhIxNJKvHsGVBgn1xWYf1NbHQhywc8= github.com/konsorten/go-windows-terminal-sequences v1.0.3/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ= github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= @@ -257,7 +262,7 @@ github.com/onsi/ginkgo v1.6.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+W github.com/onsi/ginkgo v1.7.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE= github.com/onsi/ginkgo v1.16.5 h1:8xi0RTUf59SOSfEtZMvwTvXYMzG4gV23XVHOZiXNtnE= github.com/onsi/gomega v1.4.3/go.mod h1:ex+gbHU/CVuBBDIJjb2X0qEXbFg53c61hWP/1CpauHY= -github.com/onsi/gomega v1.18.1 h1:M1GfJqGRrBrrGGsbxzV5dqM2U2ApXefZCQpkukxYRLE= +github.com/onsi/gomega v1.19.0 h1:4ieX6qQjPP/BfC3mpsAtIGGlxTWPeA3Inl/7DtXw1tw= github.com/openzipkin/zipkin-go v0.1.6/go.mod h1:QgAqvLzwWbR/WpD4A3cGpPtJrZXNIiJc5AZX7/PBEpw= github.com/philhofer/fwd v1.0.0/go.mod h1:gk3iGcWd9+svBvR0sR+KPcfE+RNWozjowpeBVG3ZVNU= github.com/pierrec/lz4 v2.0.5+incompatible/go.mod h1:pdkljMzZIN41W+lC3N2tnIh5sFi+IEE17M5jbnwPHcY= @@ -304,13 +309,15 @@ github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFR github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc= github.com/rogpeppe/go-internal v1.8.0 h1:FCbCCtXNOY3UtUuHUYaghJg4y7Fd14rXifAYUAtL9R8= github.com/rogpeppe/go-internal v1.8.0/go.mod h1:WmiCO8CzOY8rg0OYDC4/i/2WRWAB6poM+XZ2dLUbcbE= +github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.26.1 h1:/ihwxqH+4z8UxyI70wM1z9yCvkWcfz/a3mj48k/Zngc= +github.com/rs/zerolog v1.26.1/go.mod h1:/wSSJWX7lVrsOwlbyTRSOJvqRlc+WjWlfes+CiJ+tmc= github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM= github.com/ryszard/goskiplist v0.0.0-20150312221310-2dfbae5fcf46/go.mod h1:uAQ5PCi+MFsC7HjREoAz1BU+Mq60+05gifQSsHSDG/8= github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo= github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE= +github.com/sirupsen/logrus v1.6.0 h1:UBcNElsrwanuuMsnGSlYmtmgbb23qDR5dG+6X6Oo89I= github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88= -github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE= -github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= github.com/smartystreets/assertions v0.0.0-20190215210624-980c5ac6f3ac/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= github.com/smartystreets/goconvey v0.0.0-20181108003508-044398e4856c/go.mod h1:XDJAKZRPZ1CvBcN2aX5YOUTYGHki24fSF0Iv48Ibg0s= @@ -336,6 +343,7 @@ github.com/willf/bitset v1.1.10/go.mod h1:RjeCKbqT1RxIR/KWY6phxZiaY1IyutSBfGjNPy github.com/yuin/goldmark v1.1.25/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= github.com/yuin/goldmark v1.1.32/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= +github.com/yuin/goldmark v1.4.0/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= go.opencensus.io v0.20.1/go.mod h1:6WKK9ahsWS3RSO+PY9ZHZUfv2irvY6gN279GOPZjmmk= go.opencensus.io v0.20.2/go.mod h1:6WKK9ahsWS3RSO+PY9ZHZUfv2irvY6gN279GOPZjmmk= go.opencensus.io v0.21.0/go.mod h1:mSImk1erAIZhrmZN+AvHh14ztQfjbGwt4TtuofqLduU= @@ -349,6 +357,7 @@ golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8U golang.org/x/crypto v0.0.0-20190605123033-f99c8df09eb5/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto= +golang.org/x/crypto v0.0.0-20211215165025-cf75a172585e/go.mod h1:P+XmwS30IXTQdn5tA2iutPOUgjI07+tq3H3K9MVA1s8= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20190306152737-a1d7652674e8/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20190510132918-efd6b22b2522/go.mod h1:ZjyILWgesfNpC6sMxTJOJm9Kp84zZh5NQWvqDGG3Qr8= @@ -379,6 +388,7 @@ golang.org/x/mod v0.1.1-0.20191105210325-c90efee705ee/go.mod h1:QqPTAvyqsEbceGzB golang.org/x/mod v0.1.1-0.20191107180719-034126e5016b/go.mod h1:QqPTAvyqsEbceGzBzNggFXnrqF1CaUcvgkdR5Ot7KZg= golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= +golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180906233101-161cd47e91fd/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= @@ -409,7 +419,9 @@ golang.org/x/net v0.0.0-20200520182314-0ba52f642ac2/go.mod h1:qpuaurCH72eLCgpAm/ golang.org/x/net v0.0.0-20200625001655-4c5254603344/go.mod h1:/O7V0waA8r7cgGh81Ro3o1hOxt32SMVPicZroKQ2sZA= golang.org/x/net v0.0.0-20200707034311-ab3426394381/go.mod h1:/O7V0waA8r7cgGh81Ro3o1hOxt32SMVPicZroKQ2sZA= golang.org/x/net v0.0.0-20200822124328-c89045814202/go.mod h1:/O7V0waA8r7cgGh81Ro3o1hOxt32SMVPicZroKQ2sZA= +golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg= golang.org/x/net v0.0.0-20210525063256-abc453219eb5/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y= +golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y= golang.org/x/net v0.0.0-20220127200216-cd36cc0744dd/go.mod h1:CfG3xpIq0wQ8r1q4Su4UZFWDARRcnwPjda9FqA0JpMk= golang.org/x/net v0.0.0-20220225172249-27dd8689420f h1:oA4XRj0qtSt8Yo1Zms0CUlsT3KG69V2UGQWPBxujDmc= golang.org/x/net v0.0.0-20220225172249-27dd8689420f/go.mod h1:CfG3xpIq0wQ8r1q4Su4UZFWDARRcnwPjda9FqA0JpMk= @@ -429,6 +441,7 @@ golang.org/x/sync v0.0.0-20190911185100-cd5d95a43a6e/go.mod h1:RxMgew5VJxzue5/jJ golang.org/x/sync v0.0.0-20200317015054-43a5402ce75a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20200625203802-6e8e738ad208/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20201207232520-09787c993a3a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sys v0.0.0-20180830151530-49385e6e1522/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= @@ -444,7 +457,6 @@ golang.org/x/sys v0.0.0-20190606165138-5da285871e9c/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20190624142023-c5567b49c5d0/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20190726091711-fc99dfbffb4e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191001151750-bb3f8db39f24/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191204072324-ce4227a45e2e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191228213918-04cbcbbfeed8/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200106162015-b016eb3dc98e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= @@ -470,6 +482,7 @@ golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20210603081109-ebe580a85c40/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20211216021012-1d35b9e2eb4e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220114195835-da31bd327af9/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220422013727-9388b58f7150 h1:xHms4gcpe1YE7A3yIllJXP16CMAGuqwO2lX1mTyyRRc= @@ -528,6 +541,7 @@ golang.org/x/tools v0.0.0-20200618134242-20370b0cb4b2/go.mod h1:EkVYQZoAsY45+roY golang.org/x/tools v0.0.0-20200729194436-6467de6f59a7/go.mod h1:njjCfa9FT2d7l9Bc6FUM5FLjQPp3cFF28FI3qnDFljA= golang.org/x/tools v0.0.0-20200804011535-6c149bb5ef0d/go.mod h1:njjCfa9FT2d7l9Bc6FUM5FLjQPp3cFF28FI3qnDFljA= golang.org/x/tools v0.0.0-20200825202427-b303f430e36d/go.mod h1:njjCfa9FT2d7l9Bc6FUM5FLjQPp3cFF28FI3qnDFljA= +golang.org/x/tools v0.1.7/go.mod h1:LGqMHiF4EqQNHR1JncWGqT5BVaXmza+X+BDGol+dOxo= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= diff --git a/middleware/jwt/jwt.go b/middleware/jwt/jwt.go index 9ad1683..6875968 100644 --- a/middleware/jwt/jwt.go +++ b/middleware/jwt/jwt.go @@ -14,7 +14,6 @@ import ( "errors" "fmt" "net/http" - "strings" "time" jc "github.com/SermoDigital/jose/crypto" @@ -38,11 +37,18 @@ func init() { } var ( + logger = log.NewLogger(Name) // ErrMissingJWT is returned when a JWT is missing from a request. ErrMissingJWT = bittorrent.ClientError("unapproved request: missing jwt") // ErrInvalidJWT is returned when a JWT fails to verify. ErrInvalidJWT = bittorrent.ClientError("unapproved request: invalid jwt") + + errInvalidInfoHashClaim = errors.New("claim \"infohash\" is invalid") + + errInvalidKid = errors.New("invalid kid") + + errUnknownKidSigner = errors.New("signed by unknown kid") ) // Config represents all the values required by this middleware to fetch JWKs @@ -54,16 +60,6 @@ type Config struct { JWKUpdateInterval time.Duration `cfg:"jwk_set_update_interval"` } -// LogFields implements log.Fielder for a Config. -func (cfg Config) LogFields() log.Fields { - return log.Fields{ - "issuer": cfg.Issuer, - "audience": cfg.Audience, - "JWKSetURL": cfg.JWKSetURL, - "JWKUpdateInterval": cfg.JWKUpdateInterval, - } -} - type hook struct { cfg Config publicKeys map[string]crypto.PublicKey @@ -77,14 +73,14 @@ func build(options conf.MapConfig, _ storage.PeerStorage) (middleware.Hook, erro return nil, fmt.Errorf("middleware %s: %w", Name, err) } - log.Debug("creating new JWT middleware", options) + logger.Debug().Object("options", options).Msg("creating new JWT middleware") h := &hook{ cfg: cfg, publicKeys: map[string]crypto.PublicKey{}, closing: make(chan struct{}), } - log.Debug("performing initial fetch of JWKs") + logger.Debug().Msg("performing initial fetch of JWKs") if err := h.updateKeys(); err != nil { return nil, fmt.Errorf("failed to fetch initial JWK Set: %w", err) } @@ -95,7 +91,7 @@ func build(options conf.MapConfig, _ storage.PeerStorage) (middleware.Hook, erro case <-h.closing: return case <-time.After(cfg.JWKUpdateInterval): - log.Debug("performing fetch of JWKs") + logger.Debug().Msg("performing fetch of JWKs") _ = h.updateKeys() } } @@ -107,14 +103,14 @@ func build(options conf.MapConfig, _ storage.PeerStorage) (middleware.Hook, erro func (h *hook) updateKeys() error { resp, err := http.Get(h.cfg.JWKSetURL) if err != nil { - log.Error("failed to fetch JWK Set", log.Err(err)) + logger.Error().Err(err).Msg("failed to fetch JWK Set") return err } defer resp.Body.Close() var parsedJWKs gojwk.Key err = json.NewDecoder(resp.Body).Decode(&parsedJWKs) if err != nil { - log.Error("failed to decode JWK JSON", log.Err(err)) + logger.Error().Err(err).Msg("failed to decode JWK JSON") return err } @@ -122,19 +118,19 @@ func (h *hook) updateKeys() error { for _, parsedJWK := range parsedJWKs.Keys { publicKey, err := parsedJWK.DecodePublicKey() if err != nil { - log.Error("failed to decode JWK into public key", log.Err(err)) + logger.Error().Err(err).Msg("failed to decode JWK into public key") return err } keys[parsedJWK.Kid] = publicKey } h.publicKeys = keys - log.Debug("successfully fetched JWK Set") + logger.Debug().Msg("successfully fetched JWK Set") return nil } func (h *hook) Stop() stop.Result { - log.Debug("attempting to shutdown JWT middleware") + logger.Debug().Msg("attempting to shutdown JWT middleware") select { case <-h.closing: return stop.AlreadyStopped @@ -178,53 +174,51 @@ func validateJWT(ih bittorrent.InfoHash, jwtBytes []byte, cfgIss, cfgAud string, claims := parsedJWT.Claims() if iss, ok := claims.Issuer(); !ok || iss != cfgIss { - log.Debug("unequal or missing issuer when validating JWT", log.Fields{ - "exists": ok, - "claim": iss, - "config": cfgIss, - }) + logger.Debug(). + Bool("exists", ok). + Str("claim", iss). + Str("config", cfgIss). + Msg("unequal or missing issuer when validating JWT") return jwt.ErrInvalidISSClaim } if auds, ok := claims.Audience(); !ok || !in(cfgAud, auds) { - log.Debug("unequal or missing audience when validating JWT", log.Fields{ - "exists": ok, - "claim": strings.Join(auds, ","), - "config": cfgAud, - }) + logger.Debug(). + Bool("exists", ok). + Strs("claim", auds). + Str("config", cfgAud). + Msg("unequal or missing audience when validating JWT") return jwt.ErrInvalidAUDClaim } ihHex := hex.EncodeToString([]byte(ih)) if ihClaim, ok := claims.Get("infohash").(string); !ok || ihClaim != ihHex { - log.Debug("unequal or missing infohash when validating JWT", log.Fields{ - "exists": ok, - "claim": ihClaim, - "request": ihHex, - }) - return errors.New("claim \"infohash\" is invalid") + logger.Debug(). + Bool("exists", ok). + Str("claim", ihClaim). + Str("request", ihHex). + Msg("unequal or missing infohash when validating JWT") + return errInvalidInfoHashClaim } parsedJWS := parsedJWT.(jws.JWS) kid, ok := parsedJWS.Protected().Get("kid").(string) if !ok { - log.Debug("missing kid when validating JWT", log.Fields{ - "exists": ok, - "claim": kid, - }) - return errors.New("invalid kid") + logger.Debug(). + Bool("exists", ok). + Str("claim", kid). + Msg("missing kid when validating JWT") + return errInvalidKid } publicKey, ok := publicKeys[kid] if !ok { - log.Debug("missing public key forkid when validating JWT", log.Fields{ - "kid": kid, - }) - return errors.New("signed by unknown kid") + logger.Debug().Str("claim", kid).Msg("missing public key forkid when validating JWT") + return errUnknownKidSigner } err = parsedJWS.Verify(publicKey, jc.SigningMethodRS256) if err != nil { - log.Debug("failed to verify signature of JWT", log.Err(err)) + logger.Debug().Err(err).Msg("failed to verify signature of JWT") return err } diff --git a/middleware/logic.go b/middleware/logic.go index 0219012..8319f52 100644 --- a/middleware/logic.go +++ b/middleware/logic.go @@ -11,7 +11,10 @@ import ( "github.com/sot-tech/mochi/storage" ) -var _ frontend.TrackerLogic = &Logic{} +var ( + logger = log.NewLogger("middleware") + _ frontend.TrackerLogic = &Logic{} +) // NewLogic creates a new instance of a TrackerLogic that executes the provided // middleware hooks. @@ -46,7 +49,7 @@ func (l *Logic) HandleAnnounce(ctx context.Context, req *bittorrent.AnnounceRequ } } - log.Debug("generated announce response", resp) + logger.Debug().Object("response", resp).Msg("generated announce response") return ctx, resp, nil } @@ -56,7 +59,10 @@ func (l *Logic) AfterAnnounce(ctx context.Context, req *bittorrent.AnnounceReque var err error for _, h := range l.postHooks { if ctx, err = h.HandleAnnounce(ctx, req, resp); err != nil { - log.Error("post-announce hooks failed", log.Err(err)) + logger.Error().Err(err). + Object("request", req). + Object("response", resp). + Msg("post-announce hooks failed") return } } @@ -73,7 +79,7 @@ func (l *Logic) HandleScrape(ctx context.Context, req *bittorrent.ScrapeRequest) } } - log.Debug("generated scrape response", resp) + logger.Debug().Object("response", resp).Msg("generated scrape response") return ctx, resp, nil } @@ -83,7 +89,11 @@ func (l *Logic) AfterScrape(ctx context.Context, req *bittorrent.ScrapeRequest, var err error for _, h := range l.postHooks { if ctx, err = h.HandleScrape(ctx, req, resp); err != nil { - log.Error("post-scrape hooks failed", log.Err(err)) + logger.Error(). + Err(err). + Object("request", req). + Object("response", resp). + Msg("post-scrape hooks failed") return } } diff --git a/middleware/torrentapproval/container/directory/directory.go b/middleware/torrentapproval/container/directory/directory.go index 82c88f8..365bc67 100644 --- a/middleware/torrentapproval/container/directory/directory.go +++ b/middleware/torrentapproval/container/directory/directory.go @@ -23,6 +23,8 @@ import ( // Name of this container for registry const Name = "directory" +var logger = log.NewLogger("torrent approval directory") + func init() { container.Register(Name, build) } diff --git a/pkg/conf/decoder.go b/pkg/conf/decoder.go index 10321b9..0702b03 100644 --- a/pkg/conf/decoder.go +++ b/pkg/conf/decoder.go @@ -6,8 +6,7 @@ import ( "errors" "github.com/mitchellh/mapstructure" - - "github.com/sot-tech/mochi/pkg/log" + "github.com/rs/zerolog" ) // TagName is a tag name, used for decoder customization @@ -20,9 +19,8 @@ var ErrNilConfigMap = errors.New("unable to process nil map") // MapConfig is just alias for map[string]any type MapConfig map[string]any -// LogFields just returns this map as a set of Logrus fields. -func (m MapConfig) LogFields() log.Fields { - return log.Fields(m) +func (m MapConfig) MarshalZerologObject(e *zerolog.Event) { + e.Fields(map[string]any(m)) } // Unmarshal decodes receiver map into provided structure. diff --git a/pkg/log/log.go b/pkg/log/log.go index a32e69f..1ccd2dd 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -3,132 +3,78 @@ package log import ( - "fmt" "io" + "os" + "strings" + "time" - "github.com/sirupsen/logrus" + _ "code.cloudfoundry.org/go-diodes" + "github.com/rs/zerolog" + "github.com/rs/zerolog/diode" + zl "github.com/rs/zerolog/log" ) -var ( - l = logrus.New() - debug = false -) +var root = zl.Logger -// SetDebug controls debug logging. -func SetDebug(to bool) { - debug = to - l.Level = logrus.DebugLevel -} +func ConfigureLogger(output, level string, formatted, colored bool) (err error) { + lvl := zerolog.WarnLevel + output = strings.ToLower(output) + var w io.Writer + var stdAny bool + switch output { + case "stderr", "": + w, stdAny = os.Stderr, true + case "stdout": + w, stdAny = os.Stdout, true + default: + if w, err = os.OpenFile(output, os.O_APPEND|os.O_CREATE, 0600); err == nil { + w = diode.NewWriter(w, 1000, 10*time.Millisecond, func(missed int) { + zl.Warn().Int("count", missed).Msg("Logger dropped messages") + }) -// SetFormatter sets the formatter. -func SetFormatter(to logrus.Formatter) { - l.Formatter = to -} - -// SetOutput sets the output. -func SetOutput(to io.Writer) { - l.Out = to -} - -// Fields is a map of logging fields. -type Fields map[string]any - -// LogFields implements Fielder for Fields. -func (f Fields) LogFields() Fields { - return f -} - -// A Fielder provides Fields via the LogFields method. -type Fielder interface { - LogFields() Fields -} - -// err is a wrapper around an error. -type err struct { - e error -} - -// LogFields provides Fields for logging. -func (e err) LogFields() Fields { - return Fields{ - "error": e.e.Error(), - "type": fmt.Sprintf("%T", e.e), - } -} - -// Err is a wrapper around errors that implements Fielder. -func Err(e error) Fielder { - return err{e} -} - -// mergeFielders merges the Fields of multiple Fielders. -// Fields from the first Fielder will be used unchanged, Fields from subsequent -// Fielders will be prefixed with "%d.", starting from 1. -// -// must be called with len(fielders) > 0 -func mergeFielders(fielders ...Fielder) logrus.Fields { - if fielders[0] == nil { - return nil - } - - fields := fielders[0].LogFields() - for i := 1; i < len(fielders); i++ { - if fielders[i] == nil { - continue - } - prefix := fmt.Sprint(i, ".") - ff := fielders[i].LogFields() - for k, v := range ff { - fields[prefix+k] = v - } - } - - return logrus.Fields(fields) -} - -// Debug logs at the debug level if debug logging is enabled. -func Debug(v any, fielders ...Fielder) { - if debug { - if len(fielders) != 0 { - l.WithFields(mergeFielders(fielders...)).Debug(v) } else { - l.Debug(v) + return err } } + if stdAny && formatted { + w = zerolog.ConsoleWriter{ + Out: w, + NoColor: !colored, + TimeFormat: "2006-01-02 15:04:05.999", + } + } + if len(level) > 0 { + if logLevel, err := zerolog.ParseLevel(strings.ToLower(level)); err == nil { + lvl = logLevel + } else { + return err + } + } + root = zerolog.New(w).With().Timestamp().Logger() + zerolog.SetGlobalLevel(lvl) + return nil } -// Info logs at the info level. -func Info(v any, fielders ...Fielder) { - if len(fielders) != 0 { - l.WithFields(mergeFielders(fielders...)).Info(v) - } else { - l.Info(v) - } +func Debug() *zerolog.Event { + return root.Debug() } -// Warn logs at the warning level. -func Warn(v any, fielders ...Fielder) { - if len(fielders) != 0 { - l.WithFields(mergeFielders(fielders...)).Warn(v) - } else { - l.Warn(v) - } +func Info() *zerolog.Event { + return root.Info() } -// Error logs at the error level. -func Error(v any, fielders ...Fielder) { - if len(fielders) != 0 { - l.WithFields(mergeFielders(fielders...)).Error(v) - } else { - l.Error(v) - } +func Warn() *zerolog.Event { + return root.Warn() } -// Fatal logs at the fatal level and exits with a status code != 0. -func Fatal(v any, fielders ...Fielder) { - if len(fielders) != 0 { - l.WithFields(mergeFielders(fielders...)).Fatal(v) - } else { - l.Fatal(v) - } +func Error() *zerolog.Event { + return root.Error() +} + +func Fatal() *zerolog.Event { + return root.Fatal() +} + +func NewLogger(component string) zerolog.Logger { + return root.With().Str("component", component).Logger() } diff --git a/storage/keydb/storage.go b/storage/keydb/storage.go index 07eb4c7..0d05199 100644 --- a/storage/keydb/storage.go +++ b/storage/keydb/storage.go @@ -167,7 +167,7 @@ func (s store) AnnouncePeers(ih bittorrent.InfoHash, seeder bool, numWant int, v // ScrapeSwarm is the same function as redis.ScrapeSwarm except `SCard` call instead of `HLen` func (s store) ScrapeSwarm(ih bittorrent.InfoHash) (leechers uint32, seeders uint32, snatched uint32) { - log.Debug("storage: KeyDB ScrapeSwarm", log.Fields{ + log.Debug("storage: KeyDB: ScrapeSwarm", log.Fields{ "infoHash": ih, }) leechers, seeders = s.CountPeers(ih, s.SCard) diff --git a/storage/storage.go b/storage/storage.go index 37036e9..ef403ca 100644 --- a/storage/storage.go +++ b/storage/storage.go @@ -7,6 +7,8 @@ import ( "sync" "time" + "github.com/rs/zerolog" + "github.com/sot-tech/mochi/bittorrent" "github.com/sot-tech/mochi/pkg/conf" "github.com/sot-tech/mochi/pkg/log" @@ -20,6 +22,7 @@ const ( ) var ( + logger = log.NewLogger("storage configurator") driversM sync.RWMutex drivers = make(map[string]Builder) ) @@ -38,21 +41,21 @@ type Config struct { func (c Config) sanitizeGCConfig() (gcInterval, peerTTL time.Duration) { if c.GarbageCollectionInterval <= 0 { gcInterval = defaultGarbageCollectionInterval - log.Warn("falling back to default configuration", log.Fields{ - "name": "GarbageCollectionInterval", - "provided": c.GarbageCollectionInterval, - "default": defaultGarbageCollectionInterval, - }) + logger.Warn(). + Str("name", "GarbageCollectionInterval"). + Dur("provided", c.GarbageCollectionInterval). + Dur("default", defaultGarbageCollectionInterval). + Msg("falling back to default configuration") } else { gcInterval = c.GarbageCollectionInterval } if c.PeerLifetime <= 0 { peerTTL = defaultPeerLifetime - log.Warn("falling back to default configuration", log.Fields{ - "name": "PeerLifetime", - "provided": c.PeerLifetime, - "default": defaultPeerLifetime, - }) + logger.Warn(). + Str("name", "PeerLifetime"). + Dur("provided", c.PeerLifetime). + Dur("default", defaultPeerLifetime). + Msg("falling back to default configuration") } else { peerTTL = c.PeerLifetime } @@ -62,11 +65,12 @@ func (c Config) sanitizeGCConfig() (gcInterval, peerTTL time.Duration) { func (c Config) sanitizeStatisticsConfig() (statInterval time.Duration) { if c.PrometheusReportingInterval < 0 { statInterval = defaultPrometheusReportingInterval - log.Warn("falling back to default configuration", log.Fields{ - "name": "PrometheusReportingInterval", - "provided": c.PrometheusReportingInterval, - "default": defaultPrometheusReportingInterval, - }) + logger.Warn(). + Str("name", "PrometheusReportingInterval"). + Dur("provided", c.PrometheusReportingInterval). + Dur("default", defaultPrometheusReportingInterval). + Msg("falling back to default configuration") + } return } @@ -207,9 +211,9 @@ type PeerStorage interface { // For more details see the documentation in the stop package. stop.Stopper - // Fielder returns a loggable version of the data used to configure and + // LogObjectMarshaler returns a loggable version of the data used to configure and // operate a particular PeerStorage. - log.Fielder + zerolog.LogObjectMarshaler } // RegisterBuilder makes a Builder available by the provided name. @@ -266,7 +270,7 @@ func NewStorage(name string, cfg conf.MapConfig) (ps PeerStorage, err error) { st.ScheduleStatisticsCollection(statInterval) } } else { - log.Info("prometheus disabled because of zero reporting interval") + logger.Info().Msg("prometheus disabled because of zero reporting interval") } return