Merge branch 'ef-migrate-all-callsites-to-slog' into 'main'

Migrate all Logs to LabKit v2

See merge request https://gitlab.com/gitlab-org/gitlab-shell/-/merge_requests/1381

Merged-by: Igor Drozdov <idrozdov@gitlab.com>
Approved-by: Igor Drozdov <idrozdov@gitlab.com>
Reviewed-by: Vasilii Iakliushin <viakliushin@gitlab.com>
Co-authored-by: e_forbes <eforbes@gitlab.com>

Author: 2 people

.gitlab-ci.yml

@@ -75,29 +75,15 @@ default:
     paths:
       - .GOPATH/pkg/mod/
 
-.cached-ruby: &cached_ruby
-  - key:
-      prefix: "ruby-${RUBY_VERSION}-cache"
-      files:
-        - Gemfile.lock
-    policy: $POLICY
-    paths:
-      - ${BUNDLE_PATH}
-
 .cached-go-job:
   variables:
     CACHE_COMPRESSION_LEVEL: "fastest"
   cache:
     - *cached_go
 
-.cached-ruby-job:
-  cache:
-    - *cached_ruby
-
 .cached-job:
   cache:
     - *cached_go
-    - *cached_ruby
 
 .go-matrix-job:
   parallel:
@@ -108,14 +94,6 @@ default:
 # Prepare jobs
 ################################################################################
 
-bundle:install:
-  stage: prepare
-  extends: .cached-ruby-job
-  variables:
-    POLICY: pull-push
-  script:
-    - bundle install --jobs $(nproc)
-
 modules:download:
   stage: prepare
   extends:
@@ -131,7 +109,7 @@ modules:download:
 ################################################################################
 
 .test-job:
-  needs: ["bundle:install", "modules:download"]
+  needs: ["modules:download"]
   rules: !reference [".rules:go-changes", rules]
   variables:
     GITALY_CONNECTION_INFO: '{"address":"tcp://gitaly:8075", "storage":"default"}'
@@ -140,7 +118,6 @@ modules:download:
     - make build
     - cp config.yml.example config.yml
     - go version
-    - which go
   services:
     - name: registry.gitlab.com/gitlab-org/build/cng/gitaly:master
       # Disable the hooks so we don't have to stub the GitLab API

Makefile

@@ -1,4 +1,4 @@
-.PHONY: validate verify verify_ruby verify_golang test test_fancy coverage coverage_golang setup _script_install make_necessary_dirs build compile check clean install lint
+.PHONY: validate verify test test_fancy coverage setup make_necessary_dirs build compile check clean install lint
 
 FIPS_MODE ?= 0
 OS := $(shell uname | tr A-Z a-z)
@@ -67,14 +67,14 @@ test:
 
 test_fancy: ${GOTESTSUM_FILE}
 	@${GOTESTSUM_FILE} --version
-	@${GOTESTSUM_FILE} --junitfile ./cover.xml --format pkgname -- -coverprofile=./cover.out -covermode=atomic -count 1 -tags "$(GO_TAGS)" ./...
+	@${GOTESTSUM_FILE} --junitfile ./cover.xml --format pkgname -- -coverprofile=./cover.out -covermode=atomic -timeout 1m -count 1 -tags "$(GO_TAGS)" ./...
 
 ${GOTESTSUM_FILE}:
 	mkdir -p $(shell dirname ${GOTESTSUM_FILE})
 	curl -L https://github.com/gotestyourself/gotestsum/releases/download/v${GOTESTSUM_VERSION}/gotestsum_${GOTESTSUM_VERSION}_${OS}_${ARCH}.tar.gz | tar -zOxf - gotestsum > ${GOTESTSUM_FILE} && chmod +x ${GOTESTSUM_FILE}
 
 test_race:
-	go test -race -count 1 ./...
+	go test -race -timeout 1m -count 1 ./... -v
 
 coverage: 
 	[ -f cover.out ] && go tool cover -func cover.out

client/transport.go

@@ -2,12 +2,14 @@
 package client
 
 import (
+	"log/slog"
 	"net/http"
 	"time"
 
 	"gitlab.com/gitlab-org/labkit/correlation"
-	"gitlab.com/gitlab-org/labkit/log"
+	"gitlab.com/gitlab-org/labkit/fields"
 	"gitlab.com/gitlab-org/labkit/tracing"
+	"gitlab.com/gitlab-org/labkit/v2/log"
 )
 
 type transport struct {
@@ -28,32 +30,27 @@ func (rt *transport) RoundTrip(request *http.Request) (*http.Response, error) {
 	start := time.Now()
 
 	response, err := rt.next.RoundTrip(request)
-
-	fields := log.Fields{
-		"method":      request.Method,
-		"url":         request.URL.String(),
-		"duration_ms": time.Since(start) / time.Millisecond,
-	}
-	logger := log.WithContextFields(ctx, fields)
-
+	ctx = log.WithFields(ctx,
+		slog.String("method", request.Method),
+		slog.String("url", request.URL.String()),
+		slog.Float64("duration_s", time.Since(start).Seconds()),
+	)
 	if err != nil {
-		logger.WithError(err).Error("Internal API unreachable")
+		slog.ErrorContext(ctx, "Internal API unreachable", slog.String(fields.ErrorMessage, err.Error()))
 		return response, err
 	}
 
-	logger = logger.WithField("status", response.StatusCode)
+	ctx = log.WithFields(ctx, slog.Int("status", response.StatusCode))
 
 	if response.StatusCode >= 400 {
-		logger.WithError(err).Error("Internal API error")
+		slog.ErrorContext(ctx, "Internal API error")
 		return response, err
 	}
 
 	if response.ContentLength >= 0 {
-		logger = logger.WithField("content_length_bytes", response.ContentLength)
+		ctx = log.WithFields(ctx, slog.Int64("content_length_bytes", response.ContentLength))
 	}
-
-	logger.Info("Finished HTTP request")
-
+	slog.InfoContext(ctx, "Finished HTTP request")
 	return response, nil
 }
 

cmd/gitlab-shell/main.go

@@ -3,14 +3,15 @@ package main
 
 import (
 	"fmt"
+	"log/slog"
 	"os"
 	"reflect"
 
 	grpccodes "google.golang.org/grpc/codes"
 	grpcstatus "google.golang.org/grpc/status"
 
+	"gitlab.com/gitlab-org/labkit/fields"
 	"gitlab.com/gitlab-org/labkit/fips"
-	"gitlab.com/gitlab-org/labkit/log"
 
 	shellCmd "gitlab.com/gitlab-org/gitlab-shell/v14/cmd/gitlab-shell/command"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command"
@@ -29,7 +30,7 @@ var (
 	BuildTime = "19700101.000000" // Set at build time in the Makefile
 )
 
-func main() {
+func run() int {
 	command.CheckForVersionFlag(os.Args, Version, BuildTime)
 
 	readWriter := &readwriter.ReadWriter{
@@ -41,47 +42,51 @@ func main() {
 	executable, err := executable.New(executable.GitlabShell)
 	if err != nil {
 		_, _ = fmt.Fprintln(readWriter.ErrOut, "Failed to determine executable, exiting")
-		os.Exit(1)
+		return 1
 	}
 
 	config, err := config.NewFromDirExternal(executable.RootDir)
 	if err != nil {
 		_, _ = fmt.Fprintln(readWriter.ErrOut, "Failed to read config, exiting:", err)
-		os.Exit(1)
+		return 1
 	}
 
-	logCloser := logger.Configure(config)
+	logCloser := logger.ConfigureLogger(config)
+	if logCloser != nil {
+		defer logCloser.Close() //nolint:errcheck
+	}
 
 	env := sshenv.NewFromEnv()
 	cmd, err := shellCmd.New(os.Args[1:], env, config, readWriter)
 	if err != nil {
 		// For now this could happen if `SSH_CONNECTION` is not set on
 		// the environment
 		_, _ = fmt.Fprintf(readWriter.ErrOut, "%v\n", err)
-		_ = logCloser.Close()
-		os.Exit(1)
+		return 1
 	}
 
 	ctx, finished := command.Setup(executable.Name, config)
 
 	config.GitalyClient.InitSidechannelRegistry(ctx)
 
 	cmdName := reflect.TypeOf(cmd).String()
-	ctxlog := log.ContextLogger(ctx)
-	ctxlog.WithFields(log.Fields{"env": env, "command": cmdName}).Info("gitlab-shell: main: executing command")
+	slog.InfoContext(ctx, "gitlab-shell: main: executing command", slog.Any("env", env), slog.String("command", cmdName))
 	fips.Check()
 
 	if _, err := cmd.Execute(ctx); err != nil {
-		ctxlog.WithError(err).Warn("gitlab-shell: main: command execution failed")
+		slog.WarnContext(ctx, "gitlab-shell: main: command execution failed", slog.String(fields.ErrorMessage, err.Error()))
 		if grpcstatus.Convert(err).Code() != grpccodes.Internal {
 			console.DisplayWarningMessage(err.Error(), readWriter.ErrOut)
 		}
 		finished()
-		_ = logCloser.Close()
-		os.Exit(1)
+		return 1
 	}
 
-	ctxlog.Info("gitlab-shell: main: command executed successfully")
+	slog.InfoContext(ctx, "gitlab-shell: main: command executed successfully")
 	finished()
-	_ = logCloser.Close()
+	return 0
+}
+
+func main() {
+	os.Exit(run())
 }

cmd/gitlab-sshd/acceptance_test.go

@@ -325,7 +325,7 @@ func startSSHD(t *testing.T, dir string) string {
 	t.Cleanup(func() { pw.Close() })
 
 	scanner := bufio.NewScanner(pr)
-	extractor := regexp.MustCompile(`tcp_address="([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)

config.yml.example

@@ -51,7 +51,7 @@ auth_file: "/home/git/.ssh/authorized_keys"
 log_level: INFO
 
 # Log format. 'json' by default, can be changed to 'text' if needed
-# log_format: json
+log_format: text
 
 # Audit usernames.
 # Set to true to see real usernames in the logs instead of key ids, which is easier to follow, but

go.mod

@@ -14,7 +14,6 @@ require (
 	github.com/otiai10/copy v1.14.1
 	github.com/pires/go-proxyproto v0.8.0
 	github.com/prometheus/client_golang v1.23.2
-	github.com/sirupsen/logrus v1.9.4
 	github.com/stretchr/testify v1.11.1
 	gitlab.com/gitlab-org/cells/topology-service v0.0.0-20260213143839-af4593cd7194
 	gitlab.com/gitlab-org/gitaly/v18 v18.9.0-rc4
@@ -89,6 +88,7 @@ require (
 	github.com/sebest/xff v0.0.0-20210106013422-671bd2870b3a // indirect
 	github.com/shirou/gopsutil/v3 v3.24.5 // indirect
 	github.com/shoenig/go-m1cpu v0.1.6 // indirect
+	github.com/sirupsen/logrus v1.9.4 // indirect
 	github.com/tinylib/msgp v1.3.0 // indirect
 	github.com/tklauser/go-sysconf v0.3.15 // indirect
 	github.com/tklauser/numcpus v0.10.0 // indirect

internal/command/authorizedkeys/authorized_keys.go

@@ -4,10 +4,9 @@ package authorizedkeys
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"strconv"
 
-	"gitlab.com/gitlab-org/labkit/log"
-
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
@@ -28,10 +27,10 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	// This can happen when the user in sshd_config doesn't match the user
 	// trying to login. When nothing is printed, the user will be denied access.
 	if c.Args.ExpectedUser != c.Args.ActualUser {
-		log.ContextLogger(ctx).WithFields(log.Fields{
-			"expected_user": c.Args.ExpectedUser,
-			"actual_user":   c.Args.ActualUser,
-		}).Warn("authorized_keys: user mismatch, denying access")
+		slog.WarnContext(ctx, "authorized_keys: user mismatch, denying access",
+			slog.String("expected_user", c.Args.ExpectedUser),
+			slog.String("actual_user", c.Args.ActualUser),
+		)
 		return ctx, nil
 	}
 

internal/command/gitauditevent/audit.go

@@ -3,35 +3,37 @@ package gitauditevent
 
 import (
 	"context"
+	"fmt"
+	"log/slog"
 
 	pb "gitlab.com/gitlab-org/gitaly/v18/proto/go/gitalypb"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/shared/accessverifier"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/gitlabnet/gitauditevent"
-	"gitlab.com/gitlab-org/labkit/log"
+	"gitlab.com/gitlab-org/labkit/v2/log"
 )
 
 // Audit is called conditionally during `git-receive-pack` and `git-upload-pack` to generate streaming audit events.
 // Errors are not propagated since this is more a logging process.
 func Audit(ctx context.Context, args *commandargs.Shell, c *config.Config, response *accessverifier.Response, packfileStats *pb.PackfileNegotiationStatistics) {
-	ctxlog := log.WithContextFields(ctx, log.Fields{
-		"gl_repository": response.Repo,
-		"command":       args.CommandType,
-		"username":      response.Username,
-	})
+	ctx = log.WithFields(ctx,
+		slog.String("gl_repository", response.Repo),
+		slog.Any("command", args.CommandType),
+		slog.String("username", response.Username),
+	)
 
-	ctxlog.Debug("sending git audit event")
+	slog.DebugContext(ctx, "sending git audit event")
 
 	gitAuditClient, errOnlyLog := gitauditevent.NewClient(c)
 	if errOnlyLog != nil {
-		ctxlog.Errorf("failed to create gitauditevent client: %v", errOnlyLog)
+		slog.ErrorContext(ctx, fmt.Sprintf("failed to create gitauditevent client: %v", errOnlyLog))
 		return
 	}
 
 	errOnlyLog = gitAuditClient.Audit(ctx, response.Username, args, response.Repo, packfileStats)
 	if errOnlyLog != nil {
-		ctxlog.Errorf("failed to audit git event: %v", errOnlyLog)
+		slog.ErrorContext(ctx, fmt.Sprintf("failed to audit git event: %v", errOnlyLog))
 		return
 	}
 }

internal/command/githttp/pull.go

@@ -7,14 +7,15 @@ package githttp
 import (
 	"context"
 	"io"
+	"log/slog"
 
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/gitlabnet/accessverifier"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/gitlabnet/git"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/pktline"
-	"gitlab.com/gitlab-org/labkit/log"
+	"gitlab.com/gitlab-org/labkit/fields"
 )
 
 const pullService = "git-upload-pack"
@@ -63,7 +64,7 @@ func (c *PullCommand) Execute(ctx context.Context) error {
 }
 
 func (c *PullCommand) requestSSHUploadPack(ctx context.Context, client *git.Client) error {
-	log.ContextLogger(ctx).Info("Using Git over SSH upload pack")
+	slog.InfoContext(ctx, "Using Git over SSH upload pack")
 
 	return executeSSHRequest(ctx, client.SSHUploadPack, c.ReadWriter)
 }
@@ -91,7 +92,7 @@ func (c *PullCommand) readFromStdin(pw *io.PipeWriter) {
 
 		_, err := pw.Write(line)
 		if err != nil {
-			log.WithError(err).Error("failed to write line")
+			slog.Error("failed to write line", slog.String(fields.ErrorMessage, err.Error()))
 		}
 
 		if pktline.IsDone(line) {
@@ -101,6 +102,6 @@ func (c *PullCommand) readFromStdin(pw *io.PipeWriter) {
 
 	err := pw.Close()
 	if err != nil {
-		log.WithError(err).Error("failed to close writer")
+		slog.Error("failed to close writer", slog.String(fields.ErrorMessage, err.Error()))
 	}
 }