gitaly-bench: Capture Gitaly logs in coordinatorwc/gitaly-bench-logs

To bring `gitaly-bench` closer to feature parity with the existing
Ansible benchmarking script, start capturing Gitaly's logs and write
them to `<OUT_DIR>/gitaly.log`.

We use `journalctl` with the poorly documented `_PID` option to do this.
This requires us to capture the logs _before_ stopping Gitaly.

2 files changed, 137 insertions, 0 deletions

diff --git a/internal/cli/bench/coordinator.go b/internal/cli/bench/coordinator.go
index e6b75b8de..5912d7287 100644
--- a/internal/cli/bench/coordinator.go
+++ b/internal/cli/bench/coordinator.go
@@ -1,11 +1,13 @@
 package bench
 
 import (
+	"bytes"
 	"errors"
 	"fmt"
 	"net"
 	"os"
 	"os/exec"
+	"path/filepath"
 	"time"
 
 	"github.com/urfave/cli/v2"
@@ -17,6 +19,7 @@ type Coordinator struct {
 	Listener net.Listener
 	StartCmd []string
 	StopCmd  []string
+	LogCmd   []string
 	rw       *jsonRW
 }
 
@@ -37,6 +40,7 @@ func newCoordinator(listener net.Listener) *Coordinator {
 		Listener: listener,
 		StartCmd: []string{"/usr/bin/systemctl", "start", "gitaly"},
 		StopCmd:  []string{"/usr/bin/systemctl", "stop", "gitaly"},
+		LogCmd:   []string{"/bin/bash", "-c", "journalctl --output=cat _PID=$(pidof -s gitaly)"},
 		rw:       nil,
 	}
 }
@@ -135,6 +139,12 @@ func (c *Coordinator) finishBench() error {
 		return errors.New("received command other than 'stop' while Gitaly was running")
 	}
 
+	// We need to capture logs prior to stopping Gitaly for `pidof`.
+	if err := c.captureLogs(cmd.OutDir); err != nil {
+		_ = c.stopGitaly()
+		return err
+	}
+
 	return c.stopGitaly()
 }
 
@@ -179,3 +189,23 @@ func (c *Coordinator) stopGitaly() error {
 	}
 	return nil
 }
+
+func (c *Coordinator) captureLogs(outDir string) error {
+	if err := os.MkdirAll(outDir, perm.PrivateDir); err != nil {
+		return fmt.Errorf("create output directory %q: %w", outDir, err)
+	}
+
+	var stdout bytes.Buffer
+	cmd := exec.Command(c.LogCmd[0], c.LogCmd[1:]...)
+	cmd.Stdout = &stdout
+
+	if err := cmd.Run(); err != nil {
+		return fmt.Errorf("capture gitaly logs: %w", err)
+	}
+
+	if err := os.WriteFile(filepath.Join(outDir, "gitaly.log"), stdout.Bytes(), perm.PrivateFile); err != nil {
+		return fmt.Errorf("writing log file: %w", err)
+	}
+
+	return nil
+}
diff --git a/internal/cli/bench/coordinator_test.go b/internal/cli/bench/coordinator_test.go
index 39e6f5dd2..c65e35943 100644
--- a/internal/cli/bench/coordinator_test.go
+++ b/internal/cli/bench/coordinator_test.go
@@ -2,6 +2,8 @@ package bench
 
 import (
 	"net"
+	"os"
+	"path/filepath"
 	"runtime"
 	"testing"
 
@@ -174,6 +176,7 @@ func TestBenchCoordinator(t *testing.T) {
 				Listener: l,
 				StartCmd: tc.startCmd,
 				StopCmd:  tc.stopCmd,
+				LogCmd:   []string{"/bin/bash", "-c", "echo 'hi'"},
 			}
 
 			respCh := make(chan ([]CoordResp), 1)
@@ -191,6 +194,110 @@ func TestBenchCoordinator(t *testing.T) {
 	}
 }
 
+func TestBenchCoordinator_writeLogs(t *testing.T) {
+	t.Parallel()
+
+	for _, tc := range []struct {
+		name          string
+		logCmd        []string
+		incomingCmds  func(string) []CoordCmd
+		expectedLog   string
+		expectedResps []CoordResp
+		expectedErr   string
+	}{
+		{
+			name:   "log cmd fails",
+			logCmd: []string{"/bin/bash", "-c", "exit 1"},
+			incomingCmds: func(outDir string) []CoordCmd {
+				return []CoordCmd{
+					{
+						Action: startGitalyAction,
+						OutDir: outDir,
+					},
+					{
+						Action: stopGitalyAction,
+						OutDir: outDir,
+					},
+				}
+			},
+			expectedResps: []CoordResp{
+				{
+					Error: "",
+				},
+				{
+					Error: "finish benchmarking: capture gitaly logs: exit status 1",
+				},
+			},
+			expectedErr: "coordinator: session: finish benchmarking: capture gitaly logs: exit status 1",
+		},
+		{
+			name:   "ok",
+			logCmd: []string{"/bin/bash", "-c", "echo 'hello, world'"},
+			incomingCmds: func(outDir string) []CoordCmd {
+				return []CoordCmd{
+					{
+						Action: startGitalyAction,
+						OutDir: outDir,
+					},
+					{
+						Action: stopGitalyAction,
+						OutDir: outDir,
+					},
+					{
+						Action: exitCoordAction,
+					},
+				}
+			},
+			expectedResps: []CoordResp{
+				{
+					Error: "",
+				},
+				{
+					Error: "",
+				},
+				{
+					Error: "",
+				},
+			},
+			expectedLog: "hello, world\n",
+		},
+	} {
+		tc := tc
+
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+
+			l, addr := testhelper.GetLocalhostListener(t)
+			defer l.Close()
+
+			coord := &Coordinator{
+				Listener: l,
+				StartCmd: cmdOK(true),
+				StopCmd:  cmdOK(true),
+				LogCmd:   tc.logCmd,
+			}
+
+			outDir := testhelper.TempDir(t)
+
+			respCh := make(chan ([]CoordResp), 1)
+			go sendCmds(t, addr, tc.incomingCmds(outDir), respCh)
+
+			if tc.expectedErr != "" {
+				require.ErrorContains(t, coord.run(), tc.expectedErr)
+			} else {
+				require.NoError(t, coord.run())
+
+				logs, err := os.ReadFile(filepath.Join(outDir, "gitaly.log"))
+				require.NoError(t, err)
+
+				require.Equal(t, tc.expectedLog, string(logs))
+			}
+
+			require.Equal(t, tc.expectedResps, <-respCh)
+		})
+	}
+}
+
 func sendCmds(t *testing.T, addr string, cmds []CoordCmd, outCh chan ([]CoordResp)) {
 	t.Helper()