Merge pull request #209 from jzelinskie/logrus

misc fixes for #207

bittorrent/bittorrent.go

@@ -130,9 +130,3 @@ type ClientError string
 
 // Error implements the error interface for ClientError.
 func (c ClientError) Error() string { return string(c) }
-
-// Tracker represents an implementation of the BitTorrent tracker protocol.
-type Tracker interface {
-	ListenAndServe() error
-	Stop()
-}

cmd/chihaya/main.go

@@ -2,13 +2,13 @@ package main
 
 import (
 	"errors"
-	"log"
 	"net/http"
 	"os"
 	"os/signal"
 	"runtime/pprof"
 	"syscall"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/spf13/cobra"
 
@@ -19,9 +19,14 @@ import (
 )
 
 func rootCmdRun(cmd *cobra.Command, args []string) error {
+	debugLog, _ := cmd.Flags().GetBool("debug")
+	if debugLog {
+		log.SetLevel(log.DebugLevel)
+		log.Debugln("debug logging enabled")
+	}
 	cpuProfilePath, _ := cmd.Flags().GetString("cpuprofile")
 	if cpuProfilePath != "" {
-		log.Println("enabled CPU profiling to " + cpuProfilePath)
+		log.Infoln("enabled CPU profiling to", cpuProfilePath)
 		f, err := os.Create(cpuProfilePath)
 		if err != nil {
 			return err
@@ -42,26 +47,26 @@ func rootCmdRun(cmd *cobra.Command, args []string) error {
 			Addr:    cfg.PrometheusAddr,
 			Handler: prometheus.Handler(),
 		}
-		log.Println("started serving prometheus stats on", cfg.PrometheusAddr)
+		log.Infoln("started serving prometheus stats on", cfg.PrometheusAddr)
 		if err := promServer.ListenAndServe(); err != nil {
-			log.Fatal(err)
+			log.Fatalln("failed to start prometheus server:", err.Error())
 		}
 	}()
 
 	// Force the compiler to enforce memory against the storage interface.
 	peerStore, err := memory.New(cfg.Storage)
 	if err != nil {
-		return err
+		return errors.New("failed to create memory storage: " + err.Error())
 	}
 
 	preHooks, postHooks, err := configFile.CreateHooks()
 	if err != nil {
-		return err
+		return errors.New("failed to create hooks: " + err.Error())
 	}
 
 	logic := middleware.NewLogic(cfg.Config, peerStore, preHooks, postHooks)
 	if err != nil {
-		return err
+		return errors.New("failed to create TrackerLogic: " + err.Error())
 	}
 
 	shutdown := make(chan struct{})
@@ -74,7 +79,7 @@ func rootCmdRun(cmd *cobra.Command, args []string) error {
 		httpFrontend = httpfrontend.NewFrontend(logic, cfg.HTTPConfig)
 
 		go func() {
-			log.Println("started serving HTTP on", cfg.HTTPConfig.Addr)
+			log.Infoln("started serving HTTP on", cfg.HTTPConfig.Addr)
 			if err := httpFrontend.ListenAndServe(); err != nil {
 				errChan <- errors.New("failed to cleanly shutdown HTTP frontend: " + err.Error())
 			}
@@ -85,7 +90,7 @@ func rootCmdRun(cmd *cobra.Command, args []string) error {
 		udpFrontend = udpfrontend.NewFrontend(logic, cfg.UDPConfig)
 
 		go func() {
-			log.Println("started serving UDP on", cfg.UDPConfig.Addr)
+			log.Infoln("started serving UDP on", cfg.UDPConfig.Addr)
 			if err := udpFrontend.ListenAndServe(); err != nil {
 				errChan <- errors.New("failed to cleanly shutdown UDP frontend: " + err.Error())
 			}
@@ -114,6 +119,8 @@ func rootCmdRun(cmd *cobra.Command, args []string) error {
 			}
 		}
 
+		// TODO(jzelinskie): stop hooks here
+
 		close(errChan)
 	}()
 
@@ -125,7 +132,7 @@ func rootCmdRun(cmd *cobra.Command, args []string) error {
 				close(shutdown)
 				closed = true
 			} else {
-				log.Println(bufErr)
+				log.Infoln(bufErr)
 			}
 			bufErr = err
 		}
@@ -147,6 +154,7 @@ func main() {
 	}
 	rootCmd.Flags().String("config", "/etc/chihaya.yaml", "location of configuration file")
 	rootCmd.Flags().String("cpuprofile", "", "location to save a CPU profile")
+	rootCmd.Flags().Bool("debug", false, "enable debug logging")
 
 	if err := rootCmd.Execute(); err != nil {
 		log.Fatal(err)

frontend/http/frontend.go

@@ -136,7 +136,7 @@ func (t *Frontend) announceRoute(w http.ResponseWriter, r *http.Request, _ httpr
 		return
 	}
 
-	resp, err := t.logic.HandleAnnounce(context.TODO(), req)
+	resp, err := t.logic.HandleAnnounce(context.Background(), req)
 	if err != nil {
 		WriteError(w, err)
 		return
@@ -148,7 +148,7 @@ func (t *Frontend) announceRoute(w http.ResponseWriter, r *http.Request, _ httpr
 		return
 	}
 
-	go t.logic.AfterAnnounce(context.TODO(), req, resp)
+	go t.logic.AfterAnnounce(context.Background(), req, resp)
 }
 
 // scrapeRoute parses and responds to a Scrape by using t.TrackerLogic.
@@ -163,7 +163,7 @@ func (t *Frontend) scrapeRoute(w http.ResponseWriter, r *http.Request, _ httprou
 		return
 	}
 
-	resp, err := t.logic.HandleScrape(context.TODO(), req)
+	resp, err := t.logic.HandleScrape(context.Background(), req)
 	if err != nil {
 		WriteError(w, err)
 		return
@@ -175,5 +175,5 @@ func (t *Frontend) scrapeRoute(w http.ResponseWriter, r *http.Request, _ httprou
 		return
 	}
 
-	go t.logic.AfterScrape(context.TODO(), req, resp)
+	go t.logic.AfterScrape(context.Background(), req, resp)
 }

frontend/udp/bytepool/bytepool.go

@@ -7,11 +7,11 @@ type BytePool struct {
 	sync.Pool
 }
 
-// New allocates a new BytePool with slices of the provided capacity.
+// New allocates a new BytePool with slices of equal length and capacity.
-func New(length, capacity int) *BytePool {
+func New(length int) *BytePool {
 	var bp BytePool
 	bp.Pool.New = func() interface{} {
-		return make([]byte, length, capacity)
+		return make([]byte, length, length)
 	}
 	return &bp
 }

frontend/udp/frontend.go

@@ -93,7 +93,7 @@ func (t *Frontend) ListenAndServe() error {
 	}
 	defer t.socket.Close()
 
-	pool := bytepool.New(2048, 2048)
+	pool := bytepool.New(2048)
 
 	for {
 		// Check to see if we need to shutdown.
@@ -190,7 +190,6 @@ func (t *Frontend) handleRequest(r Request, w ResponseWriter) (actionName string
 		}
 
 		WriteConnectionID(w, txID, NewConnectionID(r.IP, time.Now(), t.PrivateKey))
-		return
 
 	case announceActionID, announceV6ActionID:
 		actionName = "announce"
@@ -203,7 +202,7 @@ func (t *Frontend) handleRequest(r Request, w ResponseWriter) (actionName string
 		}
 
 		var resp *bittorrent.AnnounceResponse
-		resp, err = t.logic.HandleAnnounce(context.TODO(), req)
+		resp, err = t.logic.HandleAnnounce(context.Background(), req)
 		if err != nil {
 			WriteError(w, txID, err)
 			return
@@ -211,9 +210,7 @@ func (t *Frontend) handleRequest(r Request, w ResponseWriter) (actionName string
 
 		WriteAnnounce(w, txID, resp, actionID == announceV6ActionID)
 
-		go t.logic.AfterAnnounce(context.TODO(), req, resp)
+		go t.logic.AfterAnnounce(context.Background(), req, resp)
-
-		return
 
 	case scrapeActionID:
 		actionName = "scrape"
@@ -226,7 +223,7 @@ func (t *Frontend) handleRequest(r Request, w ResponseWriter) (actionName string
 		}
 
 		var resp *bittorrent.ScrapeResponse
-		resp, err = t.logic.HandleScrape(context.TODO(), req)
+		resp, err = t.logic.HandleScrape(context.Background(), req)
 		if err != nil {
 			WriteError(w, txID, err)
 			return
@@ -234,13 +231,12 @@ func (t *Frontend) handleRequest(r Request, w ResponseWriter) (actionName string
 
 		WriteScrape(w, txID, resp)
 
-		go t.logic.AfterScrape(context.TODO(), req, resp)
+		go t.logic.AfterScrape(context.Background(), req, resp)
-
-		return
 
 	default:
 		err = errUnknownAction
 		WriteError(w, txID, err)
-		return
 	}
+
+	return
 }

middleware/jwt/jwt.go

@@ -11,7 +11,6 @@ import (
 	"crypto"
 	"encoding/json"
 	"errors"
-	"log"
 	"net/http"
 	"net/url"
 	"time"
@@ -19,6 +18,7 @@ import (
 	jc "github.com/SermoDigital/jose/crypto"
 	"github.com/SermoDigital/jose/jws"
 	"github.com/SermoDigital/jose/jwt"
+	log "github.com/Sirupsen/logrus"
 	"github.com/mendsley/gojwk"
 
 	"github.com/chihaya/chihaya/bittorrent"
@@ -64,7 +64,7 @@ func NewHook(cfg Config) middleware.Hook {
 			case <-time.After(cfg.JWKUpdateInterval):
 				resp, err := http.Get(cfg.JWKSetURL)
 				if err != nil {
-					log.Println("failed to fetch JWK Set: " + err.Error())
+					log.Errorln("failed to fetch JWK Set: " + err.Error())
 					continue
 				}
 
@@ -72,7 +72,7 @@ func NewHook(cfg Config) middleware.Hook {
 				err = json.NewDecoder(resp.Body).Decode(&parsedJWKs)
 				if err != nil {
 					resp.Body.Close()
-					log.Println("failed to decode JWK JSON: " + err.Error())
+					log.Errorln("failed to decode JWK JSON: " + err.Error())
 					continue
 				}
 				resp.Body.Close()
@@ -81,7 +81,7 @@ func NewHook(cfg Config) middleware.Hook {
 				for kid, parsedJWK := range parsedJWKs {
 					publicKey, err := parsedJWK.DecodePublicKey()
 					if err != nil {
-						log.Println("failed to decode JWK into public key: " + err.Error())
+						log.Errorln("failed to decode JWK into public key: " + err.Error())
 						continue
 					}
 					keys[kid] = publicKey

middleware/middleware.go

@@ -4,9 +4,9 @@ package middleware
 
 import (
 	"context"
-	"log"
 	"time"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/chihaya/chihaya/bittorrent"
 	"github.com/chihaya/chihaya/frontend"
 	"github.com/chihaya/chihaya/storage"
@@ -65,7 +65,7 @@ func (l *Logic) HandleAnnounce(ctx context.Context, req *bittorrent.AnnounceRequ
 func (l *Logic) AfterAnnounce(ctx context.Context, req *bittorrent.AnnounceRequest, resp *bittorrent.AnnounceResponse) {
 	for _, h := range l.postHooks {
 		if err := h.HandleAnnounce(ctx, req, resp); err != nil {
-			log.Println("chihaya: post-announce hooks failed:", err.Error())
+			log.Errorln("chihaya: post-announce hooks failed:", err.Error())
 			return
 		}
 	}
@@ -90,7 +90,7 @@ func (l *Logic) HandleScrape(ctx context.Context, req *bittorrent.ScrapeRequest)
 func (l *Logic) AfterScrape(ctx context.Context, req *bittorrent.ScrapeRequest, resp *bittorrent.ScrapeResponse) {
 	for _, h := range l.postHooks {
 		if err := h.HandleScrape(ctx, req, resp); err != nil {
-			log.Println("chihaya: post-scrape hooks failed:", err.Error())
+			log.Errorln("chihaya: post-scrape hooks failed:", err.Error())
 			return
 		}
 	}

storage/memory/peer_store.go

@@ -3,12 +3,13 @@ package memory
 import (
 	"encoding/binary"
 	"errors"
-	"log"
 	"net"
 	"runtime"
 	"sync"
 	"time"
 
+	log "github.com/Sirupsen/logrus"
+
 	"github.com/chihaya/chihaya/bittorrent"
 	"github.com/chihaya/chihaya/storage"
 )
@@ -53,7 +54,7 @@ func New(cfg Config) (storage.PeerStore, error) {
 				return
 			case <-time.After(cfg.GarbageCollectionInterval):
 				before := time.Now().Add(-cfg.PeerLifetime)
-				log.Println("memory: purging peers with no announces since ", before)
+				log.Debugln("memory: purging peers with no announces since", before)
 				ps.collectGarbage(before)
 			}
 		}
@@ -327,7 +328,6 @@ func (s *peerStore) collectGarbage(cutoff time.Time) error {
 	default:
 	}
 
-	log.Printf("memory: collecting garbage. Cutoff time: %s", cutoff.String())
 	cutoffUnix := cutoff.UnixNano()
 	for _, shard := range s.shards {
 		shard.RLock()