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

4 files changed, 55 insertions, 5 deletions

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..4db332830 100644
--- a/internal/cgroups/v1_linux_test.go
+++ b/internal/cgroups/v1_linux_test.go
@@ -11,7 +11,10 @@ import (
 	"strings"
 	"testing"
 
+	"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,14 +130,18 @@ 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, logrus.NewEntry(logger))
+
 	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()
+	processCgroupPath := v1Manager1.currentProcessCgroup()
 
 	expected := bytes.NewBufferString(fmt.Sprintf(`# HELP gitaly_cgroup_cpu_usage CPU Usage of Cgroup
 # TYPE gitaly_cgroup_cpu_usage gauge
@@ -147,13 +154,21 @@ gitaly_cgroup_memory_failed_total{path="%s"} 2
 # TYPE gitaly_cgroup_procs_total gauge
 gitaly_cgroup_procs_total{path="%s",subsystem="memory"} 1
 gitaly_cgroup_procs_total{path="%s",subsystem="cpu"} 1
-`, cgroupPath, cgroupPath, cgroupPath, cgroupPath, cgroupPath))
+`, processCgroupPath, processCgroupPath, processCgroupPath, processCgroupPath, processCgroupPath))
 	assert.NoError(t, testutil.CollectAndCompare(
 		v1Manager1,
 		expected,
 		"gitaly_cgroup_memory_failed_total",
 		"gitaly_cgroup_cpu_usage",
 		"gitaly_cgroup_procs_total"))
+
+	logEntry := hook.LastEntry()
+	assert.Contains(
+		t,
+		logEntry.Data["command.cgroup_path"],
+		processCgroupPath,
+		"log field includes a cgroup path that is a subdirectory of the current process' cgroup path",
+	)
 }
 
 func readCgroupFile(t *testing.T, path string) []byte {
diff --git a/internal/command/command.go b/internal/command/command.go
index a58b92181..ccf13d291 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,11 @@ func (c *Command) Wait() error {
 	return c.waitError
 }
 
+// SetCgroupPath sets the cgroup path for logging
+func (c *Command) SetCgroupPath(path string) {
+	c.cgroupPath = path
+}
+
 type contextWithoutDonePanic string
 
 // New creates a Command from an exec.Cmd. On success, the Command
@@ -337,7 +344,7 @@ func (c *Command) logProcessComplete() {
 	userTime := cmd.ProcessState.UserTime()
 	realTime := time.Since(c.startTime)
 
-	entry := ctxlogrus.Extract(ctx).WithFields(logrus.Fields{
+	fields := logrus.Fields{
 		"pid":                    cmd.ProcessState.Pid(),
 		"path":                   cmd.Path,
 		"args":                   cmd.Args,
@@ -346,7 +353,13 @@ 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,
-	})
+	}
+
+	if c.cgroupPath != "" {
+		fields["command.cgroup_path"] = c.cgroupPath
+	}
+
+	entry := ctxlogrus.Extract(ctx).WithFields(fields)
 
 	rusage, ok := cmd.ProcessState.SysUsage().(*syscall.Rusage)
 	if ok {
diff --git a/internal/command/command_test.go b/internal/command/command_test.go
index ddc0a933a..3ff5cbac8 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), logrus.NewEntry(logger))
+
+	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"])
+}