From a194caf3087595d8655e55f222a16c50b84262c6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tadas=20Ustinavi=C4=8Dius?= Date: Tue, 22 Sep 2026 16:57:21 +0300 Subject: [PATCH] feat(commandrunner): log every command the library executes Everything this library does on a host is a vendor CLI invocation behind a commandrunner.CommandRunner, so that interface is the one place where all executed commands can be observed. Logging goes there as a decorator rather than into each adapter: commandrunner.Logging wraps any runner, records the invocation on an slog.Logger, and returns the wrapped output and error unchanged. It is opt-in -- a consumer injects the decorated runner where it would have injected the concrete one -- and it covers the runners and adapters added later for free, since they all sit behind the same port. One record per invocation carries the binary, the arguments, the duration and, on failure, the error. Successful commands are recorded at slog.LevelInfo, which WithLevel lowers, and failures at slog.LevelError. ErrNoLogicalDrives reports an empty inventory rather than a failure, so it stays at the success level instead of logging a controller with no volume as an error. The output itself is never logged, only its size: vendor payloads carry drive serials and other identifying data. The arguments are the ones the adapter asked for, so a runner that appends flags of its own does so after the decorator has seen them and the storcli2/perccli2 JSON output flag is absent from the record; both are documented where a reader would look for them. Each runner now reports the binary it invokes through CommandPath(), so a record names the tool that ran. The decorator forwards its wrapped runner's path, which also keeps it transparent to another decorator, and falls back to the runner's type for a runner without one, such as a test mock. The legacy megaraid.Runner parses its own output instead of returning bytes, so it cannot share the decorator. megaraid.LoggingRunner decorates it the same way and emits through commandrunner.LogCommand, keeping one log shape across the library; it records no payload size, since that runner exposes none. Co-Authored-By: Claude Opus 5 (1M context) --- DESIGN.md | 34 +++ README.md | 39 +++ pkg/implementation/commandrunner/logging.go | 149 +++++++++++ .../commandrunner/logging_test.go | 239 ++++++++++++++++++ pkg/implementation/commandrunner/lsblk.go | 5 + pkg/implementation/commandrunner/mdadm.go | 5 + pkg/implementation/commandrunner/perccli2.go | 5 + pkg/implementation/commandrunner/smartctl.go | 5 + pkg/implementation/commandrunner/ssacli.go | 5 + pkg/implementation/commandrunner/storcli2.go | 5 + pkg/implementation/commandrunner/udevadm.go | 5 + .../raidcontroller/megaraid/logging.go | 94 +++++++ .../raidcontroller/megaraid/logging_test.go | 108 ++++++++ .../raidcontroller/megaraid/runner.go | 6 + 14 files changed, 704 insertions(+) create mode 100644 pkg/implementation/commandrunner/logging.go create mode 100644 pkg/implementation/commandrunner/logging_test.go create mode 100644 pkg/implementation/raidcontroller/megaraid/logging.go create mode 100644 pkg/implementation/raidcontroller/megaraid/logging_test.go diff --git a/DESIGN.md b/DESIGN.md index 0a30937..427be94 100644 --- a/DESIGN.md +++ b/DESIGN.md @@ -252,3 +252,37 @@ This adapter has the following limitations compared to hardware RAID: The `core.RAIDController` wraps any adapter and adds input validation before delegating to the underlying implementation. This is the recommended entry point for consumers of the library. + +## Command Logging + +Every host mutation and every inventory read this library performs is a vendor +CLI invocation behind a `commandrunner.CommandRunner`, which makes that +interface the one place where all executed commands can be observed. + +Logging is therefore a **decorator** on that port rather than a concern spread +across the adapters: `commandrunner.Logging` wraps any `CommandRunner`, records +the invocation on an `slog.Logger` (`log/slog`, no new dependency), and returns +the wrapped runner's output and error unchanged. It is opt-in -- a consumer +that wants a command log injects the decorated runner where it would have +injected the concrete one -- and it covers new runners and new adapters for +free, since they all sit behind the same port. + +Design notes: + +- One record per invocation, at `slog.LevelInfo` by default + (`commandrunner.WithLevel` lowers it) and at `slog.LevelError` on failure. + `commandrunner.ErrNoLogicalDrives` reports an empty inventory rather than a + failure, so it stays at the success level. +- The record carries the binary, the arguments, the duration and, on failure, + the error. The **output is never logged**: vendor payloads carry drive + serials and other identifying data, so only its size is recorded. +- The arguments are the ones the adapter asked for. A runner that appends flags + of its own (the storcli2/perccli2 JSON output flag) does so after the + decorator has seen them, so they are absent from the record. +- Runners report the binary they invoke through `CommandPath()`, so a record + names the tool that ran; the decorator forwards its wrapped runner's path, + and falls back to the runner's type for a runner without one (a test mock). +- The legacy `megaraid.Runner` returns parsed output instead of bytes, so it + cannot share the decorator. `megaraid.LoggingRunner` decorates it in the same + way and emits through the same `commandrunner.LogCommand`, keeping one log + shape across the library. diff --git a/README.md b/README.md index 9eb618b..0038e13 100644 --- a/README.md +++ b/README.md @@ -30,6 +30,8 @@ setup. identification blinking. - **Extensible** -- New controllers can be added by implementing the adapter interfaces. +- **Command logging** -- Every vendor CLI command the library executes can be + logged to an `slog.Logger` by wrapping the command runner. ## Installation @@ -85,6 +87,43 @@ func main() { > the storcli2 write path lands; until then the storcli2 components are wired > individually. +### Command logging + +Everything this library does on a host goes through a +`commandrunner.CommandRunner`, so wrapping the runner in +`commandrunner.NewLogging` logs every command executed, whichever adapter +issued it: + +```go +logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)) + +runner := commandrunner.NewLogging(commandrunner.NewStorCLI2(nil), logger) + +drives, err := physicaldrivegetter.NewStorCLI2(runner).PhysicalDrives(metadata) +``` + +Each executed command produces one record with the binary invoked, its +arguments, how long it took and the outcome: + +```json +{"time":"2026-09-22T10:12:31Z","level":"INFO","msg":"RAID command executed", + "command":"/opt/MegaRAID/storcli2/storcli2","args":["/c0","show","all"], + "duration":41000000,"output_bytes":9317} +``` + +Details worth knowing: + +- Successful commands are logged at `slog.LevelInfo`; pass + `commandrunner.WithLevel(slog.LevelDebug)` to lower that. Failures are always + logged at `slog.LevelError`, with the error attached. +- The command **output is never logged** -- vendor payloads carry drive serials + and other identifying data -- only its size. +- The arguments logged are the ones the adapter asked for: flags a runner adds + itself (storcli2 and perccli2 append the JSON output flag) are not shown. +- The decorator is transparent, so it can wrap any runner, including the ones + injected into a full `raidcontroller` composition. The legacy + `megaraid.Runner` has its own equivalent, `megaraid.NewLoggingRunner`. + ## Project Structure ``` diff --git a/pkg/implementation/commandrunner/logging.go b/pkg/implementation/commandrunner/logging.go new file mode 100644 index 0000000..e51f46e --- /dev/null +++ b/pkg/implementation/commandrunner/logging.go @@ -0,0 +1,149 @@ +package commandrunner + +import ( + "context" + "fmt" + "log/slog" + "time" + + "github.com/pkg/errors" +) + +// ExecutedCommand describes a single vendor CLI invocation, as handed to +// LogCommand. +type ExecutedCommand struct { + // Path is the binary that was invoked. + Path string + + // Args are the arguments the caller asked for. + Args []string + + // OutputBytes is the size of the command output. The output itself is + // never logged: vendor payloads carry drive serials and other identifying + // data. A runner that exposes no payload size leaves this zero, and the + // attribute is then omitted. + OutputBytes int + + // Duration is how long the invocation took. + Duration time.Duration + + // Err is the error the invocation returned, if any. + Err error +} + +// LogCommand writes one record describing an executed command: a successful +// invocation at level, a failed one at slog.LevelError. ErrNoLogicalDrives +// reports an empty inventory rather than a failure (see the SSACLI runner), so +// it is recorded at level too, with its error attached. +// +// It is exported so that a command runner outside this package -- the legacy +// megaraid.Runner, whose Run returns parsed output instead of bytes -- logs in +// the same shape. +func LogCommand(logger *slog.Logger, level slog.Level, cmd ExecutedCommand) { + attrs := []slog.Attr{ + slog.String("command", cmd.Path), + slog.Any("args", cmd.Args), + slog.Duration("duration", cmd.Duration), + } + + if cmd.OutputBytes > 0 { + attrs = append(attrs, slog.Int("output_bytes", cmd.OutputBytes)) + } + + recordLevel, message := level, "RAID command executed" + + if cmd.Err != nil { + attrs = append(attrs, slog.String("error", cmd.Err.Error())) + + if !errors.Is(cmd.Err, ErrNoLogicalDrives) { + recordLevel, message = slog.LevelError, "RAID command failed" + } + } + + logger.LogAttrs(context.Background(), recordLevel, message, attrs...) +} + +// Logging decorates a CommandRunner so that every command it executes is +// recorded on an slog.Logger: the binary invoked, its arguments, how long it +// took and the outcome. The decorator is transparent -- output and error are +// returned unchanged -- so it wraps any runner without altering adapter +// behaviour. +// +// The arguments recorded are the ones the adapter asked for. A runner that adds +// flags of its own does so after this decorator has seen the arguments, so +// those flags are absent from the record: a storcli2 or perccli2 command also +// carries the JSON output flag on the wire. +type Logging struct { + runner CommandRunner + logger *slog.Logger + level slog.Level +} + +// LoggingOption configures a Logging runner. +type LoggingOption func(*Logging) + +// WithLevel sets the level successful commands are recorded at. It defaults to +// slog.LevelInfo; failures are always recorded at slog.LevelError. +func WithLevel(level slog.Level) LoggingOption { + return func(l *Logging) { + l.level = level + } +} + +// commandPather is implemented by the runners of this package to report the +// binary they invoke, so that a log record names the tool that ran. +type commandPather interface { + CommandPath() string +} + +var _ CommandRunner = &Logging{} + +// NewLogging wraps runner so that every command it runs is logged to logger. A +// nil logger falls back to slog.Default(). +func NewLogging(runner CommandRunner, logger *slog.Logger, opts ...LoggingOption) *Logging { + target := logger + if target == nil { + target = slog.Default() + } + + logging := &Logging{ + runner: runner, + logger: target, + level: slog.LevelInfo, + } + + for _, opt := range opts { + opt(logging) + } + + return logging +} + +// Run logs the command, then returns the wrapped runner's output and error +// unchanged. +func (l *Logging) Run(args []string) ([]byte, error) { + start := time.Now() + + output, err := l.runner.Run(args) + + LogCommand(l.logger, l.level, ExecutedCommand{ + Path: l.CommandPath(), + Args: args, + OutputBytes: len(output), + Duration: time.Since(start), + Err: err, + }) + + return output, err //nolint:wrapcheck // Transparent decorator: error returned as-is. +} + +// CommandPath reports the binary the wrapped runner invokes, which also keeps +// the decorator itself transparent to another decorator wrapping it. A runner +// that does not report its binary is named by its type. +func (l *Logging) CommandPath() string { + if pather, ok := l.runner.(commandPather); ok { + return pather.CommandPath() + } + + return fmt.Sprintf("%T", l.runner) +} diff --git a/pkg/implementation/commandrunner/logging_test.go b/pkg/implementation/commandrunner/logging_test.go new file mode 100644 index 0000000..c1acb6a --- /dev/null +++ b/pkg/implementation/commandrunner/logging_test.go @@ -0,0 +1,239 @@ +package commandrunner_test + +import ( + "bytes" + "encoding/json" + "log/slog" + "testing" + + "github.com/pkg/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/mock" + "github.com/stretchr/testify/require" + + "github.com/scality/raidmgmt/pkg/implementation/commandrunner" +) + +// mockCommandRunner is a CommandRunner that also reports its binary path, like +// every concrete runner of the package. +type mockCommandRunner struct { + mock.Mock +} + +func (m *mockCommandRunner) Run(args []string) ([]byte, error) { + arguments := m.Called(args) + + output, _ := arguments.Get(0).([]byte) + + return output, arguments.Error(1) +} + +func (m *mockCommandRunner) CommandPath() string { + return "/opt/vendor/cli" +} + +// pathlessRunner is a CommandRunner that does not report a binary path. +type pathlessRunner struct{} + +func (pathlessRunner) Run(_ []string) ([]byte, error) { + return []byte("ok"), nil +} + +// newCapturingLogger returns a logger writing JSON records to buf, at a level +// low enough to capture every record the decorator can emit. +func newCapturingLogger(buf *bytes.Buffer) *slog.Logger { + return slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug})) +} + +// records decodes the captured JSON log records. +func records(t *testing.T, buf *bytes.Buffer) []map[string]any { + t.Helper() + + var decoded []map[string]any + + for _, line := range bytes.Split(bytes.TrimSpace(buf.Bytes()), []byte("\n")) { + if len(line) == 0 { + continue + } + + var record map[string]any + + require.NoError(t, json.Unmarshal(line, &record)) + + decoded = append(decoded, record) + } + + return decoded +} + +func TestLoggingLogsExecutedCommand(t *testing.T) { + var buf bytes.Buffer + + runner := &mockCommandRunner{} + runner.On("Run", []string{"/c0", "show", "all"}).Return([]byte(`{"Controllers":[]}`), nil) + + output, err := commandrunner.NewLogging(runner, newCapturingLogger(&buf)). + Run([]string{"/c0", "show", "all"}) + require.NoError(t, err) + assert.Equal(t, `{"Controllers":[]}`, string(output)) + + logged := records(t, &buf) + require.Len(t, logged, 1) + + assert.Equal(t, "INFO", logged[0]["level"]) + assert.Equal(t, "RAID command executed", logged[0]["msg"]) + assert.Equal(t, "/opt/vendor/cli", logged[0]["command"]) + assert.Equal(t, []any{"/c0", "show", "all"}, logged[0]["args"]) + assert.EqualValues(t, len(`{"Controllers":[]}`), logged[0]["output_bytes"]) + assert.Contains(t, logged[0], "duration") + assert.NotContains(t, logged[0], "error") + + runner.AssertExpectations(t) +} + +func TestLoggingLogsFailureAtErrorLevel(t *testing.T) { + var buf bytes.Buffer + + wrapped := errors.New("exit status 1") + + runner := &mockCommandRunner{} + runner.On("Run", []string{"/c0", "show"}).Return(nil, wrapped) + + output, err := commandrunner.NewLogging(runner, newCapturingLogger(&buf)). + Run([]string{"/c0", "show"}) + require.ErrorIs(t, err, wrapped) + assert.Nil(t, output) + + logged := records(t, &buf) + require.Len(t, logged, 1) + + assert.Equal(t, "ERROR", logged[0]["level"]) + assert.Equal(t, "RAID command failed", logged[0]["msg"]) + assert.Equal(t, "exit status 1", logged[0]["error"]) + // No payload was returned, so no size is recorded. + assert.NotContains(t, logged[0], "output_bytes") +} + +// An ssacli controller without any logical drive is an empty inventory, not a +// failure, so it must not be reported at error level. +func TestLoggingLogsNoLogicalDrivesAtSuccessLevel(t *testing.T) { + var buf bytes.Buffer + + runner := &mockCommandRunner{} + runner.On("Run", []string{"ctrl", "slot=0", "ld", "all", "show"}). + Return([]byte("Error: ..."), commandrunner.ErrNoLogicalDrives) + + _, err := commandrunner.NewLogging(runner, newCapturingLogger(&buf)). + Run([]string{"ctrl", "slot=0", "ld", "all", "show"}) + require.ErrorIs(t, err, commandrunner.ErrNoLogicalDrives) + + logged := records(t, &buf) + require.Len(t, logged, 1) + + assert.Equal(t, "INFO", logged[0]["level"]) + assert.Equal(t, "RAID command executed", logged[0]["msg"]) + assert.Equal(t, commandrunner.ErrNoLogicalDrives.Error(), logged[0]["error"]) +} + +func TestLoggingWithLevel(t *testing.T) { + var buf bytes.Buffer + + runner := &mockCommandRunner{} + runner.On("Run", []string{"show"}).Return([]byte("out"), nil) + + logging := commandrunner.NewLogging( + runner, + newCapturingLogger(&buf), + commandrunner.WithLevel(slog.LevelDebug), + ) + + _, err := logging.Run([]string{"show"}) + require.NoError(t, err) + + logged := records(t, &buf) + require.Len(t, logged, 1) + assert.Equal(t, "DEBUG", logged[0]["level"]) +} + +// A logger filtering out the success level drops the record: the decorator +// still returns the command's result untouched. +func TestLoggingHonoursHandlerLevel(t *testing.T) { + var buf bytes.Buffer + + runner := &mockCommandRunner{} + runner.On("Run", []string{"show"}).Return([]byte("out"), nil) + + logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelWarn})) + + output, err := commandrunner.NewLogging(runner, logger).Run([]string{"show"}) + require.NoError(t, err) + assert.Equal(t, "out", string(output)) + assert.Empty(t, buf.String()) +} + +func TestLoggingNamesRunnerWithoutCommandPathByType(t *testing.T) { + var buf bytes.Buffer + + logging := commandrunner.NewLogging(pathlessRunner{}, newCapturingLogger(&buf)) + assert.Equal(t, "commandrunner_test.pathlessRunner", logging.CommandPath()) + + _, err := logging.Run([]string{"show"}) + require.NoError(t, err) + + logged := records(t, &buf) + require.Len(t, logged, 1) + assert.Equal(t, "commandrunner_test.pathlessRunner", logged[0]["command"]) +} + +// A nil logger must not panic: it falls back to slog.Default(). +func TestLoggingWithNilLoggerUsesDefault(t *testing.T) { + var buf bytes.Buffer + + original := slog.Default() + defer slog.SetDefault(original) + + slog.SetDefault(newCapturingLogger(&buf)) + + runner := &mockCommandRunner{} + runner.On("Run", []string{"show"}).Return([]byte("out"), nil) + + _, err := commandrunner.NewLogging(runner, nil).Run([]string{"show"}) + require.NoError(t, err) + + logged := records(t, &buf) + require.Len(t, logged, 1) + assert.Equal(t, "/opt/vendor/cli", logged[0]["command"]) +} + +// Every concrete runner reports the binary it invokes, so that its commands are +// logged under the tool that ran them. +func TestRunnersReportCommandPath(t *testing.T) { + custom := "/opt/custom/cli" + + testCases := []struct { + name string + runner commandrunner.CommandRunner + expected string + }{ + {"storcli2", commandrunner.NewStorCLI2(nil), commandrunner.StorCLI2Path}, + {"storcli2-custom", commandrunner.NewStorCLI2(&custom), custom}, + {"perccli2", commandrunner.NewPercCLI2(nil), commandrunner.PercCLI2Path}, + {"ssacli", commandrunner.NewSSACLI(nil), commandrunner.SSACLIPath}, + {"mdadm", commandrunner.NewMDADM(nil), commandrunner.MDADMBinaryPath}, + {"lsblk", commandrunner.NewLSBLK(nil), commandrunner.LSBLKBinaryPath}, + {"smartctl", commandrunner.NewSmartCTL(nil), commandrunner.SmartCTLBinaryPath}, + {"udevadm", commandrunner.NewUDevADM(nil), commandrunner.UDevADMBinaryPath}, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + pather, ok := tc.runner.(interface{ CommandPath() string }) + require.True(t, ok, "runner does not report its command path") + assert.Equal(t, tc.expected, pather.CommandPath()) + + // The decorator reports the wrapped runner's binary as its own, so + // that wrapping stays transparent. + assert.Equal(t, tc.expected, commandrunner.NewLogging(tc.runner, nil).CommandPath()) + }) + } +} diff --git a/pkg/implementation/commandrunner/lsblk.go b/pkg/implementation/commandrunner/lsblk.go index c0b6623..b64fd88 100644 --- a/pkg/implementation/commandrunner/lsblk.go +++ b/pkg/implementation/commandrunner/lsblk.go @@ -29,6 +29,11 @@ func NewLSBLK(path *string) *LSBLK { } } +// CommandPath returns the path of the lsblk binary this runner invokes. +func (l *LSBLK) CommandPath() string { + return l.cliPath +} + func (l *LSBLK) Run(args []string) ([]byte, error) { cmd := LSBLKExecCommand(l.cliPath, args...) diff --git a/pkg/implementation/commandrunner/mdadm.go b/pkg/implementation/commandrunner/mdadm.go index 6290ed6..67128bf 100644 --- a/pkg/implementation/commandrunner/mdadm.go +++ b/pkg/implementation/commandrunner/mdadm.go @@ -29,6 +29,11 @@ func NewMDADM(path *string) *MDADM { } } +// CommandPath returns the path of the mdadm binary this runner invokes. +func (m *MDADM) CommandPath() string { + return m.cliPath +} + func (m *MDADM) Run(args []string) ([]byte, error) { cmd := MDADMExecCommand(m.cliPath, args...) diff --git a/pkg/implementation/commandrunner/perccli2.go b/pkg/implementation/commandrunner/perccli2.go index da98d04..2088cb7 100644 --- a/pkg/implementation/commandrunner/perccli2.go +++ b/pkg/implementation/commandrunner/perccli2.go @@ -31,6 +31,11 @@ func NewPercCLI2(path *string) *PercCLI2 { } } +// CommandPath returns the path of the perccli2 binary this runner invokes. +func (p *PercCLI2) CommandPath() string { + return p.cliPath +} + // Run appends the JSON output flag and returns the command's standard output. // perccli2 emits the same JSON envelope as storcli2; stdout is captured on its // own (not combined with stderr) so the payload parses cleanly. diff --git a/pkg/implementation/commandrunner/smartctl.go b/pkg/implementation/commandrunner/smartctl.go index 494288c..ea85dee 100644 --- a/pkg/implementation/commandrunner/smartctl.go +++ b/pkg/implementation/commandrunner/smartctl.go @@ -30,6 +30,11 @@ func NewSmartCTL(path *string) *SmartCTL { } } +// CommandPath returns the path of the smartctl binary this runner invokes. +func (s *SmartCTL) CommandPath() string { + return s.cliPath +} + func (s *SmartCTL) Run(args []string) ([]byte, error) { cmd := SmartCTLExecCommand(s.cliPath, args...) diff --git a/pkg/implementation/commandrunner/ssacli.go b/pkg/implementation/commandrunner/ssacli.go index 877270c..6f8ca04 100644 --- a/pkg/implementation/commandrunner/ssacli.go +++ b/pkg/implementation/commandrunner/ssacli.go @@ -42,6 +42,11 @@ func NewSSACLI(path *string) *SSACLI { } } +// CommandPath returns the path of the ssacli binary this runner invokes. +func (s *SSACLI) CommandPath() string { + return s.cliPath +} + func (s *SSACLI) Run(args []string) ([]byte, error) { cmd := SSACLIExecCommand(s.cliPath, args...) diff --git a/pkg/implementation/commandrunner/storcli2.go b/pkg/implementation/commandrunner/storcli2.go index 4dc366d..015cc33 100644 --- a/pkg/implementation/commandrunner/storcli2.go +++ b/pkg/implementation/commandrunner/storcli2.go @@ -35,6 +35,11 @@ func NewStorCLI2(path *string) *StorCLI2 { } } +// CommandPath returns the path of the storcli2 binary this runner invokes. +func (s *StorCLI2) CommandPath() string { + return s.cliPath +} + // Run appends the JSON output flag and returns the command's standard output. // stdout is captured on its own (not combined with stderr) because the payload // is JSON that must parse cleanly. diff --git a/pkg/implementation/commandrunner/udevadm.go b/pkg/implementation/commandrunner/udevadm.go index 4273ab3..e9c455f 100644 --- a/pkg/implementation/commandrunner/udevadm.go +++ b/pkg/implementation/commandrunner/udevadm.go @@ -31,6 +31,11 @@ func NewUDevADM(path *string) *UDevADM { } } +// CommandPath returns the path of the udevadm binary this runner invokes. +func (u *UDevADM) CommandPath() string { + return u.cliPath +} + func (u *UDevADM) Run(args []string) ([]byte, error) { cmd := UDevADMExecCommand(u.cliPath, args...) diff --git a/pkg/implementation/raidcontroller/megaraid/logging.go b/pkg/implementation/raidcontroller/megaraid/logging.go new file mode 100644 index 0000000..facab78 --- /dev/null +++ b/pkg/implementation/raidcontroller/megaraid/logging.go @@ -0,0 +1,94 @@ +package megaraid + +import ( + "fmt" + "log/slog" + "time" + + "github.com/scality/raidmgmt/pkg/implementation/commandrunner" +) + +// commandPather is implemented by MegaRAIDRunner to report the binary it +// invokes, so that a log record names the tool that ran. +type commandPather interface { + CommandPath() string +} + +// LoggingRunner decorates a Runner so that every storcli/perccli command it +// executes is recorded on an slog.Logger, in the same shape as the decomposed +// adapters' commandrunner.Logging. The decorator is transparent: the parsed +// output and the error are returned unchanged. +// +// This runner parses its own output, so no payload size is recorded; the +// arguments recorded are the ones the adapter asked for, without the JSON +// output flag Run appends on the wire. +type LoggingRunner struct { + runner Runner + logger *slog.Logger + level slog.Level +} + +// LoggingRunnerOption configures a LoggingRunner. +type LoggingRunnerOption func(*LoggingRunner) + +// WithLevel sets the level successful commands are recorded at. It defaults to +// slog.LevelInfo; failures are always recorded at slog.LevelError. +func WithLevel(level slog.Level) LoggingRunnerOption { + return func(l *LoggingRunner) { + l.level = level + } +} + +var _ Runner = &LoggingRunner{} + +// NewLoggingRunner wraps runner so that every command it runs is logged to +// logger. A nil logger falls back to slog.Default(). +func NewLoggingRunner( + runner Runner, + logger *slog.Logger, + opts ...LoggingRunnerOption, +) *LoggingRunner { + target := logger + if target == nil { + target = slog.Default() + } + + logging := &LoggingRunner{ + runner: runner, + logger: target, + level: slog.LevelInfo, + } + + for _, opt := range opts { + opt(logging) + } + + return logging +} + +// Run logs the command, then returns the wrapped runner's output and error +// unchanged. +func (l *LoggingRunner) Run(args []string) (*CmdOutput, error) { + start := time.Now() + + output, err := l.runner.Run(args) + + commandrunner.LogCommand(l.logger, l.level, commandrunner.ExecutedCommand{ + Path: l.CommandPath(), + Args: args, + Duration: time.Since(start), + Err: err, + }) + + return output, err //nolint:wrapcheck // Transparent decorator: error returned as-is. +} + +// CommandPath reports the binary the wrapped runner invokes. A runner that does +// not report its binary is named by its type. +func (l *LoggingRunner) CommandPath() string { + if pather, ok := l.runner.(commandPather); ok { + return pather.CommandPath() + } + + return fmt.Sprintf("%T", l.runner) +} diff --git a/pkg/implementation/raidcontroller/megaraid/logging_test.go b/pkg/implementation/raidcontroller/megaraid/logging_test.go new file mode 100644 index 0000000..7a5c73b --- /dev/null +++ b/pkg/implementation/raidcontroller/megaraid/logging_test.go @@ -0,0 +1,108 @@ +package megaraid_test + +import ( + "bytes" + "encoding/json" + "log/slog" + "testing" + + "github.com/pkg/errors" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/scality/raidmgmt/pkg/implementation/raidcontroller/megaraid" + "github.com/scality/raidmgmt/pkg/implementation/raidcontroller/megaraid/mocks" +) + +// loggingRecords decodes the JSON log records captured in buf. +func loggingRecords(t *testing.T, buf *bytes.Buffer) []map[string]any { + t.Helper() + + var decoded []map[string]any + + for _, line := range bytes.Split(bytes.TrimSpace(buf.Bytes()), []byte("\n")) { + if len(line) == 0 { + continue + } + + var record map[string]any + + require.NoError(t, json.Unmarshal(line, &record)) + + decoded = append(decoded, record) + } + + return decoded +} + +func newLoggingTestLogger(buf *bytes.Buffer) *slog.Logger { + return slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug})) +} + +func TestLoggingRunnerLogsExecutedCommand(t *testing.T) { + var buf bytes.Buffer + + parsed := &megaraid.CmdOutput{} + + runner := &mocks.Runner{} + runner.On("Run", []string{"/c0", "show", "all"}).Return(parsed, nil) + + output, err := megaraid.NewLoggingRunner(runner, newLoggingTestLogger(&buf)). + Run([]string{"/c0", "show", "all"}) + require.NoError(t, err) + assert.Same(t, parsed, output) + + logged := loggingRecords(t, &buf) + require.Len(t, logged, 1) + + assert.Equal(t, "INFO", logged[0]["level"]) + assert.Equal(t, "RAID command executed", logged[0]["msg"]) + assert.Equal(t, []any{"/c0", "show", "all"}, logged[0]["args"]) + assert.Contains(t, logged[0], "duration") + // This runner parses its own output, so no payload size is recorded. + assert.NotContains(t, logged[0], "output_bytes") + + runner.AssertExpectations(t) +} + +func TestLoggingRunnerLogsFailureAtErrorLevel(t *testing.T) { + var buf bytes.Buffer + + wrapped := errors.New("no controllers found") + + runner := &mocks.Runner{} + runner.On("Run", []string{"show"}).Return(nil, wrapped) + + output, err := megaraid.NewLoggingRunner( + runner, + newLoggingTestLogger(&buf), + megaraid.WithLevel(slog.LevelDebug), + ).Run([]string{"show"}) + require.ErrorIs(t, err, wrapped) + assert.Nil(t, output) + + logged := loggingRecords(t, &buf) + require.Len(t, logged, 1) + + assert.Equal(t, "ERROR", logged[0]["level"]) + assert.Equal(t, "RAID command failed", logged[0]["msg"]) + assert.Equal(t, "no controllers found", logged[0]["error"]) +} + +// The mock runner does not report a binary path, so the record names it by type. +func TestLoggingRunnerNamesRunnerWithoutCommandPathByType(t *testing.T) { + var buf bytes.Buffer + + runner := &mocks.Runner{} + runner.On("Run", []string{"show"}).Return(&megaraid.CmdOutput{}, nil) + + logging := megaraid.NewLoggingRunner(runner, newLoggingTestLogger(&buf)) + assert.Equal(t, "*mocks.Runner", logging.CommandPath()) + + _, err := logging.Run([]string{"show"}) + require.NoError(t, err) + + logged := loggingRecords(t, &buf) + require.Len(t, logged, 1) + assert.Equal(t, "*mocks.Runner", logged[0]["command"]) +} diff --git a/pkg/implementation/raidcontroller/megaraid/runner.go b/pkg/implementation/raidcontroller/megaraid/runner.go index a958e46..b332ec5 100644 --- a/pkg/implementation/raidcontroller/megaraid/runner.go +++ b/pkg/implementation/raidcontroller/megaraid/runner.go @@ -71,6 +71,12 @@ func validatePath(path string) error { return nil } +// CommandPath returns the path of the storcli/perccli binary this runner +// invokes. +func (mrr *MegaRAIDRunner) CommandPath() string { + return mrr.cli +} + // Run runs a command with the given arguments. func (mrr *MegaRAIDRunner) Run(args []string) (*CmdOutput, error) { // Add JSON output format