Merge branch 'id-switch-logging-to-labkit' into 'main'

Switch to labkit/log for logging functionality

See merge request gitlab-org/gitlab-shell!498

8 files changed, 46 insertions, 48 deletions

diff --git a/client/gitlabnet.go b/client/gitlabnet.go
index a5b22ee..a262d93 100644
--- a/client/gitlabnet.go
+++ b/client/gitlabnet.go
@@ -11,9 +11,7 @@ import (
 	"strings"
 	"time"
 
-	"gitlab.com/gitlab-org/labkit/correlation"
-
-	log "github.com/sirupsen/logrus"
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 const (
@@ -71,12 +69,12 @@ func normalizePath(path string) string {
 	return path
 }
 
-func newRequest(ctx context.Context, method, host, path string, data interface{}) (*http.Request, string, error) {
+func newRequest(ctx context.Context, method, host, path string, data interface{}) (*http.Request, error) {
 	var jsonReader io.Reader
 	if data != nil {
 		jsonData, err := json.Marshal(data)
 		if err != nil {
-			return nil, "", err
+			return nil, err
 		}
 
 		jsonReader = bytes.NewReader(jsonData)
@@ -84,12 +82,10 @@ func newRequest(ctx context.Context, method, host, path string, data interface{}
 
 	request, err := http.NewRequestWithContext(ctx, method, host+path, jsonReader)
 	if err != nil {
-		return nil, "", err
+		return nil, err
 	}
 
-	correlationID := correlation.ExtractFromContext(ctx)
-
-	return request, correlationID, nil
+	return request, nil
 }
 
 func parseError(resp *http.Response) error {
@@ -116,7 +112,7 @@ func (c *GitlabNetClient) Post(ctx context.Context, path string, data interface{
 }
 
 func (c *GitlabNetClient) DoRequest(ctx context.Context, method, path string, data interface{}) (*http.Response, error) {
-	request, correlationID, err := newRequest(ctx, method, c.httpClient.Host, path, data)
+	request, err := newRequest(ctx, method, c.httpClient.Host, path, data)
 	if err != nil {
 		return nil, err
 	}
@@ -136,12 +132,11 @@ func (c *GitlabNetClient) DoRequest(ctx context.Context, method, path string, da
 	start := time.Now()
 	response, err := c.httpClient.Do(request)
 	fields := log.Fields{
-		"correlation_id": correlationID,
 		"method":         method,
 		"url":            request.URL.String(),
 		"duration_ms":    time.Since(start) / time.Millisecond,
 	}
-	logger := log.WithFields(fields)
+	logger := log.WithContextFields(ctx, fields)
 
 	if err != nil {
 		logger.WithError(err).Error("Internal API unreachable")
diff --git a/client/httpclient.go b/client/httpclient.go
index 0dcec94..bcf81dd 100644
--- a/client/httpclient.go
+++ b/client/httpclient.go
@@ -12,9 +12,9 @@ import (
 	"strings"
 	"time"
 
-	log "github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/labkit/correlation"
 	"gitlab.com/gitlab-org/labkit/tracing"
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 const (
diff --git a/cmd/gitlab-sshd/acceptance_test.go b/cmd/gitlab-sshd/acceptance_test.go
index c92a8aa..7cb1c48 100644
--- a/cmd/gitlab-sshd/acceptance_test.go
+++ b/cmd/gitlab-sshd/acceptance_test.go
@@ -229,7 +229,7 @@ func startSSHD(t *testing.T, dir string) string {
 	t.Cleanup(func() { pw.Close() })
 
 	scanner := bufio.NewScanner(pr)
-	extractor := regexp.MustCompile(`msg="Listening on ([0-9a-f\[\]\.:]+)"`)
+	extractor := regexp.MustCompile(`tcp_address="([0-9a-f\[\]\.:]+)"`)
 
 	ctx, cancel := context.WithCancel(context.Background())
 	cmd := exec.CommandContext(ctx, sshdPath, "-config-dir", dir)
diff --git a/cmd/gitlab-sshd/main.go b/cmd/gitlab-sshd/main.go
index e524023..4cc5f69 100644
--- a/cmd/gitlab-sshd/main.go
+++ b/cmd/gitlab-sshd/main.go
@@ -8,13 +8,13 @@ import (
 	"syscall"
 	"time"
 
-	log "github.com/sirupsen/logrus"
-
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/logger"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/sshd"
+
 	"gitlab.com/gitlab-org/labkit/monitoring"
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 var (
@@ -49,15 +49,16 @@ func main() {
 		var err error
 		cfg, err = config.NewFromDir(*configDir)
 		if err != nil {
-			log.Fatalf("failed to load configuration from specified directory: %v", err)
+			log.WithError(err).Fatal("failed to load configuration from specified directory")
 		}
 	}
 	overrideConfigFromEnvironment(cfg)
 	if err := cfg.IsSane(); err != nil {
 		if *configDir == "" {
-			log.Warn("note: no config-dir provided, using only environment variables")
+			log.WithError(err).Fatal("no config-dir provided, using only environment variables")
+		} else {
+			log.WithError(err).Fatal("configuration error")
 		}
-		log.Fatalf("configuration error: %v", err)
 	}
 
 	cfg.ApplyGlobalState()
@@ -72,13 +73,13 @@ func main() {
 	// Startup monitoring endpoint.
 	if cfg.Server.WebListen != "" {
 		go func() {
-			log.Fatal(
-				monitoring.Start(
-					monitoring.WithListenerAddress(cfg.Server.WebListen),
-					monitoring.WithBuildInformation(Version, BuildTime),
-					monitoring.WithServeMux(server.MonitoringServeMux()),
-				),
+			err := monitoring.Start(
+				monitoring.WithListenerAddress(cfg.Server.WebListen),
+				monitoring.WithBuildInformation(Version, BuildTime),
+				monitoring.WithServeMux(server.MonitoringServeMux()),
 			)
+
+			log.WithError(err).Fatal("monitoring service raised an error")
 		}()
 	}
 
@@ -92,7 +93,7 @@ func main() {
 		sig := <-done
 		signal.Reset(syscall.SIGINT, syscall.SIGTERM)
 
-		log.WithFields(log.Fields{"shutdown_timeout_s": cfg.Server.GracePeriodSeconds, "signal": sig.String()}).Infof("Shutdown initiated")
+		log.WithFields(log.Fields{"shutdown_timeout_s": cfg.Server.GracePeriodSeconds, "signal": sig.String()}).Info("Shutdown initiated")
 
 		server.Shutdown()
 
@@ -103,6 +104,6 @@ func main() {
 	}()
 
 	if err := server.ListenAndServe(ctx); err != nil {
-		log.Fatalf("Failed to start GitLab built-in sshd: %v", err)
+		log.WithError(err).Fatal("Failed to start GitLab built-in sshd")
 	}
 }
diff --git a/internal/command/shared/customaction/customaction.go b/internal/command/shared/customaction/customaction.go
index d91f8ab..34086fb 100644
--- a/internal/command/shared/customaction/customaction.go
+++ b/internal/command/shared/customaction/customaction.go
@@ -10,12 +10,13 @@ import (
 	"io"
 	"net/http"
 
-	log "github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet/accessverifier"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/pktline"
+
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 type Request struct {
diff --git a/internal/handler/exec.go b/internal/handler/exec.go
index fd0ea89..89856f7 100644
--- a/internal/handler/exec.go
+++ b/internal/handler/exec.go
@@ -8,19 +8,20 @@ import (
 
 	grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware"
 	grpc_prometheus "github.com/grpc-ecosystem/go-grpc-prometheus"
-	log "github.com/sirupsen/logrus"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/metadata"
 
-	gitalyauth "gitlab.com/gitlab-org/gitaly/v14/auth"
-	"gitlab.com/gitlab-org/gitaly/v14/client"
-	pb "gitlab.com/gitlab-org/gitaly/v14/proto/go/gitalypb"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet/accessverifier"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/sshenv"
-	"gitlab.com/gitlab-org/labkit/correlation"
+
+	gitalyauth "gitlab.com/gitlab-org/gitaly/v14/auth"
+	"gitlab.com/gitlab-org/gitaly/v14/client"
+	pb "gitlab.com/gitlab-org/gitaly/v14/proto/go/gitalypb"
 	grpccorrelation "gitlab.com/gitlab-org/labkit/correlation/grpc"
 	grpctracing "gitlab.com/gitlab-org/labkit/tracing/grpc"
+	"gitlab.com/gitlab-org/labkit/correlation"
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 // GitalyHandlerFunc implementations are responsible for making
@@ -75,7 +76,6 @@ func (gc *GitalyCommand) PrepareContext(ctx context.Context, repository *pb.Repo
 func (gc *GitalyCommand) LogExecution(ctx context.Context, repository *pb.Repository, response *accessverifier.Response, env sshenv.Env) {
 	fields := log.Fields{
 		"command":         gc.ServiceName,
-		"correlation_id":  correlation.ExtractFromContext(ctx),
 		"gl_project_path": repository.GlProjectPath,
 		"gl_repository":   repository.GlRepository,
 		"user_id":         response.UserId,
@@ -86,7 +86,7 @@ func (gc *GitalyCommand) LogExecution(ctx context.Context, repository *pb.Reposi
 		"gl_key_id":       response.KeyId,
 	}
 
-	log.WithFields(fields).Info("executing git command")
+	log.WithContextFields(ctx, fields).Info("executing git command")
 }
 
 func withOutgoingMetadata(ctx context.Context, features map[string]string) context.Context {
@@ -108,9 +108,9 @@ func getConn(ctx context.Context, gc *GitalyCommand) (*grpc.ClientConn, error) {
 
 	serviceName := correlation.ExtractClientNameFromContext(ctx)
 	if serviceName == "" {
-		log.Warn("No gRPC service name specified, defaulting to gitlab-shell-unknown")
-
 		serviceName = "gitlab-shell-unknown"
+
+		log.WithFields(log.Fields{"service_name": serviceName}).Warn("No gRPC service name specified, defaulting to gitlab-shell-unknown")
 	}
 
 	serviceName = fmt.Sprintf("%s-%s", serviceName, gc.ServiceName)
diff --git a/internal/sshd/connection.go b/internal/sshd/connection.go
index 5ff055c..0e0da93 100644
--- a/internal/sshd/connection.go
+++ b/internal/sshd/connection.go
@@ -4,11 +4,12 @@ import (
 	"context"
 	"time"
 
-	log "github.com/sirupsen/logrus"
 	"golang.org/x/crypto/ssh"
 	"golang.org/x/sync/semaphore"
 
 	"gitlab.com/gitlab-org/gitlab-shell/internal/metrics"
+
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 type connection struct {
@@ -42,7 +43,7 @@ func (c *connection) handle(ctx context.Context, chans <-chan ssh.NewChannel, ha
 		}
 		channel, requests, err := newChannel.Accept()
 		if err != nil {
-			log.Infof("Could not accept channel: %v", err)
+			log.WithError(err).Info("could not accept channel")
 			c.concurrentSessions.Release(1)
 			continue
 		}
@@ -53,7 +54,7 @@ func (c *connection) handle(ctx context.Context, chans <-chan ssh.NewChannel, ha
 			// Prevent a panic in a single session from taking out the whole server
 			defer func() {
 				if err := recover(); err != nil {
-					log.Warnf("panic handling session from %s: recovered: %#+v", c.remoteAddr, err)
+					log.WithFields(log.Fields{"recovered_error": err}).Warnf("panic handling session from %s", c.remoteAddr)
 				}
 			}()
 
diff --git a/internal/sshd/sshd.go b/internal/sshd/sshd.go
index ac4ebf8..d3b5ec1 100644
--- a/internal/sshd/sshd.go
+++ b/internal/sshd/sshd.go
@@ -12,13 +12,13 @@ import (
 	"sync"
 	"net/http"
 
-	log "github.com/sirupsen/logrus"
-
 	"github.com/pires/go-proxyproto"
 	"golang.org/x/crypto/ssh"
 
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet/authorizedkeys"
+
+	"gitlab.com/gitlab-org/labkit/log"
 	"gitlab.com/gitlab-org/labkit/correlation"
 )
 
@@ -89,7 +89,7 @@ func (s *Server) listen() error {
 		log.Info("Proxy protocol is enabled")
 	}
 
-	log.Infof("Listening on %v", sshListener.Addr().String())
+	log.WithFields(log.Fields{"tcp_address": sshListener.Addr().String()}).Info("Listening for SSH connections")
 
 	s.listener = sshListener
 
@@ -111,7 +111,7 @@ func (s *Server) serve(ctx context.Context) error {
 				break
 			}
 
-			log.Warnf("Failed to accept connection: %v\n", err)
+			log.WithError(err).Warn("Failed to accept connection")
 			continue
 		}
 
@@ -173,12 +173,12 @@ func (s *Server) initConfig(ctx context.Context) (*ssh.ServerConfig, error) {
 	for _, filename := range s.Config.Server.HostKeyFiles {
 		keyRaw, err := ioutil.ReadFile(filename)
 		if err != nil {
-			log.Warnf("Failed to read host key %v: %v", filename, err)
+			log.WithError(err).Warnf("Failed to read host key %v", filename)
 			continue
 		}
 		key, err := ssh.ParsePrivateKey(keyRaw)
 		if err != nil {
-			log.Warnf("Failed to parse host key %v: %v", filename, err)
+			log.WithError(err).Warnf("Failed to parse host key %v", filename)
 			continue
 		}
 		loadedHostKeys++
@@ -201,7 +201,7 @@ func (s *Server) handleConn(ctx context.Context, sshCfg *ssh.ServerConfig, nconn
 	// Prevent a panic in a single connection from taking out the whole server
 	defer func() {
 		if err := recover(); err != nil {
-			log.Warnf("panic handling connection from %s: recovered: %#+v", remoteAddr, err)
+			log.WithFields(log.Fields{"recovered_error": err}).Warnf("panic handling session from %s", remoteAddr)
 		}
 	}()
 
@@ -210,7 +210,7 @@ func (s *Server) handleConn(ctx context.Context, sshCfg *ssh.ServerConfig, nconn
 
 	sconn, chans, reqs, err := ssh.NewServerConn(nconn, sshCfg)
 	if err != nil {
-		log.Infof("Failed to initialize SSH connection: %v", err)
+		log.WithError(err).Info("Failed to initialize SSH connection")
 		return
 	}