Merge pull request #127 from smacker/log_context

Log context

dummy/dummy_test.go

@@ -13,8 +13,13 @@ import (
 	"google.golang.org/grpc"
 	"gopkg.in/src-d/go-git-fixtures.v3"
 	"gopkg.in/src-d/go-git.v4/storage/filesystem"
+	log "gopkg.in/src-d/go-log.v1"
 )
 
+func init() {
+	log.DefaultLogger = log.New(log.Fields{"app": "dummy"})
+}
+
 type DummySuite struct {
 	suite.Suite
 	Basic          *fixtures.Fixture

provider/github/utils.go

@@ -1,15 +1,16 @@
 package github
 
 import (
+	"context"
 	"fmt"
 	"strconv"
 
 	"github.com/src-d/lookout"
+	"github.com/src-d/lookout/util/ctxlog"
 
 	"github.com/google/go-github/github"
 	"gopkg.in/sourcegraph/go-vcsurl.v1"
 	"gopkg.in/src-d/go-git.v4/plumbing"
-	"gopkg.in/src-d/go-log.v1"
 )
 
 func castEvent(r *lookout.RepositoryInfo, e *github.Event) (lookout.Event, error) {
@@ -65,21 +66,21 @@ func castHash(sha1 *string) plumbing.Hash {
 	return plumbing.NewHash(*sha1)
 }
 
-func castPullRequest(r *lookout.RepositoryInfo, pr *github.PullRequest) *lookout.ReviewEvent {
+func castPullRequest(ctx context.Context, r *lookout.RepositoryInfo, pr *github.PullRequest) *lookout.ReviewEvent {
 	pre := &lookout.ReviewEvent{}
 	pre.Provider = Provider
 	pre.InternalID = strconv.FormatInt(pr.GetID(), 10)
 
 	pre.Number = uint32(pr.GetNumber())
 	pre.RepositoryID = uint32(pr.GetHead().GetRepo().GetID())
-	pre.Source = castPullRequestBranch(pr.GetHead())
+	pre.Source = castPullRequestBranch(ctx, pr.GetHead())
 	pre.Merge = lookout.ReferencePointer{
 		InternalRepositoryURL: r.CloneURL,
 		ReferenceName:         plumbing.ReferenceName(fmt.Sprintf("refs/pull/%d/merge", pr.GetNumber())),
 		Hash:                  pr.GetMergeCommitSHA(),
 	}
 
-	pre.Base = castPullRequestBranch(pr.GetBase())
+	pre.Base = castPullRequestBranch(ctx, pr.GetBase())
 	pre.Head = lookout.ReferencePointer{
 		InternalRepositoryURL: r.CloneURL,
 		ReferenceName:         plumbing.ReferenceName(fmt.Sprintf("refs/pull/%d/head", pr.GetNumber())),
@@ -91,15 +92,15 @@ func castPullRequest(r *lookout.RepositoryInfo, pr *github.PullRequest) *lookout
 	return pre
 }
 
-func castPullRequestBranch(b *github.PullRequestBranch) lookout.ReferencePointer {
+func castPullRequestBranch(ctx context.Context, b *github.PullRequestBranch) lookout.ReferencePointer {
 	if b == nil {
-		log.Warningf("empty pull request branch given")
+		ctxlog.Get(ctx).Warningf("empty pull request branch given")
 		return lookout.ReferencePointer{}
 	}
 
 	r, err := vcsurl.Parse(b.GetRepo().GetCloneURL())
 	if err != nil {
-		log.Warningf("malformed repository URL on pull request branch")
+		ctxlog.Get(ctx).Warningf("malformed repository URL on pull request branch")
 		return lookout.ReferencePointer{}
 	}
 

provider/github/watcher.go

@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"github.com/src-d/lookout"
+	"github.com/src-d/lookout/util/ctxlog"
 
 	"github.com/google/go-github/github"
 	"gopkg.in/src-d/go-errors.v1"
@@ -47,7 +48,7 @@ func NewWatcher(pool *ClientPool, o *lookout.WatchOptions) (*Watcher, error) {
 
 // Watch start to make request to the GitHub API and return the new events.
 func (w *Watcher) Watch(ctx context.Context, cb lookout.EventHandler) error {
-	log.With(log.Fields{"urls": w.o.URLs}).Infof("Starting watcher")
+	ctxlog.Get(ctx).With(log.Fields{"urls": w.o.URLs}).Infof("Starting watcher")
 
 	ctx, cancel := context.WithCancel(ctx)
 	defer cancel()
@@ -125,7 +126,7 @@ func (w *Watcher) processRepoPRs(
 		return minInterval, err
 	}
 
-	err = w.handlePrs(cb, repo, resp, prs)
+	err = w.handlePrs(ctx, cb, repo, resp, prs)
 	return minInterval, err
 }
 
@@ -147,26 +148,32 @@ func (w *Watcher) processRepoEvents(
 		return c.PollInterval(eventsCategory), err
 	}
 
-	err = w.handleEvents(cb, repo, resp, events)
+	err = w.handleEvents(ctx, cb, repo, resp, events)
 	return c.PollInterval(eventsCategory), err
 }
 
-func (w *Watcher) handlePrs(cb lookout.EventHandler, r *lookout.RepositoryInfo,
+func (w *Watcher) handlePrs(ctx context.Context, cb lookout.EventHandler, r *lookout.RepositoryInfo,
 	resp *github.Response, prs []*github.PullRequest) error {
 
 	if len(prs) == 0 {
 		return nil
 	}
 
+	ctx, logger := ctxlog.WithLogFields(ctx, log.Fields{"repo": r.Link()})
+
 	for _, e := range prs {
-		event := castPullRequest(r, e)
+		ctx, _ := ctxlog.WithLogFields(ctx, log.Fields{
+			"pr-id":     e.GetID(),
+			"pr-number": e.GetNumber(),
+		})
+		event := castPullRequest(ctx, r, e)
 
 		if err := cb(event); err != nil {
 			return err
 		}
 	}
 
-	log.Debugf("request to %s cached", resp.Request.URL)
+	logger.Debugf("request to %s cached", resp.Request.URL)
 
 	client, err := w.getClient(r.Username, r.Name)
 	if err != nil {
@@ -176,17 +183,19 @@ func (w *Watcher) handlePrs(cb lookout.EventHandler, r *lookout.RepositoryInfo,
 	return client.Validate(resp.Request.URL.String())
 }
 
-func (w *Watcher) handleEvents(cb lookout.EventHandler, r *lookout.RepositoryInfo,
+func (w *Watcher) handleEvents(ctx context.Context, cb lookout.EventHandler, r *lookout.RepositoryInfo,
 	resp *github.Response, events []*github.Event) error {
 
 	if len(events) == 0 {
 		return nil
 	}
 
+	ctx, logger := ctxlog.WithLogFields(ctx, log.Fields{"repo": r.Link()})
+
 	for _, e := range events {
 		event, err := w.handleEvent(r, e)
 		if err != nil {
-			log.Errorf(err, "error handling event")
+			logger.Errorf(err, "error handling event")
 			continue
 		}
 
@@ -199,7 +208,7 @@ func (w *Watcher) handleEvents(cb lookout.EventHandler, r *lookout.RepositoryInf
 		}
 	}
 
-	log.Debugf("request to %s cached", resp.Request.URL)
+	logger.Debugf("request to %s cached", resp.Request.URL)
 
 	client, err := w.getClient(r.Username, r.Name)
 	if err != nil {

provider/github/watcher_test.go

@@ -24,6 +24,7 @@ import (
 func init() {
 	// make everything faster for tests
 	minInterval = time.Millisecond
+	log.DefaultLogger = log.New(log.Fields{"app": "lookout"})
 }
 
 type WatcherTestSuite struct {

provider/json/poster.go

@@ -6,6 +6,7 @@ import (
 	"io"
 
 	"github.com/src-d/lookout"
+	"github.com/src-d/lookout/util/ctxlog"
 	"gopkg.in/src-d/go-log.v1"
 )
 
@@ -44,6 +45,6 @@ func (p *Poster) Post(ctx context.Context, e lookout.Event,
 func (p *Poster) Status(ctx context.Context, e lookout.Event,
 	status lookout.AnalysisStatus) error {
 
-	log.With(log.Fields{"status": status}).Infof("New status")
+	ctxlog.Get(ctx).With(log.Fields{"status": status}).Infof("New status")
 	return nil
 }

provider/json/watcher.go

@@ -8,6 +8,7 @@ import (
 	"strings"
 
 	"github.com/src-d/lookout"
+	"github.com/src-d/lookout/util/ctxlog"
 
 	"gopkg.in/src-d/go-log.v1"
 )
@@ -31,7 +32,7 @@ func NewWatcher(reader io.Reader, o *lookout.WatchOptions) (*Watcher, error) {
 
 // Watch reads json from stdin and calls cb for each new event
 func (w *Watcher) Watch(ctx context.Context, cb lookout.EventHandler) error {
-	log.With(log.Fields{"provider": Provider}).Infof("Starting watcher")
+	ctxlog.Get(ctx).With(log.Fields{"provider": Provider}).Infof("Starting watcher")
 
 	lines := make(chan string, 1)
 	go func() {
@@ -45,7 +46,7 @@ func (w *Watcher) Watch(ctx context.Context, cb lookout.EventHandler) error {
 		case <-ctx.Done():
 			return ctx.Err()
 		case line := <-lines:
-			if err := w.handleInput(cb, line); err != nil {
+			if err := w.handleInput(ctx, cb, line); err != nil {
 				if lookout.NoErrStopWatcher.Is(err) {
 					return nil
 				}
@@ -60,15 +61,17 @@ type eventType struct {
 	Event string `json:"event"`
 }
 
-func (w *Watcher) handleInput(cb lookout.EventHandler, line string) error {
+func (w *Watcher) handleInput(ctx context.Context, cb lookout.EventHandler, line string) error {
 	if line == "" {
 		return nil
 	}
 
+	logger := ctxlog.Get(ctx).With(log.Fields{"input": line})
+
 	var eventType eventType
 
 	if err := json.Unmarshal([]byte(line), &eventType); err != nil {
-		log.With(log.Fields{"input": line}).Errorf(err, "could not unmarshal the event")
+		logger.Errorf(err, "could not unmarshal the event")
 
 		return nil
 	}
@@ -77,26 +80,26 @@ func (w *Watcher) handleInput(cb lookout.EventHandler, line string) error {
 
 	switch strings.ToLower(eventType.Event) {
 	case "":
-		log.With(log.Fields{"input": line}).Errorf(nil, `field "event" is mandatory`)
+		logger.Errorf(nil, `field "event" is mandatory`)
 		return nil
 	case "review":
 		var reviewEvent *lookout.ReviewEvent
 		if err := json.Unmarshal([]byte(line), &reviewEvent); err != nil {
-			log.With(log.Fields{"input": line}).Errorf(err, "could not unmarshal the ReviewEvent")
+			logger.Errorf(err, "could not unmarshal the ReviewEvent")
 			return nil
 		}
 
 		event = reviewEvent
 	case "push":
 		var pushEvent *lookout.PushEvent
 		if err := json.Unmarshal([]byte(line), &pushEvent); err != nil {
-			log.With(log.Fields{"input": line}).Errorf(err, "could not unmarshal the PushEvent")
+			logger.Errorf(err, "could not unmarshal the PushEvent")
 			return nil
 		}
 
 		event = pushEvent
 	default:
-		log.Errorf(nil, "event %q not supported", eventType.Event)
+		logger.Errorf(nil, "event %q not supported", eventType.Event)
 		return nil
 	}
 

provider/json/watcher_test.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/src-d/lookout"
 	"github.com/src-d/lookout/pb"
+	log "gopkg.in/src-d/go-log.v1"
 
 	"github.com/stretchr/testify/suite"
 )
@@ -28,6 +29,10 @@ var (
 	badJSON    = `{"event":"push", { ...`
 )
 
+func init() {
+	log.DefaultLogger = log.New(log.Fields{"app": "lookout"})
+}
+
 func (s *WatcherTestSuite) TestWatch() {
 	var events int