*: add structured logging

bittorrent/bittorrent.go

@@ -6,6 +6,8 @@ package bittorrent
 import (
 	"net"
 	"time"
+
+	log "github.com/Sirupsen/logrus"
 )
 
 // PeerID represents a peer ID.
@@ -24,6 +26,10 @@ func PeerIDFromBytes(b []byte) PeerID {
 	return PeerID(buf)
 }
 
+func (p PeerID) String() string {
+	return string(p[:])
+}
+
 // PeerIDFromString creates a PeerID from a string.
 //
 // It panics if s is not 20 bytes long.
@@ -66,6 +72,10 @@ func InfoHashFromString(s string) InfoHash {
 	return InfoHash(buf)
 }
 
+func (i InfoHash) String() string {
+	return string(i[:])
+}
+
 // AnnounceRequest represents the parsed parameters from an announce request.
 type AnnounceRequest struct {
 	Event      Event
@@ -92,6 +102,18 @@ type AnnounceResponse struct {
 	IPv6Peers   []Peer
 }
 
+// LogFields renders the current response as a set of Logrus fields.
+func (ar AnnounceResponse) LogFields() log.Fields {
+	return log.Fields{
+		"compact":     ar.Compact,
+		"complete":    ar.Complete,
+		"interval":    ar.Interval,
+		"minInterval": ar.MinInterval,
+		"ipv4Peers":   ar.IPv4Peers,
+		"ipv6Peers":   ar.IPv6Peers,
+	}
+}
+
 // ScrapeRequest represents the parsed parameters from a scrape request.
 type ScrapeRequest struct {
 	AddressFamily AddressFamily
@@ -107,6 +129,13 @@ type ScrapeResponse struct {
 	Files []Scrape
 }
 
+// LogFields renders the current response as a set of Logrus fields.
+func (sr ScrapeResponse) LogFields() log.Fields {
+	return log.Fields{
+		"files": sr.Files,
+	}
+}
+
 // Scrape represents the state of a swarm that is returned in a scrape response.
 type Scrape struct {
 	InfoHash   InfoHash

cmd/chihaya/main.go

@@ -45,17 +45,15 @@ func (r *Run) Start(ps storage.PeerStore) error {
 	if err != nil {
 		return errors.New("failed to read config: " + err.Error())
 	}
-
 	cfg := configFile.Chihaya
-	preHooks, postHooks, err := cfg.CreateHooks()
-	if err != nil {
-		return errors.New("failed to validate hook config: " + err.Error())
-	}
 
 	r.sg = stop.NewGroup()
+
+	log.WithFields(log.Fields{"addr": cfg.PrometheusAddr}).Info("starting Prometheus server")
 	r.sg.Add(prometheus.NewServer(cfg.PrometheusAddr))
 
 	if ps == nil {
+		log.WithFields(cfg.Storage.LogFields()).Info("starting storage")
 		ps, err = memory.New(cfg.Storage)
 		if err != nil {
 			return errors.New("failed to create memory storage: " + err.Error())
@@ -63,9 +61,18 @@ func (r *Run) Start(ps storage.PeerStore) error {
 	}
 	r.peerStore = ps
 
+	preHooks, postHooks, err := cfg.CreateHooks()
+	if err != nil {
+		return errors.New("failed to validate hook config: " + err.Error())
+	}
+	log.WithFields(log.Fields{
+		"preHooks":  preHooks,
+		"postHooks": postHooks,
+	}).Info("starting middleware")
 	r.logic = middleware.NewLogic(cfg.Config, r.peerStore, preHooks, postHooks)
 
 	if cfg.HTTPConfig.Addr != "" {
+		log.WithFields(cfg.HTTPConfig.LogFields()).Info("starting HTTP frontend")
 		httpfe, err := http.NewFrontend(r.logic, cfg.HTTPConfig)
 		if err != nil {
 			return err
@@ -74,6 +81,7 @@ func (r *Run) Start(ps storage.PeerStore) error {
 	}
 
 	if cfg.UDPConfig.Addr != "" {
+		log.WithFields(cfg.UDPConfig.LogFields()).Info("starting UDP frontend")
 		udpfe, err := udp.NewFrontend(r.logic, cfg.UDPConfig)
 		if err != nil {
 			return err
@@ -121,7 +129,7 @@ func (r *Run) Stop(keepPeerStore bool) (storage.PeerStore, error) {
 func RunCmdFunc(cmd *cobra.Command, args []string) error {
 	cpuProfilePath, _ := cmd.Flags().GetString("cpuprofile")
 	if cpuProfilePath != "" {
-		log.Infoln("enabled CPU profiling to", cpuProfilePath)
+		log.WithFields(log.Fields{"path": cpuProfilePath}).Info("enabling CPU profiling")
 		f, err := os.Create(cpuProfilePath)
 		if err != nil {
 			return err
@@ -149,7 +157,7 @@ func RunCmdFunc(cmd *cobra.Command, args []string) error {
 	for {
 		select {
 		case <-reload:
-			log.Info("received SIGUSR1")
+			log.Info("reloading; received SIGUSR1")
 			peerStore, err := r.Stop(true)
 			if err != nil {
 				return err
@@ -159,7 +167,7 @@ func RunCmdFunc(cmd *cobra.Command, args []string) error {
 				return err
 			}
 		case <-quit:
-			log.Info("received SIGINT/SIGTERM")
+			log.Info("shutting down; received SIGINT/SIGTERM")
 			if _, err := r.Stop(false); err != nil {
 				return err
 			}
@@ -177,8 +185,8 @@ func main() {
 		PersistentPreRun: func(cmd *cobra.Command, args []string) {
 			debugLog, _ := cmd.Flags().GetBool("debug")
 			if debugLog {
+				log.Info("enabling debug logging")
 				log.SetLevel(log.DebugLevel)
-				log.Debugln("debug logging enabled")
 			}
 		},
 		RunE: RunCmdFunc,

frontend/http/frontend.go

@@ -71,6 +71,19 @@ type Config struct {
 	TLSKeyPath      string        `yaml:"tls_key_path"`
 }
 
+// LogFields renders the current config as a set of Logrus fields.
+func (cfg Config) LogFields() log.Fields {
+	return log.Fields{
+		"addr":            cfg.Addr,
+		"readTimeout":     cfg.ReadTimeout,
+		"writeTimeout":    cfg.WriteTimeout,
+		"allowIPSpoofing": cfg.AllowIPSpoofing,
+		"realIPHeader":    cfg.RealIPHeader,
+		"tlsCertPath":     cfg.TLSCertPath,
+		"tlsKeyPath":      cfg.TLSKeyPath,
+	}
+}
+
 // Frontend represents the state of an HTTP BitTorrent Frontend.
 type Frontend struct {
 	srv    *http.Server

frontend/udp/frontend.go

@@ -73,6 +73,16 @@ type Config struct {
 	AllowIPSpoofing bool          `yaml:"allow_ip_spoofing"`
 }
 
+// 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,
+		"allowIPSpoofing": cfg.AllowIPSpoofing,
+	}
+}
+
 // Frontend holds the state of a UDP BitTorrent Frontend.
 type Frontend struct {
 	socket  *net.UDPConn
@@ -144,7 +154,6 @@ func (t *Frontend) listenAndServe() error {
 		return err
 	}
 
-	log.Debugf("listening on udp socket")
 	t.socket, err = net.ListenUDP("udp", udpAddr)
 	if err != nil {
 		return err
@@ -159,7 +168,7 @@ func (t *Frontend) listenAndServe() error {
 		// Check to see if we need to shutdown.
 		select {
 		case <-t.closing:
-			log.Debugf("returning from udp listen&serve")
+			log.Debug("udp listenAndServe() received shutdown signal")
 			return nil
 		default:
 		}

middleware/middleware.go

@@ -61,6 +61,7 @@ func (l *Logic) HandleAnnounce(ctx context.Context, req *bittorrent.AnnounceRequ
 		}
 	}
 
+	log.WithFields(resp.LogFields()).Debug("generated announce response")
 	return resp, nil
 }
 
@@ -87,6 +88,7 @@ func (l *Logic) HandleScrape(ctx context.Context, req *bittorrent.ScrapeRequest)
 		}
 	}
 
+	log.WithFields(resp.LogFields()).Debug("generated scrape response")
 	return resp, nil
 }
 

storage/memory/peer_store.go

@@ -52,6 +52,15 @@ type Config struct {
 	ShardCount                int           `yaml:"shard_count"`
 }
 
+// LogFields renders the current config as a set of Logrus fields.
+func (cfg Config) LogFields() log.Fields {
+	return log.Fields{
+		"gcInterval":   cfg.GarbageCollectionInterval,
+		"peerLifetime": cfg.PeerLifetime,
+		"shardCount":   cfg.ShardCount,
+	}
+}
+
 // New creates a new PeerStore backed by memory.
 func New(cfg Config) (storage.PeerStore, error) {
 	shardCount := 1