Merge branch 'log-interceptor' into 'master'

Log access and errors from interceptors

See merge request !149

13 files changed, 78 insertions, 38 deletions

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 5908c8684..6046d973b 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,5 +1,10 @@
 # Gitaly changelog
 
+UNRELEASED
+
+- Hide chatty logs behind GITALY_DEBUG=1. Log access times.
+  https://gitlab.com/gitlab-org/gitaly/merge_requests/149
+
 v0.10.0
 
 - CommitDiff: Parse a typechange diff correctly
diff --git a/cmd/gitaly/main.go b/cmd/gitaly/main.go
index 0a73134ec..082e67696 100644
--- a/cmd/gitaly/main.go
+++ b/cmd/gitaly/main.go
@@ -9,6 +9,7 @@ import (
 
 	"gitlab.com/gitlab-org/gitaly/internal/config"
 	"gitlab.com/gitlab-org/gitaly/internal/service"
+	"gitlab.com/gitlab-org/gitaly/internal/service/middleware/loghandler"
 	"gitlab.com/gitlab-org/gitaly/internal/service/middleware/panichandler"
 
 	"github.com/grpc-ecosystem/go-grpc-prometheus"
@@ -83,10 +84,12 @@ func main() {
 		grpc.StreamInterceptor(grpc_middleware.ChainStreamServer(
 			panichandler.StreamPanicHandler,         // Panic Handler first: handle panics gracefully
 			grpc_prometheus.StreamServerInterceptor, // Prometheus Metrics next: measure RPC times
+			loghandler.StreamLogHandler,
 		)),
 		grpc.UnaryInterceptor(grpc_middleware.ChainUnaryServer(
 			panichandler.UnaryPanicHandler,         // Panic Handler first: handle panics gracefully
 			grpc_prometheus.UnaryServerInterceptor, // Prometheus Metrics next: measure RPC times
+			loghandler.UnaryLogHandler,
 		)),
 	)
 
diff --git a/doc/configuration/README.md b/doc/configuration/README.md
index 7a44a3e15..e656f0665 100644
--- a/doc/configuration/README.md
+++ b/doc/configuration/README.md
@@ -57,14 +57,16 @@ match those in gitlab.yml.
 |path|string|yes|Path to storage shard|
 |name|string|yes|Name of storage shard|
 
-## Legacy environment variables
+## Environment variables
 
-These were used to configure earlier version of Gitaly. When present,
-they take precendence over the configuration file.
+### GITALY_DEBUG
+
+When set to `1`, Gitaly will print debug log messages.
 
 ### GITALY_SOCKET_PATH
 
-Required unless GITALY_LISTEN_ADDR is set.
+Required unless GITALY_LISTEN_ADDR is set. Overrides `socket_path` in
+config.toml. Deprecated; use config.toml.
 
 A path at which Gitaly should open a Unix socket. Example value:
 
@@ -74,7 +76,8 @@ GITALY_SOCKET_PATH=/home/git/gitlab/tmp/sockets/private/gitaly.socket
 
 ### GITALY_LISTEN_ADDR
 
-Required unless GITALY_SOCKET_PATH is set.
+Required unless GITALY_SOCKET_PATH is set. Overrides `listen_addr` in
+config.toml. Deprecated; use config.toml.
 
 TCP address for Gitaly to listen on. Note: at the moment Gitaly does
 not offer any form of authentication. When you use a TCP listener you
@@ -89,7 +92,8 @@ GITALY_LISTEN_ADDR=localhost:1234
 
 ### GITALY_PROMETHEUS_LISTEN_ADDR
 
-Optional.
+Optional. Overrides `prometheus_listen_addr` in config.toml.
+Deprecated; use config.toml.
 
 TCP listen address for Prometheus metrics. When missing or empty, no
 Prometheus listener is started.
diff --git a/internal/helper/debug.go b/internal/helper/debug.go
new file mode 100644
index 000000000..f016ece8c
--- /dev/null
+++ b/internal/helper/debug.go
@@ -0,0 +1,15 @@
+package helper
+
+import (
+	"log"
+	"os"
+)
+
+// Debugf behaves similarly to log.Printf. No-op unless GITALY_DEBUG=1.
+func Debugf(format string, args ...interface{}) {
+	if os.Getenv("GITALY_DEBUG") != "1" {
+		return
+	}
+
+	log.Printf("debug: "+format, args...)
+}
diff --git a/internal/service/commit/isancestor.go b/internal/service/commit/isancestor.go
index 3afa86fa3..59b64774e 100644
--- a/internal/service/commit/isancestor.go
+++ b/internal/service/commit/isancestor.go
@@ -2,7 +2,6 @@ package commit
 
 import (
 	"io/ioutil"
-	"log"
 	"os/exec"
 
 	"google.golang.org/grpc"
@@ -20,14 +19,10 @@ func (s *server) CommitIsAncestor(ctx context.Context, in *pb.CommitIsAncestorRe
 		return nil, err
 	}
 	if in.AncestorId == "" {
-		message := "Bad Request (empty ancestor sha)"
-		log.Printf("CommitIsAncestor: %q", message)
-		return nil, grpc.Errorf(codes.InvalidArgument, message)
+		return nil, grpc.Errorf(codes.InvalidArgument, "Bad Request (empty ancestor sha)")
 	}
 	if in.ChildId == "" {
-		message := "Bad Request (empty child sha)"
-		log.Printf("CommitIsAncestor: %q", message)
-		return nil, grpc.Errorf(codes.InvalidArgument, message)
+		return nil, grpc.Errorf(codes.InvalidArgument, "Bad Request (empty child sha)")
 	}
 
 	ret, err := commitIsAncestorName(repoPath, in.AncestorId, in.ChildId)
@@ -43,7 +38,6 @@ func commitIsAncestorName(path, ancestorID, childID string) (bool, error) {
 	}
 	defer cmd.Kill()
 
-	log.Printf("commitIsAncestor: RepoPath=%q ancestorSha=%s childSha=%s", path, ancestorID, childID)
-
+	helper.Debugf("commitIsAncestor: RepoPath=%q ancestorSha=%s childSha=%s", path, ancestorID, childID)
 	return cmd.Wait() == nil, nil
 }
diff --git a/internal/service/diff/commit.go b/internal/service/diff/commit.go
index 99986519d..fa3801ca3 100644
--- a/internal/service/diff/commit.go
+++ b/internal/service/diff/commit.go
@@ -2,7 +2,6 @@ package diff
 
 import (
 	"fmt"
-	"log"
 
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
 	"gitlab.com/gitlab-org/gitaly/internal/diff"
@@ -31,7 +30,7 @@ func (s *server) CommitDiff(in *pb.CommitDiffRequest, stream pb.Diff_CommitDiffS
 	ignoreWhitespaceChange := in.GetIgnoreWhitespaceChange()
 	paths := in.GetPaths()
 
-	log.Printf(
+	helper.Debugf(
 		"CommitDiff: RepoPath=%q LeftCommitId=%q RightCommitId=%q IgnoreWhitespaceChange=%t Paths=%s",
 		repoPath,
 		leftSha,
@@ -95,7 +94,7 @@ func (s *server) CommitDelta(in *pb.CommitDeltaRequest, stream pb.Diff_CommitDel
 	rightSha := in.RightCommitId
 	paths := in.GetPaths()
 
-	log.Printf(
+	helper.Debugf(
 		"CommitDelta: RepoPath=%q LeftCommitId=%q RightCommitId=%q Paths=%s",
 		repoPath,
 		leftSha,
@@ -194,7 +193,6 @@ func eachDiff(rpc string, cmdArgs []string, callback func(*diff.Diff) error) err
 	}
 
 	if err := diffParser.Err(); err != nil {
-		log.Printf("%s: Failed parsing diff for args %s: %v", rpc, cmd.Args)
 		return grpc.Errorf(codes.Internal, "%s: parse failure: %v", rpc, err)
 	}
 
diff --git a/internal/service/middleware/loghandler/loghandler.go b/internal/service/middleware/loghandler/loghandler.go
new file mode 100644
index 000000000..8f4d17f5b
--- /dev/null
+++ b/internal/service/middleware/loghandler/loghandler.go
@@ -0,0 +1,32 @@
+package loghandler
+
+import (
+	"log"
+	"time"
+
+	"golang.org/x/net/context"
+	"google.golang.org/grpc"
+)
+
+// UnaryLogHandler handles access times and errors for unary RPC's
+func UnaryLogHandler(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
+	start := time.Now()
+	resp, err := handler(ctx, req)
+	logRequest(info.FullMethod, start, err)
+	return resp, err
+}
+
+// StreamLogHandler handles access times and errors for stream RPC's
+func StreamLogHandler(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
+	start := time.Now()
+	err := handler(srv, stream)
+	logRequest(info.FullMethod, start, err)
+	return err
+}
+
+func logRequest(method string, start time.Time, err error) {
+	if err != nil {
+		log.Printf("error: %s: %v", method, err)
+	}
+	log.Printf("%s %.3f", method, time.Since(start).Seconds())
+}
diff --git a/internal/service/notifications/post_receive.go b/internal/service/notifications/post_receive.go
index f63db6f9b..e8c809f31 100644
--- a/internal/service/notifications/post_receive.go
+++ b/internal/service/notifications/post_receive.go
@@ -1,8 +1,6 @@
 package notifications
 
 import (
-	"log"
-
 	"gitlab.com/gitlab-org/gitaly/internal/helper"
 
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
@@ -11,12 +9,10 @@ import (
 )
 
 func (s *server) PostReceive(ctx context.Context, in *pb.PostReceiveRequest) (*pb.PostReceiveResponse, error) {
-	// TODO: Invalidate InfoRefs cache
 	repoPath, err := helper.GetRepoPath(in.GetRepository())
 	if err != nil {
 		return nil, err
 	}
-
-	log.Printf("PostReceive: RepoPath=%q", repoPath)
+	helper.Debugf("PostReceive: RepoPath=%q", repoPath)
 	return &pb.PostReceiveResponse{}, nil
 }
diff --git a/internal/service/ref/refname.go b/internal/service/ref/refname.go
index d3b402b94..873974143 100644
--- a/internal/service/ref/refname.go
+++ b/internal/service/ref/refname.go
@@ -2,7 +2,6 @@ package ref
 
 import (
 	"bufio"
-	"log"
 	"strings"
 
 	"google.golang.org/grpc"
@@ -23,9 +22,7 @@ func (s *server) FindRefName(ctx context.Context, in *pb.FindRefNameRequest) (*p
 		return nil, err
 	}
 	if in.CommitId == "" {
-		message := "Bad Request (empty commit sha)"
-		log.Printf("FindRefName: %q", message)
-		return nil, grpc.Errorf(codes.InvalidArgument, message)
+		return nil, grpc.Errorf(codes.InvalidArgument, "Bad Request (empty commit sha)")
 	}
 
 	ref, err := findRefName(repoPath, in.CommitId, string(in.Prefix))
@@ -44,7 +41,7 @@ func findRefName(path, commitID, prefix string) (string, error) {
 	}
 	defer cmd.Kill()
 
-	log.Printf("findRefName: RepoPath=%q commitSha=%s prefix=%s", path, commitID, prefix)
+	helper.Debugf("findRefName: RepoPath=%q commitSha=%s prefix=%s", path, commitID, prefix)
 
 	scanner := bufio.NewScanner(cmd)
 	scanner.Scan()
diff --git a/internal/service/ref/refs.go b/internal/service/ref/refs.go
index 051e9fb5a..eb3f757c9 100644
--- a/internal/service/ref/refs.go
+++ b/internal/service/ref/refs.go
@@ -5,7 +5,6 @@ import (
 	"bytes"
 	"fmt"
 	"io"
-	"log"
 	"strings"
 
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
@@ -39,7 +38,7 @@ func findRefs(writer refsWriter, repo *pb.Repository, pattern string, args ...st
 		return err
 	}
 
-	log.Printf("FindRefs: RepoPath=%q Pattern=%q", repoPath, pattern)
+	helper.Debugf("FindRefs: RepoPath=%q Pattern=%q", repoPath, pattern)
 
 	baseArgs := []string{"--git-dir", repoPath, "for-each-ref", pattern}
 
@@ -165,7 +164,7 @@ func (s *server) FindDefaultBranchName(ctx context.Context, in *pb.FindDefaultBr
 		return nil, err
 	}
 
-	log.Printf("FindDefaultBranchName: RepoPath=%q", repoPath)
+	helper.Debugf("FindDefaultBranchName: RepoPath=%q", repoPath)
 
 	defaultBranchName, err := defaultBranchName(repoPath)
 	if err != nil {
diff --git a/internal/service/smarthttp/inforefs.go b/internal/service/smarthttp/inforefs.go
index 59026f7a5..b527d9019 100644
--- a/internal/service/smarthttp/inforefs.go
+++ b/internal/service/smarthttp/inforefs.go
@@ -3,7 +3,6 @@ package smarthttp
 import (
 	"fmt"
 	"io"
-	"log"
 
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
 	pbhelper "gitlab.com/gitlab-org/gitaly-proto/go/helper"
@@ -39,7 +38,7 @@ func handleInfoRefs(service string, repo *pb.Repository, w io.Writer) error {
 	}
 	defer cmd.Kill()
 
-	log.Printf("handleInfoRefs: service=%q RepoPath=%q", service, repoPath)
+	helper.Debugf("handleInfoRefs: service=%q RepoPath=%q", service, repoPath)
 
 	if err := pktLine(w, fmt.Sprintf("# service=git-%s\n", service)); err != nil {
 		return grpc.Errorf(codes.Internal, "GetInfoRefs: pktLine: %v", err)
diff --git a/internal/service/smarthttp/receive_pack.go b/internal/service/smarthttp/receive_pack.go
index fa0caed2e..91aa97af1 100644
--- a/internal/service/smarthttp/receive_pack.go
+++ b/internal/service/smarthttp/receive_pack.go
@@ -2,7 +2,6 @@ package smarthttp
 
 import (
 	"fmt"
-	"log"
 	"os/exec"
 
 	"gitlab.com/gitlab-org/gitaly/internal/helper"
@@ -38,7 +37,7 @@ func (s *server) PostReceivePack(stream pb.SmartHTTP_PostReceivePackServer) erro
 		return err
 	}
 
-	log.Printf("PostReceivePack: RepoPath=%q GlID=%q GlRepository=%q", repoPath, req.GlId, req.GlRepository)
+	helper.Debugf("PostReceivePack: RepoPath=%q GlID=%q GlRepository=%q", repoPath, req.GlId, req.GlRepository)
 
 	osCommand := exec.Command("git", "receive-pack", "--stateless-rpc", repoPath)
 	cmd, err := helper.NewCommand(osCommand, stdin, stdout, env...)
diff --git a/internal/service/smarthttp/upload_pack.go b/internal/service/smarthttp/upload_pack.go
index f34ee1b7f..deab1da28 100644
--- a/internal/service/smarthttp/upload_pack.go
+++ b/internal/service/smarthttp/upload_pack.go
@@ -1,7 +1,6 @@
 package smarthttp
 
 import (
-	"log"
 	"os/exec"
 
 	"gitlab.com/gitlab-org/gitaly/internal/helper"
@@ -33,7 +32,7 @@ func (s *server) PostUploadPack(stream pb.SmartHTTP_PostUploadPackServer) error
 		return err
 	}
 
-	log.Printf("PostUploadPack: RepoPath=%q", repoPath)
+	helper.Debugf("PostUploadPack: RepoPath=%q", repoPath)
 
 	osCommand := exec.Command("git", "upload-pack", "--stateless-rpc", repoPath)
 	cmd, err := helper.NewCommand(osCommand, stdin, stdout)