From c9cc9c438e0fa9334c057fce1b91debb25ed1b56 Mon Sep 17 00:00:00 2001
From: John Cai <jcai@gitlab.com>
Date: Fri, 18 Mar 2022 17:09:09 -0400
Subject: command: Log cgroup path

We'd like to be able to tell if a command was run in a cgroup based on
the log entry. This change adds a field in the Command struct so
whenever the Cmd finishes, a cgroup field gets logged.

Changelog: added
---
 internal/cgroups/v1_linux.go      |  2 ++
 internal/cgroups/v1_linux_test.go | 13 ++++++++++++-
 internal/command/command.go       |  7 +++++++
 internal/command/command_test.go  | 20 ++++++++++++++++++++
 4 files changed, 41 insertions(+), 1 deletion(-)

diff --git a/internal/cgroups/v1_linux.go b/internal/cgroups/v1_linux.go
index 66a4de23a..e524d7609 100644
--- a/internal/cgroups/v1_linux.go
+++ b/internal/cgroups/v1_linux.go
@@ -100,6 +100,8 @@ func (cg *CGroupV1Manager) AddCommand(cmd *command.Command) error {
 		return fmt.Errorf("failed adding process to cgroup: %w", err)
 	}
 
+	cmd.SetCgroupPath(cgroupPath)
+
 	return nil
 }
 
diff --git a/internal/cgroups/v1_linux_test.go b/internal/cgroups/v1_linux_test.go
index 34defbf8e..81d1c28e4 100644
--- a/internal/cgroups/v1_linux_test.go
+++ b/internal/cgroups/v1_linux_test.go
@@ -10,8 +10,12 @@ import (
 	"strconv"
 	"strings"
 	"testing"
+	"time"
 
+	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
 	"github.com/prometheus/client_golang/prometheus/testutil"
+	"github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/command"
@@ -127,12 +131,16 @@ func TestMetrics(t *testing.T) {
 	require.NoError(t, v1Manager1.Setup())
 	ctx := testhelper.Context(t)
 
+	logger, hook := test.NewNullLogger()
+	logger.SetLevel(logrus.DebugLevel)
+	ctx = ctxlogrus.ToContext(ctx, logger.WithTime(time.Now()))
+
 	cmd1 := exec.Command("ls", "-hal", ".")
 	cmd2, err := command.New(ctx, cmd1, nil, nil, nil)
 	require.NoError(t, err)
-	require.NoError(t, cmd2.Wait())
 
 	require.NoError(t, v1Manager1.AddCommand(cmd2))
+	require.NoError(t, cmd2.Wait())
 
 	cgroupPath := v1Manager1.currentProcessCgroup()
 
@@ -154,6 +162,9 @@ gitaly_cgroup_procs_total{path="%s",subsystem="cpu"} 1
 		"gitaly_cgroup_memory_failed_total",
 		"gitaly_cgroup_cpu_usage",
 		"gitaly_cgroup_procs_total"))
+
+	logEntry := hook.LastEntry()
+	assert.Contains(t, logEntry.Data["command.cgroup_path"], cgroupPath)
 }
 
 func readCgroupFile(t *testing.T, path string) []byte {
diff --git a/internal/command/command.go b/internal/command/command.go
index a58b92181..0a427a8eb 100644
--- a/internal/command/command.go
+++ b/internal/command/command.go
@@ -101,6 +101,8 @@ type Command struct {
 	waitOnce  sync.Once
 
 	span opentracing.Span
+
+	cgroupPath string
 }
 
 type stdinSentinel struct{}
@@ -144,6 +146,10 @@ func (c *Command) Wait() error {
 	return c.waitError
 }
 
+func (c *Command) SetCgroupPath(path string) {
+	c.cgroupPath = path
+}
+
 type contextWithoutDonePanic string
 
 // New creates a Command from an exec.Cmd. On success, the Command
@@ -346,6 +352,7 @@ func (c *Command) logProcessComplete() {
 		"command.user_time_ms":   userTime.Seconds() * 1000,
 		"command.cpu_time_ms":    (systemTime.Seconds() + userTime.Seconds()) * 1000,
 		"command.real_time_ms":   realTime.Seconds() * 1000,
+		"command.cgroup_path":    c.cgroupPath,
 	})
 
 	rusage, ok := cmd.ProcessState.SysUsage().(*syscall.Rusage)
diff --git a/internal/command/command_test.go b/internal/command/command_test.go
index ddc0a933a..130279d3c 100644
--- a/internal/command/command_test.go
+++ b/internal/command/command_test.go
@@ -14,6 +14,7 @@ import (
 
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
 	"github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/testhelper"
@@ -364,3 +365,22 @@ func extractLastMessage(logMessage string) string {
 
 	return subMatches[1]
 }
+
+func TestCommand_logMessage(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	logger.SetLevel(logrus.DebugLevel)
+
+	ctx := ctxlogrus.ToContext(testhelper.Context(t), logger.WithTime(time.Now()))
+
+	cmd, err := New(ctx, exec.Command("echo", "hello world"), nil, nil, nil)
+	require.NoError(t, err)
+	cgroupPath := "/sys/fs/cgroup/1"
+	cmd.SetCgroupPath(cgroupPath)
+
+	require.NoError(t, cmd.Wait())
+	logEntry := hook.LastEntry()
+	assert.Equal(t, cmd.Pid(), logEntry.Data["pid"])
+	assert.Equal(t, []string{"echo", "hello world"}, logEntry.Data["args"])
+	assert.Equal(t, 0, logEntry.Data["command.exitCode"])
+	assert.Equal(t, cgroupPath, logEntry.Data["command.cgroup_path"])
+}
-- 
cgit v1.2.3