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