From 8d62d4c2f39ccb590d392b891244b3a8c5fb1526 Mon Sep 17 00:00:00 2001 From: Aurora Gaffney Date: Thu, 1 Aug 2024 10:41:43 -0500 Subject: [PATCH] chore: switch to slog for logging Fixes #177 --- cmd/cdnsd/main.go | 66 +++++++++++------- go.mod | 2 +- internal/config/config.go | 9 +-- internal/dns/dns.go | 100 +++++++++++++++++---------- internal/indexer/indexer.go | 131 ++++++++++++++++++++++++++---------- internal/logging/logging.go | 64 ------------------ internal/state/state.go | 46 ++++++++----- 7 files changed, 239 insertions(+), 179 deletions(-) delete mode 100644 internal/logging/logging.go diff --git a/cmd/cdnsd/main.go b/cmd/cdnsd/main.go index cc0906e..4d90888 100644 --- a/cmd/cdnsd/main.go +++ b/cmd/cdnsd/main.go @@ -9,6 +9,7 @@ package main import ( "flag" "fmt" + "log/slog" "net/http" _ "net/http/pprof" "os" @@ -18,7 +19,6 @@ import ( "github.com/blinklabs-io/cdnsd/internal/config" "github.com/blinklabs-io/cdnsd/internal/dns" "github.com/blinklabs-io/cdnsd/internal/indexer" - "github.com/blinklabs-io/cdnsd/internal/logging" "github.com/blinklabs-io/cdnsd/internal/state" "github.com/blinklabs-io/cdnsd/internal/version" ) @@ -43,33 +43,38 @@ func main() { os.Exit(1) } - // Configure logging - logging.Setup() - logger := logging.GetLogger() - // Sync logger on exit - defer func() { - if err := logger.Sync(); err != nil { - // We don't actually care about the error here, but we have to do something - // to appease the linter - return - } - }() + // Configure logger + logLevel := slog.LevelInfo + if cfg.Logging.Debug { + logLevel = slog.LevelDebug + } + logger := slog.New( + slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ + Level: logLevel, + }), + ) + slog.SetDefault(logger) - logger.Info( + slog.Info( fmt.Sprintf("cdnsd %s started", version.GetVersionString()), ) // Load state if err := state.GetState().Load(); err != nil { - logger.Fatalf("failed to load state: %s", err) + slog.Error( + fmt.Sprintf("failed to load state: %s", err), + ) + os.Exit(1) } // Start debug listener if cfg.Debug.ListenPort > 0 { - logger.Infof( - "starting debug listener on %s:%d", - cfg.Debug.ListenAddress, - cfg.Debug.ListenPort, + slog.Info( + fmt.Sprintf( + "starting debug listener on %s:%d", + cfg.Debug.ListenAddress, + cfg.Debug.ListenPort, + ), ) go func() { err := http.ListenAndServe( @@ -81,24 +86,35 @@ func main() { nil, ) if err != nil { - logger.Fatalf("failed to start debug listener: %s", err) + slog.Error( + fmt.Sprintf("failed to start debug listener: %s", err), + ) + os.Exit(1) } }() } // Start indexer if err := indexer.GetIndexer().Start(); err != nil { - logger.Fatalf("failed to start indexer: %s", err) + slog.Error( + fmt.Sprintf("failed to start indexer: %s", err), + ) + os.Exit(1) } // Start DNS listener - logger.Infof( - "starting DNS listener on %s:%d", - cfg.Dns.ListenAddress, - cfg.Dns.ListenPort, + slog.Info( + fmt.Sprintf( + "starting DNS listener on %s:%d", + cfg.Dns.ListenAddress, + cfg.Dns.ListenPort, + ), ) if err := dns.Start(); err != nil { - logger.Fatalf("failed to start DNS listener: %s", err) + slog.Error( + fmt.Sprintf("failed to start DNS listener: %s", err), + ) + os.Exit(1) } // Wait forever diff --git a/go.mod b/go.mod index 73085d0..1e98212 100644 --- a/go.mod +++ b/go.mod @@ -10,7 +10,6 @@ require ( github.com/kelseyhightower/envconfig v1.4.0 github.com/miekg/dns v1.1.61 go.uber.org/automaxprocs v1.5.3 - go.uber.org/zap v1.27.0 gopkg.in/yaml.v2 v2.4.0 ) @@ -40,6 +39,7 @@ require ( github.com/x448/float16 v0.8.4 // indirect go.opencensus.io v0.22.5 // indirect go.uber.org/multierr v1.10.0 // indirect + go.uber.org/zap v1.27.0 // indirect golang.org/x/crypto v0.25.0 // indirect golang.org/x/mod v0.18.0 // indirect golang.org/x/net v0.26.0 // indirect diff --git a/internal/config/config.go b/internal/config/config.go index c23b00f..8eef089 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -26,9 +26,8 @@ type Config struct { } type LoggingConfig struct { - Healthchecks bool `yaml:"healthchecks" envconfig:"LOGGING_HEALTHCHECKS"` - Level string `yaml:"level" envconfig:"LOGGING_LEVEL"` - QueryLog bool `yaml:"queryLog" envconfig:"LOGGING_QUERY_LOG"` + Debug bool `yaml:"debug" envconfig:"LOGGING_DEBUG"` + QueryLog bool `yaml:"queryLog" envconfig:"LOGGING_QUERY_LOG"` } type DnsConfig struct { @@ -65,9 +64,7 @@ type StateConfig struct { // Singleton config instance with default values var globalConfig = &Config{ Logging: LoggingConfig{ - Level: "info", - Healthchecks: false, - QueryLog: true, + QueryLog: true, }, Dns: DnsConfig{ ListenAddress: "", diff --git a/internal/dns/dns.go b/internal/dns/dns.go index 283efbe..e223d48 100644 --- a/internal/dns/dns.go +++ b/internal/dns/dns.go @@ -8,12 +8,13 @@ package dns import ( "fmt" + "log/slog" "math/rand" "net" + "os" "strings" "github.com/blinklabs-io/cdnsd/internal/config" - "github.com/blinklabs-io/cdnsd/internal/logging" "github.com/blinklabs-io/cdnsd/internal/state" "github.com/miekg/dns" @@ -49,21 +50,25 @@ func Start() error { func startListener(server *dns.Server) { if err := server.ListenAndServe(); err != nil { - logging.GetLogger().Fatalf("failed to start DNS listener: %s", err) + slog.Error( + fmt.Sprintf("failed to start DNS listener: %s", err), + ) + os.Exit(1) } } func handleQuery(w dns.ResponseWriter, r *dns.Msg) { - logger := logging.GetLogger() cfg := config.GetConfig() m := new(dns.Msg) if cfg.Logging.QueryLog { for _, q := range r.Question { - logger.Infof("query: name: %s, type: %s, class: %s", - q.Name, - dns.Type(q.Qtype).String(), - dns.Class(q.Qclass).String(), + slog.Info( + fmt.Sprintf("query: name: %s, type: %s, class: %s", + q.Name, + dns.Type(q.Qtype).String(), + dns.Class(q.Qclass).String(), + ), ) } } @@ -74,7 +79,9 @@ func handleQuery(w dns.ResponseWriter, r *dns.Msg) { strings.TrimSuffix(r.Question[0].Name, "."), ) if err != nil { - logger.Errorf("failed to lookup records in state: %s", err) + slog.Error( + fmt.Sprintf("failed to lookup records in state: %s", err), + ) return } if records != nil { @@ -83,14 +90,18 @@ func handleQuery(w dns.ResponseWriter, r *dns.Msg) { for _, tmpRecord := range records { tmpRR, err := stateRecordToDnsRR(tmpRecord) if err != nil { - logger.Errorf("failed to convert state record to dns.RR: %s", err) + slog.Error( + fmt.Sprintf("failed to convert state record to dns.RR: %s", err), + ) return } m.Answer = append(m.Answer, tmpRR) } // Send response if err := w.WriteMsg(m); err != nil { - logger.Errorf("failed to write response: %s", err) + slog.Error( + fmt.Sprintf("failed to write response: %s", err), + ) } // We found our answer, to return from handler return @@ -101,10 +112,12 @@ func handleQuery(w dns.ResponseWriter, r *dns.Msg) { r.Question[0].Name, ) if err != nil { - logger.Errorf( - "failed to lookup nameservers for %s: %s", - r.Question[0].Name, - err, + slog.Error( + fmt.Sprintf( + "failed to lookup nameservers for %s: %s", + r.Question[0].Name, + err, + ), ) } if nameservers != nil { @@ -119,15 +132,21 @@ func handleQuery(w dns.ResponseWriter, r *dns.Msg) { // Send failure response m.SetRcode(r, dns.RcodeServerFailure) if err := w.WriteMsg(m); err != nil { - logger.Errorf("failed to write response: %s", err) + slog.Error( + fmt.Sprintf("failed to write response: %s", err), + ) } - logger.Errorf("failed to query domain nameserver: %s", err) + slog.Error( + fmt.Sprintf("failed to query domain nameserver: %s", err), + ) return } else { copyResponse(r, resp, m) // Send response if err := w.WriteMsg(m); err != nil { - logger.Errorf("failed to write response: %s", err) + slog.Error( + fmt.Sprintf("failed to write response: %s", err), + ) } return } @@ -161,7 +180,9 @@ func handleQuery(w dns.ResponseWriter, r *dns.Msg) { } // Send response if err := w.WriteMsg(m); err != nil { - logger.Errorf("failed to write response: %s", err) + slog.Error( + fmt.Sprintf("failed to write response: %s", err), + ) } // We found our answer, to return from handler return @@ -177,15 +198,21 @@ func handleQuery(w dns.ResponseWriter, r *dns.Msg) { // Send failure response m.SetRcode(r, dns.RcodeServerFailure) if err := w.WriteMsg(m); err != nil { - logger.Errorf("failed to write response: %s", err) + slog.Error( + fmt.Sprintf("failed to write response: %s", err), + ) } - logger.Errorf("failed to query domain nameserver: %s", err) + slog.Error( + fmt.Sprintf("failed to query domain nameserver: %s", err), + ) return } else { copyResponse(r, resp, m) // Send response if err := w.WriteMsg(m); err != nil { - logger.Errorf("failed to write response: %s", err) + slog.Error( + fmt.Sprintf("failed to write response: %s", err), + ) } return } @@ -194,7 +221,9 @@ func handleQuery(w dns.ResponseWriter, r *dns.Msg) { // Return NXDOMAIN if we have no information about the requested domain or any of its parents m.SetRcode(r, dns.RcodeNameError) if err := w.WriteMsg(m); err != nil { - logger.Errorf("failed to write response: %s", err) + slog.Error( + fmt.Sprintf("failed to write response: %s", err), + ) } } @@ -243,7 +272,6 @@ func randomNameserverAddress(nameservers map[string][]net.IP) net.IP { } func doQuery(msg *dns.Msg, address string, recursive bool) (*dns.Msg, error) { - logger := logging.GetLogger() // Default to a random fallback server if no address is specified if address == "" { address = randomFallbackServer() @@ -252,22 +280,26 @@ func doQuery(msg *dns.Msg, address string, recursive bool) (*dns.Msg, error) { if !strings.Contains(address, ":") { address = address + `:53` } - logger.Debugf( - "querying %s: %s", - address, - formatMessageQuestionSection(msg.Question), + slog.Debug( + fmt.Sprintf( + "querying %s: %s", + address, + formatMessageQuestionSection(msg.Question), + ), ) resp, err := dns.Exchange(msg, address) if err != nil { return nil, err } - logger.Debugf( - "response: rcode=%s, authoritative=%v, authority=%s, answer=%s, extra=%s", - dns.RcodeToString[resp.Rcode], - resp.Authoritative, - formatMessageAnswerSection(resp.Ns), - formatMessageAnswerSection(resp.Answer), - formatMessageAnswerSection(resp.Extra), + slog.Debug( + fmt.Sprintf( + "response: rcode=%s, authoritative=%v, authority=%s, answer=%s, extra=%s", + dns.RcodeToString[resp.Rcode], + resp.Authoritative, + formatMessageAnswerSection(resp.Ns), + formatMessageAnswerSection(resp.Answer), + formatMessageAnswerSection(resp.Extra), + ), ) // Immediately return authoritative response if resp.Authoritative { diff --git a/internal/indexer/indexer.go b/internal/indexer/indexer.go index eb1f6e2..921ae05 100644 --- a/internal/indexer/indexer.go +++ b/internal/indexer/indexer.go @@ -9,11 +9,12 @@ package indexer import ( "encoding/hex" "fmt" + "log/slog" + "os" "strings" "time" "github.com/blinklabs-io/cdnsd/internal/config" - "github.com/blinklabs-io/cdnsd/internal/logging" "github.com/blinklabs-io/cdnsd/internal/state" "github.com/blinklabs-io/adder/event" @@ -52,7 +53,6 @@ var globalIndexer = &Indexer{ func (i *Indexer) Start() error { cfg := config.GetConfig() - logger := logging.GetLogger() // Create pipeline i.pipeline = pipeline.New() // Configure pipeline input @@ -61,20 +61,22 @@ func (i *Indexer) Start() error { func(status input_chainsync.ChainSyncStatus) { i.syncStatus = status if err := state.GetState().UpdateCursor(status.SlotNumber, status.BlockHash); err != nil { - logger.Errorf("failed to update cursor: %s", err) + slog.Error( + fmt.Sprintf("failed to update cursor: %s", err), + ) } if !i.tipReached && status.TipReached { if i.syncLogTimer != nil { i.syncLogTimer.Stop() } i.tipReached = true - logger.Infof("caught up to chain tip") + slog.Info("caught up to chain tip") } }, ), input_chainsync.WithBulkMode(true), input_chainsync.WithAutoReconnect(true), - input_chainsync.WithLogger(logger), + input_chainsync.WithLogger(NewAdderLogger()), } if cfg.Indexer.NetworkMagic > 0 { inputOpts = append( @@ -92,10 +94,12 @@ func (i *Indexer) Start() error { return err } if cursorSlotNumber > 0 { - logger.Infof( - "found previous chainsync cursor: %d, %s", - cursorSlotNumber, - cursorBlockHash, + slog.Info( + fmt.Sprintf( + "found previous chainsync cursor: %d, %s", + cursorSlotNumber, + cursorBlockHash, + ), ) hashBytes, err := hex.DecodeString(cursorBlockHash) if err != nil { @@ -113,7 +117,9 @@ func (i *Indexer) Start() error { ), ) } else if cfg.Indexer.InterceptHash != "" && cfg.Indexer.InterceptSlot > 0 { - logger.Infof("starting new chainsync at configured location: %d, %s", cfg.Indexer.InterceptSlot, cfg.Indexer.InterceptHash) + slog.Info( + fmt.Sprintf("starting new chainsync at configured location: %d, %s", cfg.Indexer.InterceptSlot, cfg.Indexer.InterceptHash), + ) hashBytes, err := hex.DecodeString(cfg.Indexer.InterceptHash) if err != nil { return err @@ -156,13 +162,19 @@ func (i *Indexer) Start() error { i.pipeline.AddOutput(output) // Start pipeline if err := i.pipeline.Start(); err != nil { - logger.Fatalf("failed to start pipeline: %s\n", err) + slog.Error( + fmt.Sprintf("failed to start pipeline: %s\n", err), + ) + os.Exit(1) } // Start error handler go func() { err, ok := <-i.pipeline.ErrorChan() if ok { - logger.Fatalf("pipeline failed: %s\n", err) + slog.Error( + fmt.Sprintf("pipeline failed: %s\n", err), + ) + os.Exit(1) } }() // Schedule periodic catch-up sync log messages @@ -172,7 +184,6 @@ func (i *Indexer) Start() error { func (i *Indexer) handleEvent(evt event.Event) error { cfg := config.GetConfig() - logger := logging.GetLogger() eventTx := evt.Payload.(input_chainsync.TransactionEvent) eventCtx := evt.Context.(input_chainsync.TransactionContext) for _, txOutput := range eventTx.Outputs { @@ -184,10 +195,12 @@ func (i *Indexer) handleEvent(evt event.Event) error { if datum != nil { var dnsDomain models.CardanoDnsDomain if _, err := cbor.Decode(datum.Cbor(), &dnsDomain); err != nil { - logger.Warnf( - "error decoding TX (%s) output datum: %s", - eventCtx.TransactionHash, - err, + slog.Warn( + fmt.Sprintf( + "error decoding TX (%s) output datum: %s", + eventCtx.TransactionHash, + err, + ), ) // Stop processing TX output if we can't parse the datum continue @@ -207,9 +220,11 @@ func (i *Indexer) handleEvent(evt event.Event) error { if cfg.Indexer.Verify { // Look for asset matching domain origin and TLD policy ID if txOutput.Assets() == nil { - logger.Warnf( - "ignoring datum for domain %q with no matching asset", - domainName, + slog.Warn( + fmt.Sprintf( + "ignoring datum for domain %q with no matching asset", + domainName, + ), ) continue } @@ -220,15 +235,19 @@ func (i *Indexer) handleEvent(evt event.Event) error { if string(assetName) == string(origin) { foundAsset = true } else { - logger.Warnf( - "ignoring datum for domain %q with no matching asset", - domainName, + slog.Warn( + fmt.Sprintf( + "ignoring datum for domain %q with no matching asset", + domainName, + ), ) } } else { - logger.Warnf( - "ignoring datum for domain %q with no matching asset", - domainName, + slog.Warn( + fmt.Sprintf( + "ignoring datum for domain %q with no matching asset", + domainName, + ), ) } } @@ -243,10 +262,12 @@ func (i *Indexer) handleEvent(evt event.Event) error { string(record.Lhs), ) if !strings.HasSuffix(recordName, domainName) { - logger.Warnf( - "ignoring datum with record %q outside of origin domain (%s)", - recordName, - domainName, + slog.Warn( + fmt.Sprintf( + "ignoring datum with record %q outside of origin domain (%s)", + recordName, + domainName, + ), ) badRecordName = true break @@ -272,9 +293,11 @@ func (i *Indexer) handleEvent(evt event.Event) error { if err := state.GetState().UpdateDomain(domainName, tmpRecords); err != nil { return err } - logger.Infof( - "found updated registration for domain: %s", - domainName, + slog.Info( + fmt.Sprintf( + "found updated registration for domain: %s", + domainName, + ), ) } } @@ -287,7 +310,7 @@ func (i *Indexer) scheduleSyncStatusLog() { } func (i *Indexer) syncStatusLog() { - logging.GetLogger().Info( + slog.Info( fmt.Sprintf( "catch-up sync in progress: at %d.%s (current tip slot is %d)", i.syncStatus.SlotNumber, @@ -309,3 +332,43 @@ func (i *Indexer) LookupDomain(name string) *Domain { func GetIndexer() *Indexer { return globalIndexer } + +// TODO: remove the below once we switch adder to slog + +// AdderLogger is a wrapper type to give our logger the expected interface +type AdderLogger struct{} + +func NewAdderLogger() *AdderLogger { + return &AdderLogger{} +} + +func (a *AdderLogger) Infof(msg string, args ...any) { + slog.Info( + fmt.Sprintf(msg, args...), + ) +} + +func (a *AdderLogger) Warnf(msg string, args ...any) { + slog.Warn( + fmt.Sprintf(msg, args...), + ) +} + +func (a *AdderLogger) Debugf(msg string, args ...any) { + slog.Debug( + fmt.Sprintf(msg, args...), + ) +} + +func (a *AdderLogger) Errorf(msg string, args ...any) { + slog.Error( + fmt.Sprintf(msg, args...), + ) +} + +func (a *AdderLogger) Fatalf(msg string, args ...any) { + slog.Error( + fmt.Sprintf(msg, args...), + ) + os.Exit(1) +} diff --git a/internal/logging/logging.go b/internal/logging/logging.go deleted file mode 100644 index f6bf468..0000000 --- a/internal/logging/logging.go +++ /dev/null @@ -1,64 +0,0 @@ -// Copyright 2023 Blink Labs Software -// -// Use of this source code is governed by an MIT-style -// license that can be found in the LICENSE file or at -// https://opensource.org/licenses/MIT. - -package logging - -import ( - "log" - "time" - - "github.com/blinklabs-io/cdnsd/internal/config" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" -) - -type Logger = zap.SugaredLogger - -var globalLogger *Logger - -func Setup() { - cfg := config.GetConfig() - // Build our custom logging config - loggerConfig := zap.NewProductionConfig() - // Change timestamp key name - loggerConfig.EncoderConfig.TimeKey = "timestamp" - // Use a human readable time format - loggerConfig.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout( - time.RFC3339, - ) - - // Set level - if cfg.Logging.Level != "" { - level, err := zapcore.ParseLevel(cfg.Logging.Level) - if err != nil { - log.Fatalf("error configuring logger: %s", err) - } - loggerConfig.Level.SetLevel(level) - } - - // Create the logger - l, err := loggerConfig.Build() - if err != nil { - log.Fatal(err) - } - - // Store the "sugared" version of the logger - globalLogger = l.Sugar() -} - -func GetLogger() *Logger { - return globalLogger -} - -func GetDesugaredLogger() *zap.Logger { - return globalLogger.Desugar() -} - -func GetAccessLogger() *zap.Logger { - return globalLogger.Desugar(). - With(zap.String("type", "access")). - WithOptions(zap.WithCaller(false)) -} diff --git a/internal/state/state.go b/internal/state/state.go index 652cf6b..79eb560 100644 --- a/internal/state/state.go +++ b/internal/state/state.go @@ -11,13 +11,13 @@ import ( "encoding/gob" "errors" "fmt" + "log/slog" "slices" "strconv" "strings" "time" "github.com/blinklabs-io/cdnsd/internal/config" - "github.com/blinklabs-io/cdnsd/internal/logging" "github.com/dgraph-io/badger/v4" ) @@ -58,17 +58,18 @@ func (s *State) Load() error { // Run GC periodically for Badger DB s.gcTimer = time.NewTicker(5 * time.Minute) go func() { - logger := logging.GetLogger() for range s.gcTimer.C { again: - logger.Debug("database: running GC") + slog.Debug("database: running GC") err := s.db.RunValueLogGC(0.5) if err != nil { // Log any actual errors if !errors.Is(err, badger.ErrNoRewrite) { - logger.Warnf( - "database: GC failure: %s", - err, + slog.Warn( + fmt.Sprintf( + "database: GC failure: %s", + err, + ), ) } } else { @@ -163,7 +164,6 @@ func (s *State) UpdateDomain( domainName string, records []DomainRecord, ) error { - logger := logging.GetLogger() err := s.db.Update(func(txn *badger.Txn) error { // Add new records recordKeys := make([]string, 0) @@ -184,7 +184,7 @@ func (s *State) UpdateDomain( if err := txn.Set([]byte(key), recordVal); err != nil { return err } - logger.Debug( + slog.Debug( fmt.Sprintf( "added record for domain %s: %s: %s: %s", domainName, @@ -267,16 +267,32 @@ func GetState() *State { } // BadgerLogger is a wrapper type to give our logger the expected interface -type BadgerLogger struct { - *logging.Logger -} +type BadgerLogger struct{} func NewBadgerLogger() *BadgerLogger { - return &BadgerLogger{ - Logger: logging.GetLogger(), - } + return &BadgerLogger{} +} + +func (b *BadgerLogger) Infof(msg string, args ...any) { + slog.Info( + fmt.Sprintf(msg, args...), + ) } func (b *BadgerLogger) Warningf(msg string, args ...any) { - b.Logger.Warnf(msg, args...) + slog.Warn( + fmt.Sprintf(msg, args...), + ) +} + +func (b *BadgerLogger) Debugf(msg string, args ...any) { + slog.Debug( + fmt.Sprintf(msg, args...), + ) +} + +func (b *BadgerLogger) Errorf(msg string, args ...any) { + slog.Error( + fmt.Sprintf(msg, args...), + ) }