diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index e2ff2f25..3c97d841 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -152,6 +152,30 @@ Errors that should stop the command are **returned**, not logged — they bubble The handler and the `--log` flag (`debug|warn|none`, default `warn`) live in [`cmds/dutctl/clilog.go`](cmds/dutctl/clilog.go). +### Agent and server logging + +`dutagent` (and `dutserver`) are service daemons, so they log differently from the client: structured records via [`internal/log`](internal/log) (built on `log/slog`), to **stderr**, at the full set of levels. The base logger is installed in `start()` (`slog.SetDefault`); the `-log` flag sets the level (`debug|info|warn|error`, default `info`) and `-log-json` switches the text handler for a JSON one. Human/TTY output is `2006/01/02 15:04:05 LEVEL [scope] message key=value` (color only on a terminal); JSON emits `scope` as an attribute. Never log to stdout. + +**Obtain the logger from the context.** Code retrieves it with `log.FromContext(ctx)`. At a component boundary, the caller sets the scope and any shared attributes *before* handing control on, so each component logs only its own concern: + +- `ctx = log.WithScope(ctx, "session")` — set the component scope (a flat label; a new scope replaces the old one). +- `ctx = log.With(ctx, "device", dev)` — add structured attributes that descend with the context. + +Module `Init`/`Deinit` and `Run` all receive a context carrying the `module`-scoped logger — a good place to log applied defaults from missing config, and the external hosts/tools/devices the module talks to. Where there genuinely is no context — process bootstrap, the `Session` methods — use `slog.Default()` or a logger frozen into the struct at construction (see `Locker`, `session.log`). Scopes in `dutagent`: `agent` (bootstrap/lifecycle, the default), `rpc`, `session`, `locker`, `module`. Scopes in `dutserver`: `server` (bootstrap/lifecycle, the default), `rpc`, `relay` (with directional `relay downstream`/`relay upstream` for the two forwarders of the relayed `Run` stream), and `registry` (the device→agent map). + +Module logging is for the **admin/operator** (the person who wrote the config and wired the DUTs), not a re-narration of what the module already prints to the client. Worth logging: external interactions with their effective parameters (tool + command, host:port, device + settings), and defaults a module applies for missing config. `Init`/`Deinit` should not log lifecycle markers — the framework already logs those. + +Always log through a logger **instance** (`log.FromContext(ctx).Info(...)`, `l.Warn(...)`), never the package-level `slog.Info`/`slog.Error`/… — those are rejected repo-wide by `forbidigo`. + +Levels: + +- `Error` — the agent failed at something it was asked to do; an operator likely must act. +- `Warn` — a handled or tolerated anomaly (e.g. a malformed client message, an admin force-unlock). +- `Info` — normal operational milestones; a few lines per request (request received/finished, running a module, listening). +- `Debug` — internal tracing, off by default (per-message traffic, worker start/stop, module init/deinit). + +An error returned up the call stack is logged once where it becomes terminal (the RPC handler), not at every hop. Module bodies should not log lifecycle markers (`"Run called"`); the framework logs the transition and sets the scope. + ### Documentation Style Guide - Use Markdown for documentation diff --git a/cmds/dutagent/dutagent.go b/cmds/dutagent/dutagent.go index 631ee45d..601e2a56 100644 --- a/cmds/dutagent/dutagent.go +++ b/cmds/dutagent/dutagent.go @@ -13,7 +13,7 @@ import ( "flag" "fmt" "io" - "log" + "log/slog" "net/http" "os" "os/signal" @@ -23,6 +23,7 @@ import ( "connectrpc.com/connect" "github.com/BlindspotSoftware/dutctl/internal/buildinfo" "github.com/BlindspotSoftware/dutctl/internal/dutagent" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/dut" "github.com/BlindspotSoftware/dutctl/protobuf/gen/dutctl/v1/dutctlv1connect" "gopkg.in/yaml.v3" @@ -37,6 +38,8 @@ const ( dryRunInfo = `Only run the initialization phase of the modules, not start the (includes validation of the configuration)` serverInfo = `Optional DUT Server address and port to register with in the format: address:port` versionFlagInfo = `Print version information and exit` + logLevelInfo = `Log level: debug, info, warn, or error` + logJSONInfo = `Emit logs as JSON instead of human-readable text` ) func newAgent(stdout io.Writer, exitFunc func(int), args []string) *agent { @@ -52,6 +55,8 @@ func newAgent(stdout io.Writer, exitFunc func(int), args []string) *agent { fs.BoolVar(&agt.dryRun, "dry-run", false, dryRunInfo) fs.StringVar(&agt.server, "server", "", serverInfo) fs.BoolVar(&agt.versionFlag, "v", false, versionFlagInfo) + fs.StringVar(&agt.logLevel, "log", "info", logLevelInfo) + fs.BoolVar(&agt.logJSON, "log-json", false, logJSONInfo) //nolint:errcheck // flag.Parse always returns no error because of flag.ExitOnError fs.Parse(args[1:]) @@ -70,6 +75,8 @@ type agent struct { checkConfig bool dryRun bool server string + logLevel string + logJSON bool // state config config @@ -94,10 +101,13 @@ const ( // otherwise with provided exitCode. func (agt *agent) cleanup(code exitCode) { if agt.modulesNeedDeinit { - err := dutagent.Deinit(agt.config.Devices) + // TODO(ctx): this background context is the shutdown seam. A later change + // can make it a context.WithTimeout to bound module Deinit, or derive it + // from a shutdown-signal context. It flows into every module's Deinit. + err := dutagent.Deinit(context.Background(), agt.config.Devices) if err != nil { printInitErr(err) - log.Print("System might be in an UNKNOWN STATE !!!") + slog.Default().Error("system might be in an UNKNOWN STATE") agt.exit(1) } } @@ -113,7 +123,7 @@ func (agt *agent) watchInterrupt() { go func() { sig := <-c - log.Printf("Captured signal: %v", sig) + slog.Default().Info("captured signal", "signal", sig) agt.cleanup(exit0) }() } @@ -132,24 +142,28 @@ func (agt *agent) loadConfig() error { return nil } -func (agt *agent) initModules() error { +func (agt *agent) initModules(ctx context.Context) error { agt.modulesNeedDeinit = true - return dutagent.Init(agt.config.Devices) + return dutagent.Init(ctx, agt.config.Devices) } // printInitErr extracts and pretty-prints the details of a dutagent.ModuleInitErr // if err is of this type, otherwise it just prints err. func printInitErr(err error) { + l := slog.Default() + var initerr *dutagent.ModuleInitError if errors.As(err, &initerr) { for _, item := range initerr.Errs { - devstr := fmt.Sprintf("dev:%q cmd:%q module:%q", item.Dev, item.Cmd, item.Mod.Config.Name) - log.Printf("init %s failed with:\n%v\n", devstr, item.Err) + l.Error("module init failed", + "device", item.Dev, "command", item.Cmd, "module", item.Mod.Config.Name, "err", item.Err) } + + return } - log.Print(err) + l.Error("module initialization error", "err", err) } // readHeaderTimeout bounds how long the server waits to read request headers. @@ -177,11 +191,14 @@ func (agt *agent) startRPCService() error { srv.Protocols.SetHTTP1(true) srv.Protocols.SetUnencryptedHTTP2(true) + slog.Default().Info("rpc service listening", "addr", agt.address) + return srv.ListenAndServe() } func (agt *agent) registerWithServer() error { - log.Printf("Registering with server %q", agt.server) + l := slog.Default() + l.Info("registering with server", "server", agt.server) client := spawnClient(agt.server) req := connect.NewRequest(&pb.RegisterRequest{ @@ -189,12 +206,15 @@ func (agt *agent) registerWithServer() error { Address: agt.address, }) + // TODO(ctx): background context — registration has no deadline or + // cancellation. A later change can bound it (context.WithTimeout) or tie it + // to a startup/shutdown context. _, err := client.Register(context.Background(), req) if err != nil { return fmt.Errorf("registering with server %q failed: %w", agt.server, err) } - log.Printf("Successfully registered with server %q", agt.server) + l.Info("successfully registered with server", "server", agt.server) return nil } @@ -204,7 +224,7 @@ func (agt *agent) registerWithServer() error { // //nolint:ireturn func spawnClient(agendURL string) dutctlv1connect.RelayServiceClient { - log.Printf("Spawning new client for agent %q", agendURL) + slog.Default().Info("spawning new client for agent", "url", agendURL) return dutctlv1connect.NewRelayServiceClient( // Instead of http.DefaultClient, use the HTTP/2 protocol without TLS @@ -234,7 +254,14 @@ func newInsecureClient() *http.Client { // //nolint:cyclop func (agt *agent) start() { - log.SetOutput(agt.stdout) + // Install the process-wide structured logger. Service diagnostics go to + // stderr (stdout is reserved for program output such as the version banner). + // The default is scoped "agent"; request handlers replace the scope as + // control enters their subsystem. See package internal/log. + base := log.New(os.Stderr, log.ParseLevel(agt.logLevel), agt.logJSON) + slog.SetDefault(log.Scope(base, "agent")) + + l := slog.Default() if agt.versionFlag { agt.printVersion() @@ -246,7 +273,7 @@ func (agt *agent) start() { // to do a graceful shutdown defer func() { if r := recover(); r != nil { - log.Printf("Recovered from panic: %v", r) + l.Error("recovered from panic", "panic", r) agt.cleanup(exit1) } }() @@ -256,26 +283,32 @@ func (agt *agent) start() { err := agt.loadConfig() if agt.checkConfig { if err != nil { - log.Printf("Bad configuration: %v", err) + l.Error("bad configuration", "err", err) agt.cleanup(exit0) } - log.Print("Configuration is valid") + l.Info("configuration is valid") agt.cleanup(exit0) } else if err != nil { - log.Printf("Loading config failed: %v", err) + l.Error("loading config failed", "err", err) agt.cleanup(exit1) } - err = agt.initModules() + // initCtx is the agent-lifetime context for module initialization. Today it + // is a plain background context; it is the single seam where a later change + // can attach a startup deadline (context.WithTimeout) or wire in + // cancellation. It flows into every module's Init via internal/log. TODO(ctx). + initCtx := context.Background() + + err = agt.initModules(initCtx) if agt.dryRun { if err != nil { printInitErr(err) - log.Print("Initialization FAILED - Dry run finished") + l.Info("initialization failed - dry run finished") agt.cleanup(exit0) } - log.Print("Initialization SUCCESSFUL - Dry run finished") + l.Info("initialization successful - dry run finished") agt.cleanup(exit0) } else if err != nil { printInitErr(err) @@ -285,13 +318,13 @@ func (agt *agent) start() { if agt.server != "" { err := agt.registerWithServer() if err != nil { - log.Printf("Registering with server %q failed: %v", agt.server, err) + l.Error("registering with server failed", "server", agt.server, "err", err) agt.cleanup(exit1) } } err = agt.startRPCService() - log.Printf("internal RPC handler error: %v", err) + l.Error("internal RPC handler error", "err", err) agt.cleanup(exit1) } diff --git a/cmds/dutagent/rpc.go b/cmds/dutagent/rpc.go index 6ffacc82..7a553487 100644 --- a/cmds/dutagent/rpc.go +++ b/cmds/dutagent/rpc.go @@ -8,13 +8,14 @@ import ( "context" "errors" "fmt" - "log" + "log/slog" "net/http" "time" "connectrpc.com/connect" "github.com/BlindspotSoftware/dutctl/internal/dutagent" "github.com/BlindspotSoftware/dutctl/internal/fsm" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/dut" "github.com/BlindspotSoftware/dutctl/pkg/lock" @@ -37,12 +38,19 @@ func userFromHeader(h http.Header) string { return lock.AnonymousUser() } +// rpcLogger returns a logger scoped to the RPC subsystem and tagged with the +// handler's method name, derived from the logger carried in ctx. +func rpcLogger(ctx context.Context, method string) *slog.Logger { + return log.Scope(log.FromContext(ctx), "rpc").With("rpc", method) +} + // List is the handler for the List RPC. func (a *rpcService) List( - _ context.Context, + ctx context.Context, _ *connect.Request[pb.ListRequest], ) (*connect.Response[pb.ListResponse], error) { - log.Println("Server received List request") + l := rpcLogger(ctx, "List") + l.Info("request received") locks := a.locker.StatusAll() @@ -67,17 +75,18 @@ func (a *rpcService) List( Devices: infos, }) - log.Print("List-RPC finished") + l.Info("request finished") return res, nil } // Commands is the handler for the Commands RPC. func (a *rpcService) Commands( - _ context.Context, + ctx context.Context, req *connect.Request[pb.CommandsRequest], ) (*connect.Response[pb.CommandsResponse], error) { - log.Println("Server received Commands request") + l := rpcLogger(ctx, "Commands") + l.Info("request received") device := req.Msg.GetDevice() @@ -102,17 +111,18 @@ func (a *rpcService) Commands( Commands: cmds, }) - log.Print("Commands-RPC finished") + l.Info("request finished") return res, nil } // Details is the handler for the Details RPC. func (a *rpcService) Details( - _ context.Context, + ctx context.Context, req *connect.Request[pb.DetailsRequest], ) (*connect.Response[pb.DetailsResponse], error) { - log.Println("Server received Details request") + l := rpcLogger(ctx, "Details") + l.Info("request received") wantDev := req.Msg.GetDevice() wantCmd := req.Msg.GetCmd() @@ -150,17 +160,18 @@ func (a *rpcService) Details( Details: helpStr, }) - log.Print("Details-RPC finished") + l.Info("request finished") return res, nil } // Lock is the handler for the Lock RPC. func (a *rpcService) Lock( - _ context.Context, + ctx context.Context, req *connect.Request[pb.LockRequest], ) (*connect.Response[pb.LockResponse], error) { - log.Println("Server received Lock request") + l := rpcLogger(ctx, "Lock") + l.Info("request received") device := req.Msg.GetDevice() user := userFromHeader(req.Header()) @@ -198,17 +209,18 @@ func (a *rpcService) Lock( ExpiresAt: expiresAt, }) - log.Print("Lock-RPC finished") + l.Info("lock acquired", "device", device, "owner", info.Owner) return res, nil } // Unlock is the handler for the Unlock RPC. func (a *rpcService) Unlock( - _ context.Context, + ctx context.Context, req *connect.Request[pb.UnlockRequest], ) (*connect.Response[pb.UnlockResponse], error) { - log.Println("Server received Unlock request") + l := rpcLogger(ctx, "Unlock") + l.Info("request received") device := req.Msg.GetDevice() user := userFromHeader(req.Header()) @@ -231,7 +243,7 @@ func (a *rpcService) Unlock( } } - log.Print("Unlock-RPC finished") + l.Info("lock released", "device", device, "user", user, "forced", req.Msg.GetForce()) return connect.NewResponse(&pb.UnlockResponse{}), nil } @@ -249,13 +261,19 @@ func (a *rpcService) Run( ctx context.Context, stream *connect.BidiStream[pb.RunRequest, pb.RunResponse], ) error { - log.Println("Server received Run request") + user := userFromHeader(stream.RequestHeader()) + + // Set the RPC scope once; it flows through the FSM, the session backend and + // the modules on ctx, so each only logs its own concern. + ctx = log.With(log.WithScope(ctx, "rpc"), "rpc", "Run", "user", user) + l := log.FromContext(ctx) + l.Info("request received") fsmArgs := runCmdArgs{ stream: &streamAdapter{inner: stream}, deviceList: a.devices, locker: a.locker, - user: userFromHeader(stream.RequestHeader()), + user: user, } finalArgs, err := fsm.Run(ctx, fsmArgs, receiveCommandRPC) @@ -276,9 +294,9 @@ func (a *rpcService) Run( } if err != nil { - log.Print("Run-RPC finished with error: ", err) + l.Error("request finished with error", "err", err) } else { - log.Print("Run-RPC finished successfully") + l.Info("request finished successfully") } return err diff --git a/cmds/dutagent/states.go b/cmds/dutagent/states.go index 5169a25a..3bf46e84 100644 --- a/cmds/dutagent/states.go +++ b/cmds/dutagent/states.go @@ -8,11 +8,11 @@ import ( "context" "errors" "fmt" - "log" "connectrpc.com/connect" "github.com/BlindspotSoftware/dutctl/internal/dutagent" "github.com/BlindspotSoftware/dutctl/internal/fsm" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/dut" "github.com/BlindspotSoftware/dutctl/pkg/module" @@ -136,15 +136,28 @@ func acquireAutoLock(_ context.Context, args runCmdArgs) (runCmdArgs, fsm.State[ // never touches the explicit lock slot, so an explicit Lock the same owner // holds for the device survives the run. ErrNotLocked is tolerated because // a forced unlock by an admin may have wiped the slot concurrently. -func releaseAutoLock(_ context.Context, args runCmdArgs) (runCmdArgs, fsm.State[runCmdArgs], error) { +func releaseAutoLock(ctx context.Context, args runCmdArgs) (runCmdArgs, fsm.State[runCmdArgs], error) { err := args.locker.ClearAutoLock(args.cmdMsg.GetDevice(), args.user) if err != nil && !errors.Is(err, dutagent.ErrNotLocked) { - log.Printf("Failed to release auto-lock on device %q: %v", args.cmdMsg.GetDevice(), err) + log.FromContext(ctx).Warn("failed to release auto-lock", "device", args.cmdMsg.GetDevice(), "err", err) } return args, nil, nil } +// runModule runs a single module, recovering a panic into an error so a +// misbehaving module aborts only its run instead of crashing the agent. (The +// session's Console invariant guards also panic; this is where they land.) +func runModule(ctx context.Context, mod dut.Module, s module.Session, args ...string) (err error) { + defer func() { + if r := recover(); r != nil { + err = fmt.Errorf("module panicked: %v", r) + } + }() + + return mod.Run(ctx, s, args...) +} + // executeModules is a state of the Run RPC. // // It starts the execution the current command's modules. The execution is done @@ -152,6 +165,11 @@ func releaseAutoLock(_ context.Context, args runCmdArgs) (runCmdArgs, fsm.State[ // Further, worker goroutines will be started to serve the module-to-client communication // during the module execution. func executeModules(ctx context.Context, args runCmdArgs) (runCmdArgs, fsm.State[runCmdArgs], error) { + // Module execution is the agent's core orchestration: scope it "agent" and + // tag the device and command, which then descend to every record on this path. + ctx = log.With(log.WithScope(ctx, "agent"), "device", args.cmdMsg.GetDevice(), "command", args.cmdMsg.GetCommand()) + l := log.FromContext(ctx) + broker := &dutagent.Broker{} // Deferred initialization of the moduleErr channel: only create if not already provided @@ -180,28 +198,35 @@ func executeModules(ctx context.Context, args runCmdArgs) (runCmdArgs, fsm.State go func() { cnt := len(args.cmd.Modules) - for idx, module := range args.cmd.Modules { + for idx, mod := range args.cmd.Modules { if ctx.Err() != nil { - log.Printf("Execution aborted, %d of %d modules done: %v", idx, cnt, ctx.Err()) + l.Warn("execution aborted", "modules-done", idx, "modules-total", cnt, "err", ctx.Err()) modCtxCancel() return } - log.Printf("Running module %d of %d: %q", idx+1, cnt, module.Config.Name) + // Announce the hand-off in the agent scope (this line is the + // framework's, not the module's). + ml := l.With("module", mod.Config.Name, "module-index", idx+1, "modules-total", cnt) + ml.Info("running module") + + // Set the "module" scope on the context handed to the module, so + // only the module's own records are scoped to it. + runCtx := log.With(log.WithScope(rpcCtx, "module"), "module", mod.Config.Name, "module-index", idx+1) - err := module.Run(rpcCtx, moduleSession, moduleArgs[idx]...) + err := runModule(runCtx, mod, moduleSession, moduleArgs[idx]...) if err != nil { args.moduleErrCh <- err - log.Printf("Module %q failed: %v", module.Config.Name, err) + ml.Error("module failed", "err", err) modCtxCancel() return } } - log.Print("All modules finished successfully") + l.Info("all modules finished successfully") modCtxCancel() close(args.moduleErrCh) }() diff --git a/cmds/dutagent/states_test.go b/cmds/dutagent/states_test.go index 1c9b9d26..f06992a8 100644 --- a/cmds/dutagent/states_test.go +++ b/cmds/dutagent/states_test.go @@ -347,9 +347,9 @@ type dummyModule struct { runCalls int } -func (m *dummyModule) Help() string { return "dummy" } -func (m *dummyModule) Init() error { return nil } -func (m *dummyModule) Deinit() error { return nil } +func (m *dummyModule) Help() string { return "dummy" } +func (m *dummyModule) Init(_ context.Context) error { return nil } +func (m *dummyModule) Deinit(_ context.Context) error { return nil } func (m *dummyModule) Run(_ context.Context, _ module.Session, args ...string) error { // session unused in these tests m.runCalls++ m.runArgs = append([]string{}, args...) // copy for safety diff --git a/cmds/dutctl/rpc.go b/cmds/dutctl/rpc.go index a3c7893f..17bbee4d 100644 --- a/cmds/dutctl/rpc.go +++ b/cmds/dutctl/rpc.go @@ -31,6 +31,10 @@ import ( var errInterrupted = errors.New("interrupted") func (app *application) listRPC() error { + // TODO(ctx): unary RPCs run on a bare background context — no signal + // cancellation and no deadline. A later change should share an app-level + // context (see runRPC's signal.NotifyContext) and add a timeout. Applies to + // every unary RPC in this file (List/Lock/Unlock/Commands/Details). ctx := context.Background() req := connect.NewRequest(&pb.ListRequest{}) diff --git a/cmds/exp/dutserver/dutserver.go b/cmds/exp/dutserver/dutserver.go index d029b0c1..4d00478a 100644 --- a/cmds/exp/dutserver/dutserver.go +++ b/cmds/exp/dutserver/dutserver.go @@ -8,29 +8,32 @@ package main import ( "flag" - "io" - "log" + "log/slog" "net/http" "os" "os/signal" "syscall" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/protobuf/gen/dutctl/v1/dutctlv1connect" ) const ( - addressInfo = `Server address and port in the format: address:port` + addressInfo = `Server address and port in the format: address:port` + logLevelInfo = `Log level: debug, info, warn, or error` + logJSONInfo = `Emit logs as JSON instead of human-readable text` ) -func newServer(stdout io.Writer, exitFunc func(int), args []string) *server { +func newServer(exitFunc func(int), args []string) *server { var svr server - svr.stdout = stdout svr.exit = exitFunc f := flag.NewFlagSet(args[0], flag.ExitOnError) f.StringVar(&svr.address, "s", "localhost:1024", addressInfo) + f.StringVar(&svr.logLevel, "log", "info", logLevelInfo) + f.BoolVar(&svr.logJSON, "log-json", false, logJSONInfo) //nolint:errcheck // flag.Parse never returns an error because of flag.ExitOnError f.Parse(args[1:]) @@ -40,11 +43,12 @@ func newServer(stdout io.Writer, exitFunc func(int), args []string) *server { // server represents the dutserver application. type server struct { - stdout io.Writer - exit func(int) + exit func(int) // flags - address string + address string + logLevel string + logJSON bool } type exitCode int @@ -70,7 +74,7 @@ func (svr *server) watchInterrupt() { go func() { sig := <-c - log.Printf("Captured signal: %v", sig) + slog.Default().Info("captured signal", "signal", sig) svr.cleanup(exit0) }() } @@ -106,19 +110,27 @@ func (svr *server) startRPCService() error { srv.Protocols.SetHTTP1(true) srv.Protocols.SetUnencryptedHTTP2(true) + slog.Default().Info("rpc service listening", "addr", svr.address) + return srv.ListenAndServe() } -// start orchestrates the dutagent execution. +// start orchestrates the dutserver execution. func (svr *server) start() { - log.SetOutput(svr.stdout) + // Install the process-wide structured logger. Service diagnostics go to + // stderr; the default scope is "server" and request handlers replace the + // scope as control enters their subsystem. See package internal/log. + base := log.New(os.Stderr, log.ParseLevel(svr.logLevel), svr.logJSON) + slog.SetDefault(log.Scope(base, "server")) + + l := slog.Default() // By design dutserver's code does not panic. // But other code could, or *things* happen at runtime. So we catch it here // to do a graceful shutdown defer func() { if r := recover(); r != nil { - log.Printf("Recovered from panic: %v", r) + l.Error("recovered from panic", "panic", r) svr.cleanup(exit1) } }() @@ -131,10 +143,10 @@ func (svr *server) start() { err := svr.startRPCService() // runs forever - log.Printf("internal RPC handler error: %v", err) + l.Error("rpc service stopped", "err", err) svr.cleanup(exit1) } func main() { - newServer(os.Stdout, os.Exit, os.Args).start() + newServer(os.Exit, os.Args).start() } diff --git a/cmds/exp/dutserver/rpc.go b/cmds/exp/dutserver/rpc.go index 4692684f..2dcf77e7 100644 --- a/cmds/exp/dutserver/rpc.go +++ b/cmds/exp/dutserver/rpc.go @@ -9,13 +9,13 @@ import ( "errors" "fmt" "io" - "log" "maps" "net/http" "slices" "sync" "connectrpc.com/connect" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/lock" "github.com/BlindspotSoftware/dutctl/protobuf/gen/dutctl/v1/dutctlv1connect" @@ -33,12 +33,12 @@ type agent struct { } // conn returns the RPC client that connetcs to the DUT agent. -func (a *agent) conn() dutctlv1connect.DeviceServiceClient { +func (a *agent) conn(ctx context.Context) dutctlv1connect.DeviceServiceClient { a.Lock() defer a.Unlock() if a.client == nil { - a.client = spawnClient(a.address) + a.client = spawnClient(ctx, a.address) } return a.client @@ -73,12 +73,16 @@ func (s *rpcService) findAgent(device string) (*agent, error) { // addAgent tries to register devices handled by an agent with address. // If one of the provided devices already exists an error is returned and none of the deviced will be stored. -func (s *rpcService) addAgent(address string, devices []string) error { +func (s *rpcService) addAgent(ctx context.Context, address string, devices []string) error { s.mu.Lock() defer s.mu.Unlock() + l := log.FromContext(ctx) + for _, device := range devices { if _, exists := s.agents[device]; exists { + l.Warn("rejecting registration: device already registered", "device", device, "agent", address) + return fmt.Errorf("device %q already registered", device) } } @@ -87,15 +91,18 @@ func (s *rpcService) addAgent(address string, devices []string) error { s.agents[device] = &agent{address: address} } + l.Info("agent registered", "agent", address, "devices", devices) + return nil } // List is the handler for the List RPC. func (s *rpcService) List( - _ context.Context, + ctx context.Context, _ *connect.Request[pb.ListRequest], ) (*connect.Response[pb.ListResponse], error) { - log.Println("Server received List request") + l := log.FromContext(log.With(log.WithScope(ctx, "rpc"), "rpc", "List")) + l.Info("request received") names := slices.Sorted(maps.Keys(s.agents)) infos := make([]*pb.DeviceInfo, 0, len(names)) @@ -109,7 +116,7 @@ func (s *rpcService) List( Devices: infos, }) - log.Print("List-RPC finished") + l.Info("request finished") return res, nil } @@ -119,24 +126,27 @@ func (s *rpcService) Commands( ctx context.Context, req *connect.Request[pb.CommandsRequest], ) (*connect.Response[pb.CommandsResponse], error) { - log.Println("Server received Commands request") - device := req.Msg.GetDevice() + ctx = log.With(log.WithScope(ctx, "rpc"), "rpc", "Commands", "device", device) + l := log.FromContext(ctx) + l.Info("request received") agent, err := s.findAgent(device) if err != nil { return nil, connect.NewError(connect.CodeInvalidArgument, err) } - res, err := forwardCommandsReq(ctx, agent.address, req) + res, err := forwardCommandsReq(log.WithScope(ctx, "relay"), agent.address, req) if err != nil { + l.Error("forwarding to agent failed", "agent", agent.address, "err", err) + return nil, connect.NewError( connect.CodeInternal, fmt.Errorf("forwarding request to agent %q: %w", agent.address, err), ) } - log.Print("Commands-RPC finished") + l.Info("request finished", "agent", agent.address) return res, nil } @@ -145,24 +155,27 @@ func (s *rpcService) Details( ctx context.Context, req *connect.Request[pb.DetailsRequest], ) (*connect.Response[pb.DetailsResponse], error) { - log.Println("Server received Details request") - device := req.Msg.GetDevice() + ctx = log.With(log.WithScope(ctx, "rpc"), "rpc", "Details", "device", device) + l := log.FromContext(ctx) + l.Info("request received") agent, err := s.findAgent(device) if err != nil { return nil, connect.NewError(connect.CodeInvalidArgument, err) } - res, err := forwardDetailsReq(ctx, agent.address, req) + res, err := forwardDetailsReq(log.WithScope(ctx, "relay"), agent.address, req) if err != nil { + l.Error("forwarding to agent failed", "agent", agent.address, "err", err) + return nil, connect.NewError( connect.CodeInternal, fmt.Errorf("forwarding request to agent %q: %w", agent.address, err), ) } - log.Print("Details-RPC finished") + l.Info("request finished", "agent", agent.address) return res, nil } @@ -174,9 +187,15 @@ func (s *rpcService) Run( ctx context.Context, downstream *connect.BidiStream[pb.RunRequest, pb.RunResponse], ) error { - log.Println("Server received Run request") + user := downstream.RequestHeader().Get(lock.UserHeader) + + // Set the RPC scope once; it flows to the relay forwarding goroutines on + // ctx, so each logs only its own concern. + ctx = log.With(log.WithScope(ctx, "rpc"), "rpc", "Run", "user", user) + l := log.FromContext(ctx) + l.Info("request received") - donwnStreamRequest, err := downstream.Receive() + downStreamRequest, err := downstream.Receive() if err != nil { return connect.NewError( connect.CodeAborted, @@ -189,7 +208,7 @@ func (s *rpcService) Run( ok bool ) - if cmdMsg, ok = isCommandMsg(donwnStreamRequest); !ok { + if cmdMsg, ok = isCommandMsg(downStreamRequest); !ok { return connect.NewError( connect.CodeInvalidArgument, errors.New("first run request must contain a command"), @@ -197,23 +216,30 @@ func (s *rpcService) Run( } device := cmdMsg.GetDevice() + ctx = log.With(ctx, "device", device) + l = log.FromContext(ctx) agent, err := s.findAgent(device) if err != nil { return connect.NewError(connect.CodeInvalidArgument, err) } - upstream := agent.conn().Run(ctx) + l.Info("routing to agent", "agent", agent.address) - // This is the first message of a new Run RPC from a client. - log.Println("Run request has a command message - starting new stream to DUT agent") + // upstream is bound to the request context (ctx), so it is torn down when this + // handler returns. A relay-internal abort currently relies on that return plus + // parent-context teardown; a future context.WithCancelCause on runCtx could + // bind upstream to the relay directly for prompt cancellation. TODO(ctx). + upstream := agent.conn(log.WithScope(ctx, "relay")).Run(ctx) // Forward the requesting user's identity to the agent so it can enforce locking. - upstream.RequestHeader().Set(lock.UserHeader, downstream.RequestHeader().Get(lock.UserHeader)) + upstream.RequestHeader().Set(lock.UserHeader, user) // Forward the initial request to the DUT agent. - err = upstream.Send(donwnStreamRequest) + err = upstream.Send(downStreamRequest) if err != nil { + l.Error("forwarding to agent failed", "agent", agent.address, "err", err) + return connect.NewError( connect.CodeInternal, fmt.Errorf("sending initial request to agent %q: %w", device, err), @@ -223,45 +249,43 @@ func (s *rpcService) Run( // TODO: consider refactoring and use context.WithCancelCause(ctx) const numForwardingWorkers = 2 - errChan := make(chan error, numForwardingWorkers) // Each oft the two goroutines can send an error. + errChan := make(chan error, numForwardingWorkers) // Each of the two goroutines can send an error. runCtx, cancel := context.WithCancel(ctx) defer cancel() // Ensure the context is cancelled when the function returns. - // agent to client forwarding + // agent to client forwarding (downstream direction) go func() { defer cancel() + l := log.FromContext(log.WithScope(runCtx, "relay downstream")) + for { select { case <-runCtx.Done(): - log.Println("Agent to client forwarding terminating: Run-Context cancelled") + l.Debug("forwarding stopped: context cancelled") return default: // Unblock select, continue with the forwarding logic. } - log.Println("Receiving response from agent to forward to client (blocking)") - res, err := upstream.Receive() if errors.Is(err, io.EOF) { - log.Println("Agent to client forwarding terminating: Stream closed by agent") + l.Debug("forwarding stopped: stream closed by agent") return } if err != nil { - log.Printf("Agent to client forwarding terminating as receiving has been cancelled: %v", err) errChan <- err return } - log.Printf("Forwarding response to client: %v", res) + l.Debug("forwarding message to client", "kind", responseKind(res)) err = downstream.Send(res) if err != nil { - log.Printf("Agent to client forwarding terminating as sending has been cancelled: %v", err) errChan <- err return @@ -269,40 +293,38 @@ func (s *rpcService) Run( } }() - // client to agent forwarding + // client to agent forwarding (upstream direction) go func() { defer cancel() + l := log.FromContext(log.WithScope(runCtx, "relay upstream")) + for { select { case <-runCtx.Done(): - log.Println("Client to agent forwarding terminating: Run-Context cancelled") + l.Debug("forwarding stopped: context cancelled") return default: // Unblock select, continue with the forwarding logic. } - log.Println("Receiving request from client to forward to agent (blocking)") - req, err := downstream.Receive() if errors.Is(err, io.EOF) { - log.Println("Client to agent forwarding terminating: Stream closed by client") + l.Debug("forwarding stopped: stream closed by client") return } if err != nil { - log.Printf("Client to agent forwarding terminating as receiving has been cancelled: %v", err) errChan <- err return } - log.Printf("Forwarding request to agent %q: %v", device, req) + l.Debug("forwarding message to agent", "kind", requestKind(req)) err = upstream.Send(req) if err != nil { - log.Printf("Client to agent forwarding terminating as sending has been cancelled: %v", err) errChan <- err return @@ -310,15 +332,12 @@ func (s *rpcService) Run( } }() - // Wait for both forwarding routines to finish. - log.Println("Waiting for forwarding routines to finish") - - // Check if any of the forwarding routines encountered an error. + // Wait for both forwarding routines to finish, or for one to fail. select { case <-runCtx.Done(): - log.Println("Run RPC forwarding completed successfully") + l.Info("request finished") case err := <-errChan: - log.Printf("Run RPC forwarding aborted, forwarding error: %v", err) + l.Error("request finished with error", "err", err) return err } @@ -340,6 +359,38 @@ func isCommandMsg(req *pb.RunRequest) (*pb.Command, bool) { return cmdMsg, true } +// requestKind names the payload variant carried by a RunRequest, so relayed +// traffic can be logged by kind without dumping its contents. +func requestKind(req *pb.RunRequest) string { + switch { + case req.GetCommand() != nil: + return "command" + case req.GetConsole() != nil: + return "console" + case req.GetFile() != nil: + return "file" + default: + return "unknown" + } +} + +// responseKind names the payload variant carried by a RunResponse, so relayed +// traffic can be logged by kind without dumping its contents. +func responseKind(res *pb.RunResponse) string { + switch { + case res.GetPrint() != nil: + return "print" + case res.GetConsole() != nil: + return "console" + case res.GetFileRequest() != nil: + return "file-request" + case res.GetFile() != nil: + return "file" + default: + return "unknown" + } +} + // forwardCommandsReq forwards the Commands request to the respective DUT agent. // It returns the response from the agent or an error if the request fails. // TODO: try to refactor the forwarding functions into a generic function that can be reused for all RPCs. @@ -348,11 +399,13 @@ func forwardCommandsReq( url string, req *connect.Request[pb.CommandsRequest], ) (*connect.Response[pb.CommandsResponse], error) { - log.Printf("Forwarding Commands request to agent %q", url) + log.FromContext(ctx).Debug("forwarding commands request to agent", "agent", url) // TODO: potential resource leak. Investigate how clients can be reused or closed. // For now, we spawn a new client for each request. - client := spawnClient(url) + client := spawnClient(ctx, url) + // TODO(ctx): ctx carries the caller's cancellation but no deadline (the + // client sets none). A per-RPC timeout would attach here. return client.Commands(ctx, req) } @@ -361,26 +414,32 @@ func forwardCommandsReq( // TODO: try to refactor the forwarding functions into a generic function that can be reused for all RPCs. func forwardDetailsReq( ctx context.Context, - agent string, + url string, req *connect.Request[pb.DetailsRequest], ) (*connect.Response[pb.DetailsResponse], error) { - log.Printf("Forwarding Details request to agent %q", agent) + log.FromContext(ctx).Debug("forwarding details request to agent", "agent", url) // TODO: potential resource leak. Investigate how clients can be reused or closed. // For now, we spawn a new client for each request. - client := spawnClient(agent) + client := spawnClient(ctx, url) + // TODO(ctx): ctx carries the caller's cancellation but no deadline (the + // client sets none). A per-RPC timeout would attach here. return client.Details(ctx, req) } // spawnClient creates a new client to the DUT agent specified by the agent address. // TODO: refactor into pkg and reuse in dutctl and dutserver. -func spawnClient(agendURL string) dutctlv1connect.DeviceServiceClient { - log.Printf("Spawning new client for agent %q", agendURL) +func spawnClient(ctx context.Context, agentURL string) dutctlv1connect.DeviceServiceClient { + // ctx is used only for the log line below. Do NOT bind the client's dial or + // lifetime to it: the client is cached (see agent.conn) and shared across + // requests, so tying it to a single request's context would be a bug. A + // per-RPC deadline belongs on the call context passed to the forwarders. + log.FromContext(ctx).Debug("spawning client for agent", "agent", agentURL) return dutctlv1connect.NewDeviceServiceClient( // Instead of http.DefaultClient, use the HTTP/2 protocol without TLS newInsecureClient(), - fmt.Sprintf("http://%s", agendURL), + fmt.Sprintf("http://%s", agentURL), connect.WithGRPC(), ) } @@ -403,10 +462,12 @@ func newInsecureClient() *http.Client { } func (s *rpcService) Register( - _ context.Context, + ctx context.Context, req *connect.Request[pb.RegisterRequest], ) (*connect.Response[pb.RegisterResponse], error) { - log.Println("Server received Register request") + ctx = log.With(log.WithScope(ctx, "rpc"), "rpc", "Register") + l := log.FromContext(ctx) + l.Info("request received") addr := req.Msg.GetAddress() if addr == "" { @@ -423,16 +484,14 @@ func (s *rpcService) Register( } } - log.Printf("Registering agent %q with devices %v", addr, req.Msg.GetDevices()) - - err := s.addAgent(addr, req.Msg.GetDevices()) + err := s.addAgent(log.WithScope(ctx, "registry"), addr, req.Msg.GetDevices()) if err != nil { return nil, connect.NewError(connect.CodeAlreadyExists, fmt.Errorf("adding agent %q: %w", addr, err)) } res := connect.NewResponse(&pb.RegisterResponse{}) - log.Print("Register-RPC finished") + l.Info("request finished") return res, nil } diff --git a/internal/chanio/chanio.go b/internal/chanio/chanio.go index 6e8f0174..1c487b54 100644 --- a/internal/chanio/chanio.go +++ b/internal/chanio/chanio.go @@ -8,7 +8,7 @@ package chanio import ( "errors" "io" - "log" + "log/slog" ) // ChanReader implements io.Reader that reads from a channel of byte slices. @@ -16,63 +16,74 @@ import ( type ChanReader struct { ch <-chan []byte buf []byte // Buffer to store excess bytes + log *slog.Logger } -// NewChanReader returns a new ChanReader reading from ch. The provided channel must not be nil. -func NewChanReader(ch <-chan []byte) (*ChanReader, error) { +// NewChanReader returns a new ChanReader reading from ch. The provided channel +// must not be nil. Reads are traced at debug level through logger; pass an +// already-scoped logger (its scope is used as-is) or nil for slog.Default(). +func NewChanReader(ch <-chan []byte, logger *slog.Logger) (*ChanReader, error) { if ch == nil { return nil, errors.New("cannot create a ChanReader with a nil channel") } + if logger == nil { + logger = slog.Default() + } + return &ChanReader{ ch: ch, buf: make([]byte, 0), + log: logger, }, nil } +// logger returns the reader's logger, falling back to the default if it was +// constructed directly (e.g. in a test) rather than via NewChanReader. +func (r *ChanReader) logger() *slog.Logger { + if r.log != nil { + return r.log + } + + return slog.Default() +} + // Read reads up to len(bytes) bytes into bytes. It returns the number of bytes // read and any error encountered. func (r *ChanReader) Read(bytes []byte) (int, error) { - log.Printf("Channel Reader: Read called with %d bytes\n", len(bytes)) + r.logger().Debug("chan read", "want", len(bytes)) + // If there's enough data in the buffer, use it and return early. if len(r.buf) >= len(bytes) { n := copy(bytes, r.buf) r.buf = r.buf[n:] // Adjust the buffer - log.Printf("Channel Reader: Returning early (internal buffer >= read buffer), %d bytes from buffer\n", n) + r.logger().Debug("chan read served from buffer", "n", n) return n, nil } - log.Printf("Channel Reader: no early return, continue to read from buffer and channel\n") - var nBuf, nChan int // If the buffer is not empty but contains some data, start by filling bytes with it. if len(r.buf) > 0 { - log.Printf("Channel Reader: Reading from internal buffer\n") - nBuf = copy(bytes, r.buf) r.buf = r.buf[nBuf:] // Adjust the buffer if nBuf == len(bytes) { // If the buffer fulfilled the bytes, return early - log.Printf("Channel Reader: Returning early (internal buffer = read buffer), %d bytes from buffer\n", nBuf) + r.logger().Debug("chan read served from buffer", "n", nBuf) return nBuf, nil } } - log.Printf("Channel Reader: Continue reading from channel\n") - // Read from the channel if the buffer is empty or insufficient chanBytes, ok := <-r.ch if !ok { - log.Printf("Channel Reader: Channel closed returning EOF") + r.logger().Debug("chan read EOF: channel closed", "buffered", nBuf) return nBuf, io.EOF // Return any remaining buffer content before EOF } - log.Printf("Channel Reader: Channel read %d bytes. Continue calculating total read count\n", len(chanBytes)) - // Calculate the total bytes to copy to bytes, considering any existing content from the buffer totalNeeded := len(bytes) - len(r.buf) nChan = copy(bytes[nBuf:], chanBytes) @@ -82,7 +93,7 @@ func (r *ChanReader) Read(bytes []byte) (int, error) { r.buf = append(r.buf, chanBytes[totalNeeded:]...) } - log.Printf("Channel Reader: Read %d bytes from internal buffer and %d bytes from channel\n", nBuf, nChan) + r.logger().Debug("chan read complete", "from_buffer", nBuf, "from_channel", nChan) return nBuf + nChan, nil } diff --git a/internal/chanio/chanio_test.go b/internal/chanio/chanio_test.go index a0c40fc5..8ab356f5 100644 --- a/internal/chanio/chanio_test.go +++ b/internal/chanio/chanio_test.go @@ -38,7 +38,7 @@ func TestNewChanWriter(t *testing.T) { func TestNewChanReader(t *testing.T) { // Test with valid channel ch := make(chan []byte) - reader, err := NewChanReader(ch) + reader, err := NewChanReader(ch, nil) if err != nil { t.Fatalf("NewChanReader() returned an error: %v", err) @@ -53,7 +53,7 @@ func TestNewChanReader(t *testing.T) { } // Test with nil channel - reader, err = NewChanReader(nil) + reader, err = NewChanReader(nil, nil) if err == nil { t.Fatalf("NewChanReader() did not return an error for nil channel") diff --git a/internal/dutagent/broker.go b/internal/dutagent/broker.go index 333deb93..999051c0 100644 --- a/internal/dutagent/broker.go +++ b/internal/dutagent/broker.go @@ -7,9 +7,9 @@ package dutagent import ( "context" - "log" "sync" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -17,6 +17,15 @@ import ( // the other handles client-to-module communication. const numWorkers = 2 +// Session log scopes. The general scope covers broker setup; the directional +// scopes distinguish the two communication flows, and are inherited by the +// workers and the chanio readers they (and the session) construct. +const ( + scopeSession = "session" // general session/broker setup + scopeSessionDownstream = "session downstream" // agent/session → client + scopeSessionUpstream = "session upstream" // client → agent/session +) + // Broker mediates between a module and its environment while the module is executed. // This concerns communication and data exchange. type Broker struct { @@ -28,8 +37,6 @@ type Broker struct { } func (b *Broker) init() { - log.Print("Broker: Initializing") - b.session.printCh = make(chan string) b.session.stdinCh = make(chan []byte) b.session.stdoutCh = make(chan []byte) @@ -47,9 +54,16 @@ func (b *Broker) init() { // //nolint:ireturn // returning interface module.Session is intentional for abstraction boundary func (b *Broker) Start(ctx context.Context, s Stream) (module.Session, <-chan error) { + ctx = log.WithScope(ctx, scopeSession) + b.once.Do(func() { b.init() b.stream = s + // Freeze the session-scoped logger onto the session: its module-facing + // methods carry no context to derive a logger from. + b.session.log = log.FromContext(ctx) + + log.FromContext(ctx).Debug("broker initializing") workerCtx, workerCancel := context.WithCancel(ctx) @@ -68,17 +82,23 @@ func (b *Broker) Start(ctx context.Context, s Stream) (module.Session, <-chan er } func (b *Broker) toClient(ctx context.Context, cancel context.CancelFunc) { + // Scope the downstream (agent → client) flow; the worker and its chanio + // reader inherit it from ctx. + ctx = log.WithScope(ctx, scopeSessionDownstream) + go func() { defer b.wg.Done() - log.Print("Broker: Starting module-to-client worker") + l := log.FromContext(ctx) + l.Debug("worker started") err := toClientWorker(ctx, b.stream, &b.session) if err != nil { - log.Printf("Broker: module-to-client worker terminated: %v", err) + // Surfaced to the RPC layer via errCh, which logs the terminal error. + l.Warn("worker terminated", "err", err) b.errCh <- err } else { - log.Print("Broker: module-to-client worker returned") + l.Debug("worker stopped") } // Cancel companion regardless of outcome; fromClientWorker drains one pending receive to catch concurrent error. cancel() @@ -86,17 +106,22 @@ func (b *Broker) toClient(ctx context.Context, cancel context.CancelFunc) { } func (b *Broker) fromClient(ctx context.Context, cancel context.CancelFunc) { + // Scope the upstream (client → agent) flow; the worker inherits it from ctx. + ctx = log.WithScope(ctx, scopeSessionUpstream) + go func() { defer b.wg.Done() - log.Print("Broker: Starting client-to-module worker") + l := log.FromContext(ctx) + l.Debug("worker started") err := fromClientWorker(ctx, b.stream, &b.session) if err != nil { - log.Printf("Broker: client-to-module worker terminated: %v", err) + // Surfaced to the RPC layer via errCh, which logs the terminal error. + l.Warn("worker terminated", "err", err) b.errCh <- err } else { - log.Print("Broker: client-to-module worker returned") + l.Debug("worker stopped") } // Cancel companion regardless of outcome; toClientWorker will exit promptly. cancel() diff --git a/internal/dutagent/init.go b/internal/dutagent/init.go index 7b5a4466..ad65254d 100644 --- a/internal/dutagent/init.go +++ b/internal/dutagent/init.go @@ -5,9 +5,11 @@ package dutagent import ( + "context" "fmt" - "log" + "log/slog" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/dut" ) @@ -55,7 +57,11 @@ type ModuleInitErrorDetails struct { // Init runs the Init function of all modules for all commands of the provided // devices. All init functions are called, even if an error occurs. In this case // the an ModuleInitErr is returned that holds all errors reported by the modules. -func Init(devices dut.Devlist) error { +// +// ctx is the agent-lifetime context for startup; each module's Init receives a +// child of it carrying the module-scoped logger. It is a plain background +// context today — see the caller for where a startup deadline would attach. +func Init(ctx context.Context, devices dut.Devlist) error { var ierr = &ModuleInitError{ Errs: make([]ModuleInitErrorDetails, 0), msg: "module initialization failed", @@ -64,8 +70,14 @@ func Init(devices dut.Devlist) error { for devname, device := range devices { for cmdname, cmd := range device.Cmds { for _, module := range cmd.Modules { - err := catchPanic(module.Init) + mlog := log.Scope(slog.Default(), "module").With("device", devname, "command", cmdname, "module", module.Config.Name) + mctx := log.Into(ctx, mlog) + + mlog.Debug("initializing module") + + err := catchPanic(func() error { return module.Init(mctx) }) if err != nil { + // Aggregated and reported by the caller (printInitErr); not logged here. ierr.Errs = append(ierr.Errs, ModuleInitErrorDetails{ Dev: devname, Cmd: cmdname, @@ -81,7 +93,7 @@ func Init(devices dut.Devlist) error { return ierr } - log.Print("Module Initialization OK") + slog.Default().Info("module initialization complete") return nil } @@ -89,18 +101,27 @@ func Init(devices dut.Devlist) error { // Deinit runs the Deinit function of all modules for all commands of the provided // devices. All Deinit functions are called, even if an error occurs. In this case // the an ModuleInitErr is returned that holds all errors reported by the modules. -func Deinit(devices dut.Devlist) error { +// +// ctx is the shutdown context; each module's Deinit receives a child of it +// carrying the module-scoped logger. It is a plain background context today — +// see the caller for where a shutdown deadline would attach. +func Deinit(ctx context.Context, devices dut.Devlist) error { var derr = &ModuleInitError{ Errs: make([]ModuleInitErrorDetails, 0), msg: "bad clean-up", } - log.Printf("GRACEFUL SHUTDOWN: De-init modules") + slog.Default().Info("graceful shutdown: deinitializing modules") for devname, device := range devices { for cmdname, cmd := range device.Cmds { for _, module := range cmd.Modules { - err := catchPanic(module.Deinit) + mlog := log.Scope(slog.Default(), "module").With("device", devname, "command", cmdname, "module", module.Config.Name) + mctx := log.Into(ctx, mlog) + + mlog.Debug("deinitializing module") + + err := catchPanic(func() error { return module.Deinit(mctx) }) if err != nil { derr.Errs = append(derr.Errs, ModuleInitErrorDetails{ Dev: devname, @@ -117,7 +138,7 @@ func Deinit(devices dut.Devlist) error { return derr } - log.Print("All modules de-initialized") + slog.Default().Info("all modules deinitialized") return nil } diff --git a/internal/dutagent/locker.go b/internal/dutagent/locker.go index 96614cb5..628e3156 100644 --- a/internal/dutagent/locker.go +++ b/internal/dutagent/locker.go @@ -7,9 +7,11 @@ package dutagent import ( "errors" "fmt" - "log" + "log/slog" "sync" "time" + + "github.com/BlindspotSoftware/dutctl/internal/log" ) // Sentinel errors returned by Locker. @@ -115,6 +117,7 @@ type Locker struct { mu sync.Mutex explicit map[string]LockInfo auto map[string]LockInfo + log *slog.Logger } // NewLocker returns a ready-to-use Locker. @@ -122,6 +125,7 @@ func NewLocker() *Locker { return &Locker{ explicit: make(map[string]LockInfo), auto: make(map[string]LockInfo), + log: log.Scope(slog.Default(), "locker"), } } @@ -233,12 +237,12 @@ func (l *Locker) ForceClearLock(device string) error { } if hadExplicit { - log.Printf("Force-clearing explicit lock on device %q, previously held by %q", device, explicitInfo.Owner) + l.log.Warn("force-clearing lock", "kind", "explicit", "device", device, "previous_owner", explicitInfo.Owner) delete(l.explicit, device) } if hadAuto { - log.Printf("Force-clearing auto lock on device %q, previously held by %q", device, autoInfo.Owner) + l.log.Warn("force-clearing lock", "kind", "auto", "device", device, "previous_owner", autoInfo.Owner) delete(l.auto, device) } diff --git a/internal/dutagent/session.go b/internal/dutagent/session.go index d8ea6222..01dad768 100644 --- a/internal/dutagent/session.go +++ b/internal/dutagent/session.go @@ -5,11 +5,13 @@ package dutagent import ( + "errors" "fmt" "io" - "log" + "log/slog" "github.com/BlindspotSoftware/dutctl/internal/chanio" + "github.com/BlindspotSoftware/dutctl/internal/log" ) // session implements the module.Session interface. @@ -25,6 +27,20 @@ type session struct { // It is used for both, to indicate the file that was requested by the module // and the file that is being sent back to the client. currentFile string + + // log is the session-scoped logger, frozen in by the broker (see Broker.Start) + // because the module.Session methods carry no context to derive it from. + log *slog.Logger +} + +// logger returns the session's scoped logger, falling back to the default if +// the broker has not set one (e.g. a session built directly in a test). +func (s *session) logger() *slog.Logger { + if s.log != nil { + return s.log + } + + return slog.Default() } func (s *session) Print(a ...any) { @@ -47,19 +63,23 @@ func (s *session) Console() (stdin io.Reader, stdout, stderr io.Writer) { err error ) - stdinReader, err = chanio.NewChanReader(s.stdinCh) + // The channels are always initialized by Broker.init before a module runs, + // so a failure here is a broken invariant (a nil channel), not a runtime + // condition. Console has no error return, so panic; the module-execution + // goroutine recovers it into a clean run error (see executeModules). + stdinReader, err = chanio.NewChanReader(s.stdinCh, log.Scope(s.logger(), scopeSessionUpstream)) if err != nil { - log.Fatalf("session.Console() failed to create stdinReader: %v", err) + panic(fmt.Sprintf("session.Console: stdin reader: %v", err)) } stdoutWriter, err = chanio.NewChanWriter(s.stdoutCh) if err != nil { - log.Fatalf("session.Console() failed to create stdoutWriter: %v", err) + panic(fmt.Sprintf("session.Console: stdout writer: %v", err)) } stderrWriter, err = chanio.NewChanWriter(s.stderrCh) if err != nil { - log.Fatalf("session.Console() failed to create stderrWriter: %v", err) + panic(fmt.Sprintf("session.Console: stderr writer: %v", err)) } return stdinReader, stdoutWriter, stderrWriter @@ -67,18 +87,20 @@ func (s *session) Console() (stdin io.Reader, stdout, stderr io.Writer) { func (s *session) RequestFile(name string) (io.Reader, error) { if s.fileReqCh == nil { - log.Fatal("session.RequestFile() called but session.fileReq is nil") + return nil, errors.New("session not initialized: file request channel is nil") } - log.Printf("Module issued file request for: %q", name) + // Requesting and reading a file is the upstream (client → agent) flow. + up := log.Scope(s.logger(), scopeSessionUpstream) + up.Debug("module requested file", "name", name) s.fileReqCh <- name // Send the file request to the client. file := <-s.fileCh // This will block until the client sends the file. - r, err := chanio.NewChanReader(file) + r, err := chanio.NewChanReader(file, up) if err != nil { - log.Fatalf("session.RequestFile() failed to create reader: %v", err) + return nil, fmt.Errorf("request file %q: %w", name, err) } return r, nil @@ -86,7 +108,7 @@ func (s *session) RequestFile(name string) (io.Reader, error) { func (s *session) SendFile(name string, r io.Reader) error { if s.currentFile != "" { - log.Fatal("session.SendFile() called during a ongoing file request") + return fmt.Errorf("send file %q: a file request is already in progress", name) } content, err := io.ReadAll(r) @@ -94,7 +116,8 @@ func (s *session) SendFile(name string, r io.Reader) error { return err } - log.Printf("Module issued file transfer of : %q, with %d bytes", name, len(content)) + // Sending a file to the client is the downstream (agent → client) flow. + log.Scope(s.logger(), scopeSessionDownstream).Debug("module sending file", "name", name, "bytes", len(content)) s.currentFile = name diff --git a/internal/dutagent/worker.go b/internal/dutagent/worker.go index 62484fe9..793e0814 100644 --- a/internal/dutagent/worker.go +++ b/internal/dutagent/worker.go @@ -9,9 +9,9 @@ import ( "errors" "fmt" "io" - "log" "github.com/BlindspotSoftware/dutctl/internal/chanio" + "github.com/BlindspotSoftware/dutctl/internal/log" pb "github.com/BlindspotSoftware/dutctl/protobuf/gen/dutctl/v1" ) @@ -21,6 +21,8 @@ import ( // //nolint:cyclop, funlen func toClientWorker(ctx context.Context, stream Stream, s *session) error { + l := log.FromContext(ctx) + for { select { case <-ctx.Done(): @@ -64,7 +66,7 @@ func toClientWorker(ctx context.Context, stream Stream, s *session) error { s.currentFile = name case file := <-s.fileCh: - r, err := chanio.NewChanReader(file) + r, err := chanio.NewChanReader(file, l) if err != nil { return err } @@ -74,7 +76,7 @@ func toClientWorker(ctx context.Context, stream Stream, s *session) error { return err } - log.Printf("Received file from module, sending to client. Name: %q, Size %d", s.currentFile, len(content)) + l.Debug("file received from module", "name", s.currentFile, "bytes", len(content)) res := &pb.RunResponse{ Msg: &pb.RunResponse_File{ @@ -100,6 +102,8 @@ func toClientWorker(ctx context.Context, stream Stream, s *session) error { // //nolint:cyclop,funlen,gocognit func fromClientWorker(ctx context.Context, stream Stream, s *session) error { + l := log.FromContext(ctx) + type recvResult struct { req *pb.RunRequest err error @@ -153,7 +157,7 @@ func fromClientWorker(ctx context.Context, stream Stream, s *session) error { } if r.req == nil { // Defensive: shouldn't happen unless stream.Receive misbehaves - log.Println("Received nil request without error; ignoring") + l.Warn("ignoring nil request without error") continue } @@ -166,12 +170,12 @@ func fromClientWorker(ctx context.Context, stream Stream, s *session) error { case *pb.Console_Stdin: stdin := consoleMsg.Stdin if stdin == nil { - log.Println("Received nil stdin message") + l.Warn("ignoring nil stdin message") continue } - log.Printf("Server received stdin from client: %q", string(stdin)) + l.Debug("received stdin from client", "bytes", len(stdin)) select { case <-ctx.Done(): @@ -179,21 +183,19 @@ func fromClientWorker(ctx context.Context, stream Stream, s *session) error { case s.stdinCh <- stdin: } - log.Println("Passed stdin to module") - default: - log.Printf("Unexpected Console message %T", consoleMsg) + l.Warn("unexpected console message", "type", fmt.Sprintf("%T", consoleMsg)) } case *pb.RunRequest_File: fileMsg := msg.File if fileMsg == nil { - log.Println("Received empty file message") + l.Warn("bad file transfer: empty file message") return fmt.Errorf("bad file transfer: received empty file-message") } if s.currentFile == "" { - log.Println("Received file without a request") + l.Warn("bad file transfer: file without a request") return fmt.Errorf("bad file transfer: received file-message without a former request") } @@ -202,29 +204,28 @@ func fromClientWorker(ctx context.Context, stream Stream, s *session) error { content := fileMsg.GetContent() if content == nil { - log.Println("Received file message with empty content") + l.Warn("bad file transfer: file message with empty content") return fmt.Errorf("bad file transfer: received file-message without content") } if path != s.currentFile { - log.Printf("Received unexpected file %q - ignoring!", path) + l.Warn("bad file transfer: unexpected file", "received", path, "requested", s.currentFile) return fmt.Errorf("bad file transfer: received file-message %q but requested %q", path, s.currentFile) } - log.Printf("Server received file %q from client", path) + l.Debug("received file from client", "name", path, "bytes", len(content)) file := make(chan []byte, 1) s.fileCh <- file file <- content close(file) - log.Println("Passed file to module (buffered in the session)") s.currentFile = "" default: - log.Printf("Unexpected message type %T", msg) + l.Warn("unexpected message type", "type", fmt.Sprintf("%T", msg)) } } } diff --git a/internal/log/color_test.go b/internal/log/color_test.go new file mode 100644 index 00000000..ac51edda --- /dev/null +++ b/internal/log/color_test.go @@ -0,0 +1,86 @@ +// Copyright 2025 Blindspot Software +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package log + +import ( + "bytes" + "context" + "log/slog" + "strings" + "testing" + "time" +) + +// emit logs one record through a text handler with the given color setting and +// returns the written line. White-box so it can set color without a real TTY. +func emit(color bool, level slog.Level, msg string) string { + var buf bytes.Buffer + + h := newTextHandler(&buf, slog.LevelDebug, color) + rec := slog.NewRecord(time.Time{}, level, msg, 0) //nolint:exhaustruct + + _ = h.Handle(context.Background(), rec) + + return buf.String() +} + +func TestColorOnlyWhenEnabled(t *testing.T) { + if got := emit(false, slog.LevelError, "boom"); strings.Contains(got, "\x1b[") { + t.Errorf("color disabled, but line has ANSI codes: %q", got) + } + + got := emit(true, slog.LevelError, "boom") + if !strings.Contains(got, ansiRed) { + t.Errorf("color enabled for ERROR, want red %q in %q", ansiRed, got) + } + if !strings.Contains(got, ansiReset) { + t.Errorf("colored line must reset, missing %q in %q", ansiReset, got) + } +} + +func TestLevelColorBySeverity(t *testing.T) { + cases := map[slog.Level]string{ + slog.LevelDebug: ansiGray, + slog.LevelWarn: ansiYellow, + slog.LevelError: ansiRed, + } + for level, want := range cases { + if got := emit(true, level, "x"); !strings.Contains(got, want) { + t.Errorf("level %v: want color %q in %q", level, want, got) + } + } + + // INFO stays the terminal default. emit uses a zero timestamp (no dimmed + // time prefix), so an uncolored INFO line carries no ANSI codes at all. + got := emit(true, slog.LevelInfo, "x") + if strings.Contains(got, "\x1b[") { + t.Errorf("INFO level must be uncolored, got %q", got) + } +} + +func TestColorSpansWholeContent(t *testing.T) { + // For a colored level the message (not just the level token) is inside the + // colored span, i.e. the reset comes after the message. + got := emit(true, slog.LevelError, "boom") + + start := strings.Index(got, ansiRed) + msg := strings.Index(got, "boom") + reset := strings.LastIndex(got, ansiReset) + + if start < 0 || msg < 0 || reset < 0 || !(start < msg && msg < reset) { + t.Errorf("want red ... boom ... reset in order, got %q", got) + } +} + +func TestLevelPadding(t *testing.T) { + // INFO (4 chars) padded to width 5 then a separator space => two spaces. + if got := emit(false, slog.LevelInfo, "m"); !strings.Contains(got, "INFO m") { + t.Errorf("want padded %q in %q", "INFO m", got) + } + // ERROR (5 chars) needs no padding, just the separator space. + if got := emit(false, slog.LevelError, "m"); !strings.Contains(got, "ERROR m") { + t.Errorf("want %q in %q", "ERROR m", got) + } +} diff --git a/internal/log/log.go b/internal/log/log.go new file mode 100644 index 00000000..b23e2351 --- /dev/null +++ b/internal/log/log.go @@ -0,0 +1,377 @@ +// Copyright 2025 Blindspot Software +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package log provides structured logging for the dutagent and dutserver +// services, built on the standard library's log/slog. +// +// # Obtaining a logger +// +// A logger is carried through a request on its context.Context. Code retrieves +// it with FromContext and, at a component boundary, derives a child logger and +// stores it back with With (to add structured attributes) or WithScope (to set +// the scope). Because the context already flows through the agent's request +// path, a component can be given its logging context without changing call +// signatures, and each component then logs only its own concern while the +// surrounding attributes and scope are already attached. +// +// FromContext falls back to slog.Default(), so code that has no request context +// (process bootstrap, module Init/Deinit) still logs through the same backend. +// +// # Scope +// +// A scope identifies the component a log record originates from — the RPC layer, +// the session backend, a module, and so on. A scope is a single, flat label: +// setting a new scope replaces any previous one (scopes do not nest). Each +// component sets its own scope at its entry boundary. +// +// How the scope is rendered depends on the handler built by New: the text +// handler (human/TTY output) prepends it to the message as "[session] ...", +// while the JSON handler emits it as a "scope" attribute so it stays filterable. +package log + +import ( + "context" + "io" + "log/slog" + "os" + "strconv" + "strings" + "sync" +) + +// ScopeKey is the attribute key under which the scope is emitted by the JSON +// handler. +const ScopeKey = "scope" + +// ctxKey is the (unexported, collision-free) context key for the logger. +type ctxKey struct{} + +// FromContext returns the logger stored in ctx, or slog.Default() if none is +// set. It never returns nil, so callers can log unconditionally. +func FromContext(ctx context.Context) *slog.Logger { + if l, ok := ctx.Value(ctxKey{}).(*slog.Logger); ok { + return l + } + + return slog.Default() +} + +// Into returns a copy of ctx carrying l. Most call sites use With or WithScope +// instead; use Into directly to seed an externally built logger — for example a +// request logger in an interceptor, or a capturing logger in a test. +func Into(ctx context.Context, l *slog.Logger) context.Context { + return context.WithValue(ctx, ctxKey{}, l) +} + +// With returns a copy of ctx whose logger has the given attributes added. The +// arguments follow the slog key-value convention, e.g. With(ctx, "device", d). +func With(ctx context.Context, args ...any) context.Context { + return Into(ctx, FromContext(ctx).With(args...)) +} + +// WithScope returns a copy of ctx whose logger is scoped to name. Setting a new +// scope replaces any previous one; see Scope and the package documentation. +func WithScope(ctx context.Context, name string) context.Context { + return Into(ctx, Scope(FromContext(ctx), name)) +} + +// Scope returns a copy of l whose scope is set to name, replacing any existing +// scope. Use it when holding a *slog.Logger directly rather than a context; +// WithScope is the context-based equivalent used at component boundaries. +func Scope(l *slog.Logger, name string) *slog.Logger { + if h, ok := l.Handler().(*scopeHandler); ok { + return slog.New(&scopeHandler{inner: h.inner, scope: name, render: h.render}) + } + + return slog.New(&scopeHandler{inner: l.Handler(), scope: name}) +} + +// New builds a base logger writing to w. When json is false a text handler is +// used and the scope is rendered as a "[scope]" message prefix; when true a +// JSON handler is used and the scope is emitted as a ScopeKey attribute. +func New(w io.Writer, level slog.Leveler, json bool) *slog.Logger { + if level == nil { + level = slog.LevelInfo + } + + if json { + opts := &slog.HandlerOptions{Level: level} + + return slog.New(&scopeHandler{inner: slog.NewJSONHandler(w, opts), render: scopeAsAttr}) + } + + return slog.New(&scopeHandler{inner: newTextHandler(w, level, useColor(w)), render: scopeAsPrefix}) +} + +// useColor reports whether ANSI color should be emitted to w: only when w is a +// terminal (a character device) and the NO_COLOR convention is not set. +func useColor(w io.Writer) bool { + if os.Getenv("NO_COLOR") != "" { + return false + } + + f, ok := w.(*os.File) + if !ok { + return false + } + + info, err := f.Stat() + if err != nil { + return false + } + + return info.Mode()&os.ModeCharDevice != 0 +} + +// ParseLevel maps a level name (debug, info, warn, error; case-insensitive) to a +// slog.Level, returning LevelInfo for an empty or unrecognized value. +func ParseLevel(s string) slog.Level { + switch strings.ToLower(strings.TrimSpace(s)) { + case "debug": + return slog.LevelDebug + case "warn", "warning": + return slog.LevelWarn + case "error": + return slog.LevelError + default: + return slog.LevelInfo + } +} + +// scopeRender selects how a scope is rendered on a record. +type scopeRender int + +const ( + scopeAsPrefix scopeRender = iota // text: "[scope] msg" + scopeAsAttr // json: {"scope":"...", ...} +) + +// scopeHandler wraps a slog.Handler and renders the current scope on each +// record. It is immutable: Scope, WithAttrs and WithGroup all return a fresh +// handler, so a logger is safe to share across concurrent requests. +type scopeHandler struct { + inner slog.Handler + scope string + render scopeRender +} + +func (h *scopeHandler) Enabled(ctx context.Context, level slog.Level) bool { + return h.inner.Enabled(ctx, level) +} + +func (h *scopeHandler) Handle(ctx context.Context, r slog.Record) error { + if h.scope != "" { + switch h.render { + case scopeAsPrefix: + r.Message = "[" + h.scope + "] " + r.Message + case scopeAsAttr: + r.AddAttrs(slog.String(ScopeKey, h.scope)) + } + } + + return h.inner.Handle(ctx, r) +} + +func (h *scopeHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &scopeHandler{inner: h.inner.WithAttrs(attrs), scope: h.scope, render: h.render} +} + +func (h *scopeHandler) WithGroup(name string) slog.Handler { + return &scopeHandler{inner: h.inner.WithGroup(name), scope: h.scope, render: h.render} +} + +// timeFormat is the timestamp layout for the human-readable text handler. It +// mirrors the standard library log package's default (date and clock, without +// sub-seconds or timezone). +const timeFormat = "2006/01/02 15:04:05" + +// levelWidth is the column width the level name is padded to, so messages align +// regardless of level. It is the width of the longest standard name (DEBUG/ERROR). +const levelWidth = 5 + +// ANSI color codes used by the text handler when writing to a terminal. +const ( + ansiReset = "\x1b[0m" + ansiRed = "\x1b[31m" + ansiYellow = "\x1b[33m" + ansiGray = "\x1b[90m" +) + +// levelColor returns the ANSI color for a level by severity, or "" for INFO, +// which stays in the terminal's default color (it is the common case). +func levelColor(l slog.Level) string { + switch { + case l >= slog.LevelError: + return ansiRed + case l >= slog.LevelWarn: + return ansiYellow + case l < slog.LevelInfo: + return ansiGray + default: + return "" + } +} + +// textHandler is a slog.Handler that writes compact, human-readable lines: +// +// 2006/01/02 15:04:05 LEVEL message key=value key=value +// +// It is the non-JSON handler built by New. The scope is supplied by the +// wrapping scopeHandler as a "[scope] " message prefix, so it appears right +// after the level. The level is padded for alignment and, when color is set +// (w is a terminal), the timestamp is dimmed and the level colored by severity. +// Records are written under a shared mutex so concurrent goroutines never +// interleave partial lines. +type textHandler struct { + mu *sync.Mutex + w io.Writer + level slog.Leveler + color bool + attrs string // preformatted " key=value" pairs carried from WithAttrs + group string // dotted key prefix carried from WithGroup, e.g. "outer.inner." +} + +func newTextHandler(w io.Writer, level slog.Leveler, color bool) *textHandler { + return &textHandler{mu: &sync.Mutex{}, w: w, level: level, color: color} +} + +func (h *textHandler) Enabled(_ context.Context, l slog.Level) bool { + return l >= h.level.Level() +} + +func (h *textHandler) Handle(_ context.Context, r slog.Record) error { + var b strings.Builder + + // The timestamp is always dimmed (when color is on); it is metadata that + // should recede on every line, regardless of level. + if !r.Time.IsZero() { + ts := r.Time.Format(timeFormat) + if h.color { + b.WriteString(ansiGray) + b.WriteString(ts) + b.WriteString(ansiReset) + } else { + b.WriteString(ts) + } + + b.WriteByte(' ') + } + + // The rest of the line (level, message and attributes) shares the level's + // color, so the whole content is colored. INFO has no color and stays the + // terminal default. + color := "" + if h.color { + color = levelColor(r.Level) + } + + if color != "" { + b.WriteString(color) + } + + levelText := r.Level.String() + b.WriteString(levelText) + + for i := len(levelText); i < levelWidth; i++ { + b.WriteByte(' ') // pad shorter level names to align the message column + } + + b.WriteByte(' ') + b.WriteString(r.Message) + b.WriteString(h.attrs) + + r.Attrs(func(a slog.Attr) bool { + appendAttr(&b, h.group, a) + + return true + }) + + if color != "" { + b.WriteString(ansiReset) + } + + b.WriteByte('\n') + + h.mu.Lock() + defer h.mu.Unlock() + + _, err := io.WriteString(h.w, b.String()) + + return err +} + +func (h *textHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + + var b strings.Builder + + b.WriteString(h.attrs) + + for _, a := range attrs { + appendAttr(&b, h.group, a) + } + + return &textHandler{mu: h.mu, w: h.w, level: h.level, color: h.color, attrs: b.String(), group: h.group} +} + +func (h *textHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + + return &textHandler{mu: h.mu, w: h.w, level: h.level, color: h.color, attrs: h.attrs, group: h.group + name + "."} +} + +// appendAttr writes " key=value" for a, prefixing the key with group and +// flattening nested groups. Empty attributes are skipped, matching slog's own +// text handler. +func appendAttr(b *strings.Builder, group string, a slog.Attr) { + a.Value = a.Value.Resolve() + + if a.Equal(slog.Attr{}) { + return + } + + if a.Value.Kind() == slog.KindGroup { + attrs := a.Value.Group() + if len(attrs) == 0 { + return + } + + prefix := group + if a.Key != "" { + prefix = group + a.Key + "." + } + + for _, ga := range attrs { + appendAttr(b, prefix, ga) + } + + return + } + + b.WriteByte(' ') + b.WriteString(group) + b.WriteString(a.Key) + b.WriteByte('=') + b.WriteString(quoteIfNeeded(a.Value.String())) +} + +// quoteIfNeeded wraps s in double quotes when it is empty or contains +// whitespace, '=' or control characters, so the value stays a single token. +func quoteIfNeeded(s string) string { + if s == "" { + return `""` + } + + for _, r := range s { + if r <= ' ' || r == '=' || r == '"' { + return strconv.Quote(s) + } + } + + return s +} diff --git a/internal/log/log_test.go b/internal/log/log_test.go new file mode 100644 index 00000000..d5bc213f --- /dev/null +++ b/internal/log/log_test.go @@ -0,0 +1,132 @@ +// Copyright 2025 Blindspot Software +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package log_test + +import ( + "bytes" + "context" + "log/slog" + "regexp" + "strings" + "testing" + + "github.com/BlindspotSoftware/dutctl/internal/log" +) + +// newCtx returns a context carrying a logger that writes to buf, using New so +// the scope-rendering handler is exercised. +func newCtx(buf *bytes.Buffer, json bool) context.Context { + return log.Into(context.Background(), log.New(buf, slog.LevelDebug, json)) +} + +func TestFromContextFallsBackToDefault(t *testing.T) { + if got := log.FromContext(context.Background()); got != slog.Default() { + t.Errorf("FromContext on empty context = %p, want slog.Default() %p", got, slog.Default()) + } +} + +func TestTextScopeRendersAsPrefix(t *testing.T) { + var buf bytes.Buffer + ctx := newCtx(&buf, false) + + ctx = log.WithScope(ctx, "session") + log.FromContext(ctx).Info("connected") + + if out := buf.String(); !strings.Contains(out, "[session] connected") { + t.Errorf("text output = %q, want it to contain %q", out, "[session] connected") + } +} + +func TestJSONScopeRendersAsAttribute(t *testing.T) { + var buf bytes.Buffer + ctx := newCtx(&buf, true) + + ctx = log.WithScope(ctx, "session") + log.FromContext(ctx).Info("connected") + + out := buf.String() + if !strings.Contains(out, `"scope":"session"`) { + t.Errorf("json output = %q, want it to contain %q", out, `"scope":"session"`) + } + if !strings.Contains(out, `"msg":"connected"`) { + t.Errorf("json output = %q, want msg without a prefix", out) + } +} + +func TestNewScopeReplacesPrevious(t *testing.T) { + var buf bytes.Buffer + ctx := newCtx(&buf, false) + + ctx = log.WithScope(ctx, "rpc") + ctx = log.WithScope(ctx, "session") // replaces "rpc", does not nest + log.FromContext(ctx).Info("hello") + + out := buf.String() + if !strings.Contains(out, "[session] hello") { + t.Errorf("output = %q, want it to contain %q", out, "[session] hello") + } + if strings.Contains(out, "rpc") { + t.Errorf("output = %q, want previous scope %q to be replaced", out, "rpc") + } +} + +func TestWithAttributesSurviveScope(t *testing.T) { + var buf bytes.Buffer + ctx := newCtx(&buf, false) + + ctx = log.With(ctx, "device", "dut-1") + ctx = log.WithScope(ctx, "module") // scope change must keep earlier attributes + log.FromContext(ctx).Info("running") + + out := buf.String() + if !strings.Contains(out, "[module] running") { + t.Errorf("output = %q, want scope prefix", out) + } + if !strings.Contains(out, "device=dut-1") { + t.Errorf("output = %q, want attribute device=dut-1 to survive the scope change", out) + } +} + +func TestTextHandlerFormat(t *testing.T) { + var buf bytes.Buffer + ctx := newCtx(&buf, false) + + ctx = log.WithScope(ctx, "svc") + log.FromContext(ctx).Info("hello there", "code", 7, "note", "with space") + + out := strings.TrimRight(buf.String(), "\n") + + // Shape: "2006/01/02 15:04:05 INFO [svc] hello there code=7 note=..." + // (INFO is padded to width 5, so two spaces precede the scope.) A plain + // bytes.Buffer is not a terminal, so no color codes are emitted. + want := regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} INFO {2}\[svc\] hello there code=7 note="with space"$`) + if !want.MatchString(out) { + t.Errorf("text line = %q, want it to match %v", out, want) + } + + // The compact format must not carry slog's machine-style time=/level=/msg= keys. + for _, bad := range []string{"time=", "level=", "msg="} { + if strings.Contains(out, bad) { + t.Errorf("text line = %q, must not contain %q", out, bad) + } + } +} + +func TestParseLevel(t *testing.T) { + cases := map[string]slog.Level{ + "debug": slog.LevelDebug, + "INFO": slog.LevelInfo, + "Warn": slog.LevelWarn, + "warning": slog.LevelWarn, + "error": slog.LevelError, + "": slog.LevelInfo, + "bogus": slog.LevelInfo, + } + for in, want := range cases { + if got := log.ParseLevel(in); got != want { + t.Errorf("ParseLevel(%q) = %v, want %v", in, got, want) + } + } +} diff --git a/pkg/dut/dut_test.go b/pkg/dut/dut_test.go index 8260ff1a..f96144ea 100644 --- a/pkg/dut/dut_test.go +++ b/pkg/dut/dut_test.go @@ -265,8 +265,8 @@ type helpModule struct { } func (m *helpModule) Help() string { return m.text } -func (m *helpModule) Init() error { return nil } -func (m *helpModule) Deinit() error { return nil } +func (m *helpModule) Init(_ context.Context) error { return nil } +func (m *helpModule) Deinit(_ context.Context) error { return nil } func (m *helpModule) Run(_ context.Context, _ module.Session, _ ...string) error { return nil } func TestHelpText(t *testing.T) { diff --git a/pkg/module/agent/status.go b/pkg/module/agent/status.go index c8d0d617..a2c7475e 100644 --- a/pkg/module/agent/status.go +++ b/pkg/module/agent/status.go @@ -7,7 +7,6 @@ package agent import ( "context" "fmt" - "log" "os/exec" "strings" @@ -28,26 +27,18 @@ type Status struct{} var _ module.Module = &Status{} func (m *Status) Help() string { - log.Println("agent.Status module: Help called") - return "Get status information about the system on which dutagent is running. No Arguments required." } -func (m *Status) Init() error { - log.Println("agent.Status module: Init called") - +func (m *Status) Init(_ context.Context) error { return nil } -func (m *Status) Deinit() error { - log.Println("agent.Status module: Deinit called") - +func (m *Status) Deinit(_ context.Context) error { return nil } func (m *Status) Run(_ context.Context, s module.Session, _ ...string) error { - log.Println("agent.Status module: Run called") - var out strings.Builder //nolint:noctx diff --git a/pkg/module/dummy/dummy_file_transfer.go b/pkg/module/dummy/dummy_file_transfer.go index 3e275497..da981a2d 100644 --- a/pkg/module/dummy/dummy_file_transfer.go +++ b/pkg/module/dummy/dummy_file_transfer.go @@ -10,10 +10,11 @@ import ( "fmt" "io" "io/fs" - "log" + "log/slog" "os" "path/filepath" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -32,25 +33,21 @@ type FT struct{} var _ module.Module = &FT{} func (d *FT) Help() string { - log.Println("dummy.FT module: Help called") - return "This dummy module demonstrates file transfer." } -func (d *FT) Init() error { - log.Println("dummy.FT module: Init called") - +func (d *FT) Init(_ context.Context) error { return nil } -func (d *FT) Deinit() error { - log.Println("dummy.FT module: Deinit called") - +func (d *FT) Deinit(_ context.Context) error { return nil } -func (d *FT) Run(_ context.Context, s module.Session, args ...string) error { - log.Println("dummy.FT module: Run called") +func (d *FT) Run(ctx context.Context, s module.Session, args ...string) error { + // The logger on ctx is already scoped to this module by the agent; the + // module just logs what it does and passes the logger to its helpers. + l := log.FromContext(ctx) s.Println("Hello from dummy file transfer module") s.Printf("Called with %d arguments\n", len(args)) @@ -68,14 +65,14 @@ func (d *FT) Run(_ context.Context, s module.Session, args ...string) error { return fmt.Errorf("file request failed: %v", err) } - log.Printf("dummy.FT module: Reading file: %s", inFile) + l.Debug(fmt.Sprintf("reading input file %q", inFile)) raw, err := io.ReadAll(fileReader) if err != nil { return fmt.Errorf("failed to read file: %v", err) } - err = save(raw, inFile) + err = save(l, raw, inFile) if err != nil { return fmt.Errorf("failed to save file: %v", err) } @@ -86,21 +83,19 @@ func (d *FT) Run(_ context.Context, s module.Session, args ...string) error { } outFile := args[1] - log.Printf("dummy.FT module: Sending back processed file %q", outFile) err = s.SendFile(outFile, bytes.NewBuffer(result)) if err != nil { return fmt.Errorf("failed to send file: %v", err) } + l.Info(fmt.Sprintf("processed and returned %q", outFile)) s.Printf("File operated successfully, delivered %q as passed in arg[1] as output\n", outFile) return nil } -func save(raw []byte, path string) error { - log.Printf("dummy.FT module: Save received content on disk") - +func save(l *slog.Logger, raw []byte, path string) error { dir, err := os.MkdirTemp("", "dutagent-out") if err != nil { return fmt.Errorf("failed to create temp dir: %v", err) @@ -115,14 +110,12 @@ func save(raw []byte, path string) error { return fmt.Errorf("failed to write file: %v", err) } - log.Printf("dummy.FT module: Wrote file to: %s", dest) + l.Debug(fmt.Sprintf("wrote received file to %q", dest)) return nil } func process(input []byte) ([]byte, error) { - log.Printf("dummy.FT module: Process received content") - if len(input) == 0 { return nil, fmt.Errorf("empty input") } @@ -130,7 +123,5 @@ func process(input []byte) ([]byte, error) { // Dummy processing input = append(input, []byte("\n\nprocessed by dummy.FT module\n")...) - log.Printf("dummy.FT module: Processed content") - return input, nil } diff --git a/pkg/module/dummy/dummy_repeat.go b/pkg/module/dummy/dummy_repeat.go index fbcdb9f4..ce10998d 100644 --- a/pkg/module/dummy/dummy_repeat.go +++ b/pkg/module/dummy/dummy_repeat.go @@ -7,7 +7,6 @@ package dummy import ( "bufio" "context" - "log" "strings" "github.com/BlindspotSoftware/dutctl/pkg/module" @@ -28,32 +27,22 @@ type Repeat struct{} var _ module.Module = &Repeat{} func (d *Repeat) Help() string { - log.Println("dummy.Repeat module: Help called") - return "This dummy module repeats the input from the client." } -func (d *Repeat) Init() error { - log.Println("dummy.Repeat module: Init called") - +func (d *Repeat) Init(_ context.Context) error { return nil } -func (d *Repeat) Deinit() error { - log.Println("dummy.Repeat module: Deinit called") - +func (d *Repeat) Deinit(_ context.Context) error { return nil } func (d *Repeat) Run(_ context.Context, s module.Session, _ ...string) error { - log.Println("dummy.Repeat module: Run called") - cin, cout, cerr := s.Console() _, err := cout.Write([]byte("Hello from dummy repeat module!\nEnter one word per line. (Two words will terminate)\n")) if err != nil { - log.Println("dummy.Repeat module: error writing to client: ", err) - return err } @@ -62,8 +51,6 @@ func (d *Repeat) Run(_ context.Context, s module.Session, _ ...string) error { for { line, err := r.ReadString('\n') if err != nil { - log.Println("dummy.Repeat module: error reading from client: ", err) - return err } @@ -73,8 +60,6 @@ func (d *Repeat) Run(_ context.Context, s module.Session, _ ...string) error { if len(words) > 1 { _, err = cerr.Write([]byte("Oh no! Can only handle one word per line.\n")) if err != nil { - log.Println("dummy.Repeat module: error writing to client: ", err) - return err } @@ -83,8 +68,6 @@ func (d *Repeat) Run(_ context.Context, s module.Session, _ ...string) error { _, err = cout.Write([]byte(words[0] + "\n")) if err != nil { - log.Println("dummy.Repeat module: error writing to client: ", err) - return err } } diff --git a/pkg/module/dummy/dummy_status.go b/pkg/module/dummy/dummy_status.go index f144bf38..d0ef9fdd 100644 --- a/pkg/module/dummy/dummy_status.go +++ b/pkg/module/dummy/dummy_status.go @@ -6,7 +6,6 @@ package dummy import ( "context" - "log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -26,26 +25,18 @@ type Status struct{} var _ module.Module = &Status{} func (d *Status) Help() string { - log.Println("dummy.Status module: Help called") - return "This dummy module prints status information about itself and the environment." } -func (d *Status) Init() error { - log.Println("dummy.Status module: Init called") - +func (d *Status) Init(_ context.Context) error { return nil } -func (d *Status) Deinit() error { - log.Println("dummy.Status module: Deinit called") - +func (d *Status) Deinit(_ context.Context) error { return nil } func (d *Status) Run(_ context.Context, s module.Session, args ...string) error { - log.Println("dummy.Status module: Run called") - s.Println("Hello from dummy status module") s.Printf("Called with %d arguments\n", len(args)) diff --git a/pkg/module/file/file.go b/pkg/module/file/file.go index c7eb30e4..8cdabd59 100644 --- a/pkg/module/file/file.go +++ b/pkg/module/file/file.go @@ -10,12 +10,12 @@ import ( "fmt" "io" "io/fs" - "log" "os" "path/filepath" "strconv" "strings" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -90,8 +90,6 @@ ARGUMENTS: ) func (f *File) Help() string { - log.Println("file module: Help called") - help := strings.Builder{} help.WriteString(abstract) @@ -149,9 +147,7 @@ func usageAndDescription(operation, source, destination string) string { } } -func (f *File) Init() error { - log.Println("file module: Init called") - +func (f *File) Init(ctx context.Context) error { if f.Permission != "" { // Permission must start with "0" to indicate octal format if f.Permission[0] != '0' { @@ -164,6 +160,7 @@ func (f *File) Init() error { } } else { f.Permission = "0" + strconv.FormatInt(int64(DefaultFilePerm), 8) + log.FromContext(ctx).Debug("no permission configured, using default " + f.Permission) } // Validate operation is set @@ -179,15 +176,11 @@ func (f *File) Init() error { return nil } -func (f *File) Deinit() error { - log.Println("file module: Deinit called") - +func (f *File) Deinit(_ context.Context) error { return nil } -func (f *File) Run(_ context.Context, sesh module.Session, args ...string) error { - log.Println("file module: Run called") - +func (f *File) Run(ctx context.Context, sesh module.Session, args ...string) error { // Parse paths err := f.parsePaths(args) if err != nil { @@ -196,17 +189,18 @@ func (f *File) Run(_ context.Context, sesh module.Session, args ...string) error switch f.Operation { case string(opUpload): - return f.uploadFile(sesh) + return f.uploadFile(ctx, sesh) case string(opDownload): - return f.downloadFile(sesh) + return f.downloadFile(ctx, sesh) default: return fmt.Errorf("invalid operation %q: must be 'upload' or 'download'", f.Operation) } } // uploadFile handles uploading a file from client to dutagent. -func (f *File) uploadFile(sesh module.Session) error { - log.Printf("file module: Uploading %q from client to %q on dutagent", f.sourcePath, f.destPath) +func (f *File) uploadFile(ctx context.Context, sesh module.Session) error { + l := log.FromContext(ctx) + l.Debug(fmt.Sprintf("uploading %q from client to %q on dutagent", f.sourcePath, f.destPath)) // Request file from client fileReader, err := sesh.RequestFile(f.sourcePath) @@ -251,15 +245,16 @@ func (f *File) uploadFile(sesh module.Session) error { return fmt.Errorf("failed to write file data: %w", copyErr) } - log.Printf("file module: Successfully uploaded %d bytes to %q", bytesWritten, f.destPath) + l.Info(fmt.Sprintf("uploaded %d bytes to %q", bytesWritten, f.destPath)) sesh.Printf("Upload complete: %s -> %s (%d bytes)\n", f.sourcePath, f.destPath, bytesWritten) return nil } // downloadFile handles downloading a file from dutagent to client. -func (f *File) downloadFile(sesh module.Session) error { - log.Printf("file module: Downloading %q from dutagent to %q on client", f.sourcePath, f.destPath) +func (f *File) downloadFile(ctx context.Context, sesh module.Session) error { + l := log.FromContext(ctx) + l.Debug(fmt.Sprintf("downloading %q from dutagent to %q on client", f.sourcePath, f.destPath)) // Validate source file exists fileInfo, err := os.Stat(f.sourcePath) @@ -284,7 +279,7 @@ func (f *File) downloadFile(sesh module.Session) error { return fmt.Errorf("failed to send file to client: %w", err) } - log.Printf("file module: Successfully downloaded %d bytes from %q", fileInfo.Size(), f.sourcePath) + l.Info(fmt.Sprintf("downloaded %d bytes from %q", fileInfo.Size(), f.sourcePath)) sesh.Printf("Download complete: %s -> %s (%d bytes)\n", f.sourcePath, f.destPath, fileInfo.Size()) return nil diff --git a/pkg/module/file/file_test.go b/pkg/module/file/file_test.go index d3c3c1ab..69bc3970 100644 --- a/pkg/module/file/file_test.go +++ b/pkg/module/file/file_test.go @@ -5,6 +5,7 @@ package file import ( + "context" "strings" "testing" @@ -217,7 +218,7 @@ func TestInit(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - err := tt.file.Init() + err := tt.file.Init(context.Background()) if (err != nil) != tt.wantErr { t.Errorf("Init() error = %v, wantErr %v", err, tt.wantErr) return diff --git a/pkg/module/flash-emulate/flash-emulate.go b/pkg/module/flash-emulate/flash-emulate.go index e41f949d..c3fb13b8 100644 --- a/pkg/module/flash-emulate/flash-emulate.go +++ b/pkg/module/flash-emulate/flash-emulate.go @@ -11,11 +11,11 @@ import ( "errors" "fmt" "io" - "log" "os" "os/exec" "strings" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -74,8 +74,6 @@ from Dediprog) must be connected to the DUT's SPI flash bus. ` func (e *FlashEmulate) Help() string { - log.Println("flash-emulate module: Help called") - help := strings.Builder{} help.WriteString(abstract) help.WriteString(usage) @@ -89,14 +87,13 @@ func (e *FlashEmulate) Help() string { return help.String() } -func (e *FlashEmulate) Init() error { - log.Println("flash-emulate module: Init called") - +func (e *FlashEmulate) Init(ctx context.Context) error { if e.Tool == "" { e.Tool = defaultTool + log.FromContext(ctx).Debug("no tool configured, using default " + defaultTool) } - _, err := exec.LookPath(e.Tool) + toolPath, err := exec.LookPath(e.Tool) if err != nil { return fmt.Errorf("emulation tool %q: %w", e.Tool, err) } @@ -105,17 +102,17 @@ func (e *FlashEmulate) Init() error { return errors.New("chip must be configured (e.g. \"N25Q256A13\")") } + log.FromContext(ctx).Debug(fmt.Sprintf("using emulation tool %s at %s", e.Tool, toolPath)) + return nil } -func (e *FlashEmulate) Deinit() error { - log.Println("flash-emulate module: Deinit called") - +func (e *FlashEmulate) Deinit(_ context.Context) error { return os.RemoveAll(e.localImagePath) } -func (e *FlashEmulate) Run(_ context.Context, sesh module.Session, args ...string) error { - log.Println("flash-emulate module: Run called") +func (e *FlashEmulate) Run(ctx context.Context, sesh module.Session, args ...string) error { + l := log.FromContext(ctx) if len(args) < 1 { return errors.New("missing argument: image file path") @@ -155,7 +152,8 @@ func (e *FlashEmulate) Run(_ context.Context, sesh module.Session, args ...strin cmdArgs := e.cmdline() - log.Printf("flash-emulate module: Executing command: %s %s", e.Tool, strings.Join(cmdArgs, " ")) + l.Info(fmt.Sprintf("loading image into emulator with %s", e.Tool)) + l.Debug(fmt.Sprintf("executing %s %s", e.Tool, strings.Join(cmdArgs, " "))) sesh.Print(fmt.Sprintf("Executing: %s %s", e.Tool, strings.Join(cmdArgs, " "))) err = execute(sesh, e.Tool, cmdArgs...) @@ -222,7 +220,6 @@ func execute(sesh module.Session, tool string, args ...string) error { output, err := cmd.CombinedOutput() if len(output) > 0 { - log.Printf("flash-emulate module: tool output:\n%s", output) sesh.Print(string(output)) } diff --git a/pkg/module/flash-emulate/flash-emulate_test.go b/pkg/module/flash-emulate/flash-emulate_test.go index 88de16eb..6efac801 100644 --- a/pkg/module/flash-emulate/flash-emulate_test.go +++ b/pkg/module/flash-emulate/flash-emulate_test.go @@ -17,30 +17,30 @@ import ( func TestInit(t *testing.T) { tests := []struct { - name string + name string flashEmulate FlashEmulate - expectErr bool + expectErr bool }{ { - name: "valid config", + name: "valid config", flashEmulate: FlashEmulate{Tool: "/bin/sh", Chip: "N25Q256A13"}, - expectErr: false, + expectErr: false, }, { - name: "missing chip", + name: "missing chip", flashEmulate: FlashEmulate{Tool: "/bin/sh"}, - expectErr: true, + expectErr: true, }, { - name: "tool not found", + name: "tool not found", flashEmulate: FlashEmulate{Tool: "this-tool-does-not-exist-xyzabc123", Chip: "N25Q256A13"}, - expectErr: true, + expectErr: true, }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - err := tt.flashEmulate.Init() + err := tt.flashEmulate.Init(context.Background()) if (err != nil) != tt.expectErr { t.Errorf("unexpected error state (wantErr=%v): %v", tt.expectErr, err) } @@ -61,7 +61,7 @@ func TestInitDefaultTool(t *testing.T) { e := FlashEmulate{Chip: "N25Q256A13"} - if err := e.Init(); err != nil { + if err := e.Init(context.Background()); err != nil { t.Errorf("unexpected error: %v", err) } @@ -73,7 +73,7 @@ func TestInitDefaultTool(t *testing.T) { func TestDeinit(t *testing.T) { t.Run("no image to clean up", func(t *testing.T) { e := FlashEmulate{} - if err := e.Deinit(); err != nil { + if err := e.Deinit(context.Background()); err != nil { t.Errorf("unexpected error: %v", err) } }) @@ -87,7 +87,7 @@ func TestDeinit(t *testing.T) { f.Close() e := FlashEmulate{localImagePath: f.Name()} - if err := e.Deinit(); err != nil { + if err := e.Deinit(context.Background()); err != nil { t.Errorf("unexpected error: %v", err) } @@ -99,16 +99,16 @@ func TestDeinit(t *testing.T) { func TestRun(t *testing.T) { tests := []struct { - name string + name string flashEmulate FlashEmulate - args []string - expectErr bool + args []string + expectErr bool }{ { - name: "missing image argument", + name: "missing image argument", flashEmulate: FlashEmulate{Tool: "/bin/sh", Chip: "N25Q256A13"}, - args: []string{}, - expectErr: true, + args: []string{}, + expectErr: true, }, } @@ -150,7 +150,7 @@ func TestRun(t *testing.T) { t.Errorf("expected requested file name %q, got %q", "firmware.rom", sesh.RequestedFileName) } - if err := e.Deinit(); err != nil { + if err := e.Deinit(context.Background()); err != nil { t.Errorf("unexpected Deinit error: %v", err) } }) @@ -221,7 +221,7 @@ func TestRun(t *testing.T) { t.Errorf("expected first temp file %q to be cleaned up before second run", firstPath) } - if err := e.Deinit(); err != nil { + if err := e.Deinit(context.Background()); err != nil { t.Errorf("unexpected Deinit error: %v", err) } }) @@ -274,9 +274,9 @@ func TestHelp(t *testing.T) { func TestCmdline(t *testing.T) { tests := []struct { - name string + name string flashEmulate FlashEmulate - expected []string + expected []string }{ { name: "basic cmdline without device", diff --git a/pkg/module/flash/flash.go b/pkg/module/flash/flash.go index 449f30fb..7565c30d 100644 --- a/pkg/module/flash/flash.go +++ b/pkg/module/flash/flash.go @@ -11,7 +11,6 @@ import ( "errors" "fmt" "io" - "log" "os" "os/exec" "path/filepath" @@ -19,6 +18,7 @@ import ( "strings" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -87,8 +87,6 @@ the DUT. ` func (f *Flash) Help() string { - log.Println("flash module: Help called") - help := strings.Builder{} help.WriteString(abstract) help.WriteString(usage) @@ -98,9 +96,7 @@ func (f *Flash) Help() string { return help.String() } -func (f *Flash) Init() error { - log.Println("flash module: Init called") - +func (f *Flash) Init(ctx context.Context) error { if f.Tool == "" { return fmt.Errorf("tool must be configured; supported tools are %v", f.supportedTools) } @@ -109,11 +105,13 @@ func (f *Flash) Init() error { return fmt.Errorf("%q unsupported; supported tools are %v", f.Tool, f.supportedTools) } - _, err := exec.LookPath(f.Tool) + toolPath, err := exec.LookPath(f.Tool) if err != nil { return fmt.Errorf("flash tool %q: %w", f.Tool, err) } + log.FromContext(ctx).Debug(fmt.Sprintf("using flash tool %s at %s", f.Tool, toolPath)) + // dpcmd auto-detects hardware, so programmer is optional // flashrom/flashprog require a programmer to be specified base := filepath.Base(f.Tool) @@ -130,15 +128,13 @@ func (f *Flash) isSupported(tool string) bool { return slices.Contains(f.supportedTools, base) } -func (f *Flash) Deinit() error { - log.Println("flash module: Deinit called") - +func (f *Flash) Deinit(_ context.Context) error { return os.RemoveAll(f.localImagePath) } //nolint:cyclop -func (f *Flash) Run(_ context.Context, sesh module.Session, args ...string) error { - log.Println("flash module: Run called") +func (f *Flash) Run(ctx context.Context, sesh module.Session, args ...string) error { + l := log.FromContext(ctx) if len(args) < 1 { return errors.New("missing argument: flash operation") @@ -168,9 +164,16 @@ func (f *Flash) Run(_ context.Context, sesh module.Session, args ...string) erro } } + action := "reading" + if f.op == opWrite { + action = "writing" + } + + l.Info(fmt.Sprintf("%s flash with %s", action, f.Tool)) + cmdStr := fmt.Sprintf("%s %s", f.Tool, strings.Join(f.cmdline(), " ")) - log.Printf("flash module: Executing command: %s", cmdStr) + l.Debug(fmt.Sprintf("executing %s", cmdStr)) sesh.Print(fmt.Sprintf("Executing: %s", cmdStr)) err := execute(sesh, f.Tool, f.cmdline()...) diff --git a/pkg/module/gpio/gpio.go b/pkg/module/gpio/gpio.go index 76ac2bf7..52665f83 100644 --- a/pkg/module/gpio/gpio.go +++ b/pkg/module/gpio/gpio.go @@ -11,10 +11,10 @@ package gpio import ( "context" "fmt" - "log" "strings" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -102,8 +102,6 @@ other modules or otherwise occupied by the system! ` func (b *Button) Help() string { - log.Println("gpio.Button module: Help called") - help := strings.Builder{} help.WriteString(abstractButton) help.WriteString(usageButton) @@ -123,11 +121,11 @@ func (b *Button) Help() string { return help.String() } -func (b *Button) Init() error { - log.Println("gpio.Button module: Init called") - +func (b *Button) Init(ctx context.Context) error { b.gpio = b.backendParser(b.Backend) + log.FromContext(ctx).Debug(fmt.Sprintf("initializing pin %d to idle", b.Pin)) + if b.ActiveLow { // with active low, idle is high return b.High(b.Pin) @@ -136,9 +134,7 @@ func (b *Button) Init() error { return b.Low(b.Pin) } -func (b *Button) Deinit() error { - log.Println("gpio.Button module: Deinit called") - +func (b *Button) Deinit(_ context.Context) error { if b.gpio == nil { return nil } @@ -146,9 +142,7 @@ func (b *Button) Deinit() error { return b.Low(b.Pin) } -func (b *Button) Run(_ context.Context, s module.Session, args ...string) error { - log.Println("gpio.Button module: Run called") - +func (b *Button) Run(ctx context.Context, s module.Session, args ...string) error { var ( duration time.Duration err error @@ -175,6 +169,7 @@ func (b *Button) Run(_ context.Context, s module.Session, args ...string) error return err } + log.FromContext(ctx).Info(fmt.Sprintf("button press for %s (pin %d)", duration, b.Pin)) s.Printf("Button pressed for %s\n", duration) return nil @@ -225,8 +220,6 @@ other modules or otherwise occupied by the system! ` func (s *Switch) Help() string { - log.Println("gpio.Switch module: Help called") - help := strings.Builder{} help.WriteString(abstractSwitch) help.WriteString(usageSwitch) @@ -244,26 +237,24 @@ func (s *Switch) Help() string { return help.String() } -func (s *Switch) Init() error { - log.Println("gpio.Switch module: Init called") - +func (s *Switch) Init(ctx context.Context) error { s.gpio = s.backendParser(s.Backend) initial := strings.ToLower(s.Initial) if initial == "on" { s.state = on + log.FromContext(ctx).Debug(fmt.Sprintf("initializing pin %d to on", s.Pin)) return s.on() } s.state = off + log.FromContext(ctx).Debug(fmt.Sprintf("initializing pin %d to off", s.Pin)) return s.off() } -func (s *Switch) Deinit() error { - log.Println("gpio.Switch module: Deinit called") - +func (s *Switch) Deinit(_ context.Context) error { if s.gpio == nil { return nil } @@ -272,8 +263,8 @@ func (s *Switch) Deinit() error { } //nolint:cyclop -func (s *Switch) Run(_ context.Context, sesh module.Session, args ...string) error { - log.Println("gpio.Switch module: Run called") +func (s *Switch) Run(ctx context.Context, sesh module.Session, args ...string) error { + l := log.FromContext(ctx) if len(args) == 0 { sesh.Printf("Current state: %s\n", s.state) @@ -288,6 +279,8 @@ func (s *Switch) Run(_ context.Context, sesh module.Session, args ...string) err return err } + l.Info(fmt.Sprintf("switch on (pin %d)", s.Pin)) + if s.state == on { sesh.Print("Already on") } else { @@ -303,6 +296,8 @@ func (s *Switch) Run(_ context.Context, sesh module.Session, args ...string) err return err } + l.Info(fmt.Sprintf("switch off (pin %d)", s.Pin)) + if s.state == off { sesh.Print("Already off") } else { @@ -327,6 +322,8 @@ func (s *Switch) Run(_ context.Context, sesh module.Session, args ...string) err s.state = on } + + l.Info(fmt.Sprintf("switch %s (pin %d)", s.state, s.Pin)) default: return fmt.Errorf("unknown argument: %s", args[0]) } diff --git a/pkg/module/gpio/gpio_test.go b/pkg/module/gpio/gpio_test.go index 4b60024a..4bc09684 100644 --- a/pkg/module/gpio/gpio_test.go +++ b/pkg/module/gpio/gpio_test.go @@ -100,7 +100,7 @@ func TestButtonInit(t *testing.T) { tt.button.backendParser = mockBackend } - err := tt.button.Init() + err := tt.button.Init(context.Background()) if (err != nil) != tt.expectErr { t.Errorf("unexpected error: %v", err) } @@ -155,7 +155,7 @@ func TestButtonDeinit(t *testing.T) { } tt.button.gpio = mockGpio - err := tt.button.Deinit() + err := tt.button.Deinit(context.Background()) if (err != nil) != tt.expectErr { t.Errorf("unexpected error: %v", err) } @@ -435,7 +435,7 @@ func TestSwitchInit(t *testing.T) { t.Run(tt.name, func(t *testing.T) { tt.swtch.backendParser = mockBackend - err := tt.swtch.Init() + err := tt.swtch.Init(context.Background()) if (err != nil) != tt.expectErr { t.Errorf("unexpected error: %v", err) } @@ -473,7 +473,7 @@ func TestSwitchDeinit(t *testing.T) { } tt.swtch.gpio = mockGpio - err := tt.swtch.Deinit() + err := tt.swtch.Deinit(context.Background()) if (err != nil) != tt.expectErr { t.Errorf("unexpected error: %v", err) } diff --git a/pkg/module/ipmi/ipmi.go b/pkg/module/ipmi/ipmi.go index dbcf4ec6..d83b74ea 100644 --- a/pkg/module/ipmi/ipmi.go +++ b/pkg/module/ipmi/ipmi.go @@ -8,10 +8,10 @@ package ipmi import ( "context" "fmt" - "log" "strings" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" "github.com/bougou/go-ipmi" ) @@ -41,8 +41,6 @@ type IPMI struct { var _ module.Module = &IPMI{} func (i *IPMI) Help() string { - log.Println("ipmi module: Help called") - help := strings.Builder{} help.WriteString("IPMI Power Management Module\n") help.WriteString("\nUsage:\n") @@ -72,26 +70,27 @@ const ( status = "status" ) -func (i *IPMI) Init() error { - log.Printf("ipmi module: Init starting for BMC %s", i.Host) +func (i *IPMI) Init(ctx context.Context) error { + l := log.FromContext(ctx) port := i.Port if port == 0 { port = defaultPort - log.Printf("ipmi module: Using default port %d", defaultPort) + l.Debug(fmt.Sprintf("no port configured, using default %d", defaultPort)) } - // Parse custom timeout if provided + // Parse custom timeout if provided; an unparseable value falls back to the default. timeout := defaultTimeout if i.Timeout != "" { parsedTimeout, err := time.ParseDuration(i.Timeout) if err == nil { timeout = parsedTimeout - log.Printf("ipmi module: Using custom timeout %v", timeout) } else { - log.Printf("ipmi module: Invalid timeout format '%s', using default %v", i.Timeout, defaultTimeout) + l.Debug(fmt.Sprintf("invalid timeout %q, using default %s", i.Timeout, defaultTimeout)) } + } else { + l.Debug(fmt.Sprintf("no timeout configured, using default %s", defaultTimeout)) } if i.Host == "" { @@ -106,28 +105,27 @@ func (i *IPMI) Init() error { ipmiClient.WithTimeout(timeout) ipmiClient.WithRetry(trials) - err = ipmiClient.Connect(context.Background()) + // Bounded by ctx: today the init context is a plain background context, but + // passing it (not context.Background()) means a later startup deadline or + // shutdown cancellation on that context will bound this connect. TODO(ctx). + err = ipmiClient.Connect(ctx) if err != nil { return fmt.Errorf("failed to connect to IPMI BMC %s:%d: %v", i.Host, port, err) } i.client = ipmiClient - log.Printf("ipmi module: Init completed successfully for %s:%d", i.Host, port) + + l.Debug(fmt.Sprintf("connected to BMC %s:%d", i.Host, port)) return nil } -func (i *IPMI) Deinit() error { +func (i *IPMI) Deinit(ctx context.Context) error { if i.client == nil { return nil } - err := i.client.Close(context.Background()) - if err != nil { - log.Printf("ipmi module: Deinit failed to close client: %v", err) - } - - return err + return i.client.Close(ctx) } func (i *IPMI) Run(ctx context.Context, s module.Session, args ...string) error { @@ -182,6 +180,7 @@ func (i *IPMI) handlePowerCommand(ctx context.Context, s module.Session, command return fmt.Errorf("power %s command failed: %v", command, err) } + log.FromContext(ctx).Info(fmt.Sprintf("chassis %s (BMC %s)", command, i.Host)) s.Println(message) return nil diff --git a/pkg/module/module.go b/pkg/module/module.go index 948252dc..09811e43 100644 --- a/pkg/module/module.go +++ b/pkg/module/module.go @@ -39,14 +39,19 @@ type Module interface { // It's a good place to establish connections or allocate resources and check whether // the module is configured functional. It is also called when a command containing this // module is called as a dry-run to check the configuration. - Init() error + // + // The context carries a logger scoped to this module; obtain it with + // log.FromContext(ctx). It has no request deadline (Init runs at startup). + Init(ctx context.Context) error // Deinit is called when the module is unloaded by dutagent or an internal error occurs. // It is used to clean up any resources that were allocated during the Init phase and // shall guarantee a graceful shutdown of the service. // // Implementations must be safe to call even if Init was never called or failed partway. // Init may fail after partially allocating resources that still need cleanup. - Deinit() error + // + // The context carries a logger scoped to this module; obtain it with log.FromContext(ctx). + Deinit(ctx context.Context) error // Run is the entry point and executes the module with the given arguments. Run(ctx context.Context, s Session, args ...string) error } diff --git a/pkg/module/pdu/pdu.go b/pkg/module/pdu/pdu.go index 5e3f1364..77a765e8 100644 --- a/pkg/module/pdu/pdu.go +++ b/pkg/module/pdu/pdu.go @@ -9,12 +9,12 @@ import ( "context" "fmt" "io" - "log" "net/http" "net/url" "strings" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -41,8 +41,6 @@ type PDU struct { } func (p *PDU) Help() string { - log.Println("pdu module: Help called") - help := strings.Builder{} help.WriteString("PDU Power Management Module\n") @@ -69,9 +67,7 @@ const ( status = "status" ) -func (p *PDU) Init() error { - log.Printf("pdu module: Init called - Host: %s, User: %s, Outlet: %d", p.Host, p.User, p.Outlet) - +func (p *PDU) Init(_ context.Context) error { if p.Outlet < 0 { return fmt.Errorf("invalid outlet number %d: outlet must be 0 or greater", p.Outlet) } @@ -92,14 +88,10 @@ func (p *PDU) Init() error { p.statusURL = statusURL - log.Printf("pdu module: Init completed - controlURL: %s, statusURL: %s", p.controlURL.String(), p.statusURL.String()) - return nil } -func (p *PDU) Deinit() error { - log.Println("pdu module: Deinit called") - +func (p *PDU) Deinit(_ context.Context) error { return nil } @@ -135,6 +127,8 @@ func (p *PDU) Run(ctx context.Context, s module.Session, args ...string) error { // doRequest creates and executes an HTTP request with authentication and validates the response. func (p *PDU) doRequest(ctx context.Context, url string) (*http.Response, error) { + log.FromContext(ctx).Debug("GET " + url) + req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil) if err != nil { return nil, err @@ -176,6 +170,7 @@ func (p *PDU) setPower(ctx context.Context, s module.Session, state string) erro } defer resp.Body.Close() + log.FromContext(ctx).Info(fmt.Sprintf("outlet %d power %s", p.Outlet, state)) s.Printf("PDU outlet%d power set to '%s' successfully\n", p.Outlet, state) return nil diff --git a/pkg/module/serial/serial.go b/pkg/module/serial/serial.go index a2aa1548..e72848ea 100644 --- a/pkg/module/serial/serial.go +++ b/pkg/module/serial/serial.go @@ -10,10 +10,10 @@ import ( "context" "errors" "fmt" - "log" "strings" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" "go.bug.st/serial" ) @@ -135,8 +135,6 @@ EXAMPLES: ` func (s *Serial) Help() string { - log.Println("serial module: Help called") - help := strings.Builder{} help.WriteString(abstract) help.WriteString(usage) @@ -146,15 +144,14 @@ func (s *Serial) Help() string { return help.String() } -func (s *Serial) Init() error { - log.Println("serial module: Init called") - +func (s *Serial) Init(ctx context.Context) error { if s.Port == "" { return fmt.Errorf("COM port is not set") } if s.Baud == 0 { s.Baud = DefaultBaudRate + log.FromContext(ctx).Debug(fmt.Sprintf("no baud rate configured, using default %d", DefaultBaudRate)) } s.delay = defaultDelay @@ -175,9 +172,7 @@ func (s *Serial) Init() error { return nil } -func (s *Serial) Deinit() error { - log.Println("serial module: Deinit called") - +func (s *Serial) Deinit(_ context.Context) error { // Nothing to clean up: the port is opened and closed within each Run // (see Run's defer), never held on the struct between runs. return nil @@ -204,7 +199,10 @@ func defaultOpenPort(name string, baud int) (port, error) { //nolint:cyclop,funlen // monitor/sequence dispatch with pacing and drain; the branch count is inherent func (s *Serial) Run(ctx context.Context, session module.Session, args ...string) error { - log.Println("serial module: Run called") + // The logger carried on ctx is already scoped to this module by the agent + // (scope "module", with module/device/command attributes), so the module + // only adds what is specific to this run. + l := log.FromContext(ctx) // Parse into LOCAL state every Run — the module instance is shared and // reused across RPCs, so nothing per-run may live on the struct. @@ -228,10 +226,10 @@ func (s *Serial) Run(ctx context.Context, session module.Session, args ...string // previous session, otherwise a step could match data from the last boot. err = serialPort.ResetInputBuffer() if err != nil { - log.Printf("serial module: reset input buffer failed: %v", err) + l.Warn("reset input buffer failed", "err", err) } - log.Printf("serial module: connected to %s at %d baud", s.Port, s.Baud) + l.Info(fmt.Sprintf("connected to %s at %d baud", s.Port, s.Baud)) clientOut := newClientWriter(session) clientOut.markerf("--- Connected to %s at %d baud ---\n", s.Port, s.Baud) @@ -243,7 +241,7 @@ func (s *Serial) Run(ctx context.Context, session module.Session, args ...string if cfg.timeout > 0 { var cancel context.CancelFunc - log.Printf("serial module: setting global timeout of %s", cfg.timeout) + l.Debug(fmt.Sprintf("setting global timeout %s", cfg.timeout)) loopCtx, cancel = context.WithTimeout(ctx, cfg.timeout) defer cancel() @@ -253,7 +251,7 @@ func (s *Serial) Run(ctx context.Context, session module.Session, args ...string // Monitor mode: no steps — stream the console until cancelled or -t elapses. if len(cfg.steps) == 0 { - log.Println("serial module: monitor mode; streaming until cancelled") + l.Debug("monitor mode; streaming until cancelled") err = eng.monitor(loopCtx) if err != nil { diff --git a/pkg/module/serial/serial_test.go b/pkg/module/serial/serial_test.go index 234b87c3..aa1a5c47 100644 --- a/pkg/module/serial/serial_test.go +++ b/pkg/module/serial/serial_test.go @@ -127,14 +127,14 @@ func TestSerialRunBadArgs(t *testing.T) { func TestSerialInit(t *testing.T) { t.Run("missing port", func(t *testing.T) { s := &Serial{} - if err := s.Init(); err == nil { + if err := s.Init(context.Background()); err == nil { t.Error("Init with empty Port = nil error, want error") } }) t.Run("defaults baud", func(t *testing.T) { s := &Serial{Port: "/dev/fake"} - if err := s.Init(); err != nil { + if err := s.Init(context.Background()); err != nil { t.Fatalf("Init: %v", err) } @@ -161,7 +161,7 @@ func TestSerialInitDelay(t *testing.T) { t.Run(tt.name, func(t *testing.T) { s := &Serial{Port: "/dev/fake", Delay: tt.delay} - err := s.Init() + err := s.Init(context.Background()) if (err != nil) != tt.wantErr { t.Fatalf("Init err = %v, wantErr %v", err, tt.wantErr) } diff --git a/pkg/module/shell/shell.go b/pkg/module/shell/shell.go index 1e6aa91f..a9c57902 100644 --- a/pkg/module/shell/shell.go +++ b/pkg/module/shell/shell.go @@ -9,10 +9,10 @@ import ( "context" "errors" "fmt" - "log" "os/exec" "strings" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -50,8 +50,6 @@ The shell module is non-interactive and does not support stdin. ` func (s *Shell) Help() string { - log.Println("shell module: Help called") - help := strings.Builder{} help.WriteString(abstract) help.WriteString(usage) @@ -65,11 +63,10 @@ func (s *Shell) Help() string { return help.String() } -func (s *Shell) Init() error { - log.Println("shell module: Init called") - +func (s *Shell) Init(ctx context.Context) error { if s.Path == "" { s.Path = DefaultShellPath + log.FromContext(ctx).Debug("no shell path configured, using default " + DefaultShellPath) } _, err := exec.LookPath(s.Path) @@ -80,15 +77,11 @@ func (s *Shell) Init() error { return nil } -func (s *Shell) Deinit() error { - log.Println("shell module: Deinit called") - +func (s *Shell) Deinit(_ context.Context) error { return nil } -func (s *Shell) Run(_ context.Context, sesh module.Session, args ...string) error { - log.Println("shell module: Run called") - +func (s *Shell) Run(ctx context.Context, sesh module.Session, args ...string) error { if len(args) == 0 { return fmt.Errorf("missing command-string") } @@ -100,6 +93,8 @@ func (s *Shell) Run(_ context.Context, sesh module.Session, args ...string) erro cmdStr := args[0] binary := s.Path + log.FromContext(ctx).Info(fmt.Sprintf("executing %q", cmdStr)) + //nolint:noctx shell := exec.Command(binary, "-c", cmdStr) diff --git a/pkg/module/ssh/ssh.go b/pkg/module/ssh/ssh.go index 1d07a44a..99484522 100644 --- a/pkg/module/ssh/ssh.go +++ b/pkg/module/ssh/ssh.go @@ -10,10 +10,10 @@ import ( "context" "errors" "fmt" - "log" "os" "strings" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" "golang.org/x/crypto/ssh" ) @@ -57,8 +57,6 @@ The ssh module is non-interactive yet. ` func (s *SSH) Help() string { - log.Println("ssh module: Help called") - help := strings.Builder{} help.WriteString(abstract) help.WriteString(usage) @@ -69,9 +67,7 @@ func (s *SSH) Help() string { return help.String() } -func (s *SSH) Init() error { - log.Println("ssh module: Init called") - +func (s *SSH) Init(_ context.Context) error { err := s.evalConfiguration() if err != nil { return err @@ -119,15 +115,11 @@ func (s *SSH) Init() error { return nil } -func (s *SSH) Deinit() error { - log.Println("ssh module: Deinit called") - +func (s *SSH) Deinit(_ context.Context) error { return nil } -func (s *SSH) Run(_ context.Context, sesh module.Session, args ...string) error { - log.Println("ssh module: Run called") - +func (s *SSH) Run(ctx context.Context, sesh module.Session, args ...string) error { if len(args) == 0 { return fmt.Errorf("missing command-string") } @@ -136,6 +128,9 @@ func (s *SSH) Run(_ context.Context, sesh module.Session, args ...string) error return fmt.Errorf("too many arguments - if the command-string contains spaces or special characters, quote it") } + l := log.FromContext(ctx) + l.Debug(fmt.Sprintf("dialing %s@%s", s.User, s.addr)) + client, err := ssh.Dial("tcp", s.addr, s.config) if err != nil { return fmt.Errorf("failed to dial SSH server: %w", err) @@ -148,6 +143,8 @@ func (s *SSH) Run(_ context.Context, sesh module.Session, args ...string) error } defer session.Close() + l.Info(fmt.Sprintf("executing %q on %s", args[0], s.Host)) + // Execute the command and capture output output, err := session.CombinedOutput(args[0]) if err != nil { diff --git a/pkg/module/time/wait.go b/pkg/module/time/wait.go index cf9c86dc..8e0fe58a 100644 --- a/pkg/module/time/wait.go +++ b/pkg/module/time/wait.go @@ -7,10 +7,10 @@ package time import ( "context" "fmt" - "log" "strings" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -52,8 +52,6 @@ and a unit suffix, such as "300ms", "-1.5h" or "2h45m". Valid time units are "ns", "us" (or "µs"), "ms", "s", "m", "h".` func (w *Wait) Help() string { - log.Println("time.Wait module: Help called") - help := strings.Builder{} help.WriteString(abstract) help.WriteString(usage) @@ -64,11 +62,10 @@ func (w *Wait) Help() string { return help.String() } -func (w *Wait) Init() error { - log.Println("time.Wait module: Init called") - +func (w *Wait) Init(ctx context.Context) error { if w.Duration == "" { w.Duration = DefaultDuration + log.FromContext(ctx).Debug("no duration configured, using default " + DefaultDuration) } d, err := time.ParseDuration(w.Duration) @@ -81,15 +78,11 @@ func (w *Wait) Init() error { return nil } -func (w *Wait) Deinit() error { - log.Println("time.Wait module: Deinit called") - +func (w *Wait) Deinit(_ context.Context) error { return nil } func (w *Wait) Run(_ context.Context, s module.Session, args ...string) error { - log.Println("time.Wait module: Run called") - var duration time.Duration // Override default duration or configured duration with value passed via cmd line. diff --git a/pkg/module/wifisocket/wifisocket.go b/pkg/module/wifisocket/wifisocket.go index 6a52863a..23fc8c27 100644 --- a/pkg/module/wifisocket/wifisocket.go +++ b/pkg/module/wifisocket/wifisocket.go @@ -11,12 +11,12 @@ import ( "encoding/json" "fmt" "io" - "log" "net/http" "net/url" "strings" "time" + "github.com/BlindspotSoftware/dutctl/internal/log" "github.com/BlindspotSoftware/dutctl/pkg/module" ) @@ -47,8 +47,6 @@ const ( ) func (w *WifiSocket) Help() string { - log.Println("wifisocket module: Help called") - help := strings.Builder{} help.WriteString("WiFi Socket (Tasmota) Module\n\n") @@ -67,15 +65,14 @@ func (w *WifiSocket) Help() string { return help.String() } -func (w *WifiSocket) Init() error { - log.Printf("wifisocket module: Init called - Host: %s, Channel: %d", w.Host, w.Channel) - +func (w *WifiSocket) Init(ctx context.Context) error { if w.Host == "" { return fmt.Errorf("wifisocket: host must be configured") } if w.Channel <= 0 { w.Channel = 1 + log.FromContext(ctx).Debug("no channel configured, using default 1") } w.client = &http.Client{Timeout: defaultTimeout} @@ -94,14 +91,10 @@ func (w *WifiSocket) Init() error { w.controlURL = u w.Host = host - log.Printf("wifisocket module: Init completed - controlURL: %s", w.controlURL.String()) - return nil } -func (w *WifiSocket) Deinit() error { - log.Println("wifisocket module: Deinit called") - +func (w *WifiSocket) Deinit(_ context.Context) error { return nil } @@ -135,6 +128,8 @@ func (w *WifiSocket) Run(ctx context.Context, s module.Session, args ...string) // doRequest performs an HTTP GET and ensures HTTP 200 OK. func (w *WifiSocket) doRequest(ctx context.Context, u string) (*http.Response, error) { + log.FromContext(ctx).Debug("GET " + u) + req, err := http.NewRequestWithContext(ctx, http.MethodGet, u, nil) if err != nil { return nil, err @@ -179,6 +174,8 @@ func (w *WifiSocket) setPower(ctx context.Context, s module.Session, state strin } defer resp.Body.Close() + log.FromContext(ctx).Info(fmt.Sprintf("socket channel %d power %s", w.Channel, state)) + body, _ := io.ReadAll(resp.Body) confirmed, err := w.parseState(body) diff --git a/pkg/module/wifisocket/wifisocket_test.go b/pkg/module/wifisocket/wifisocket_test.go index 4236b724..60f9b397 100644 --- a/pkg/module/wifisocket/wifisocket_test.go +++ b/pkg/module/wifisocket/wifisocket_test.go @@ -5,6 +5,7 @@ package wifisocket import ( + "context" "strings" "testing" ) @@ -52,7 +53,7 @@ func TestParseStateJSONHTMLPlain(t *testing.T) { func TestInitControlURL(t *testing.T) { w := &WifiSocket{Host: "http://example.local:8080"} - if err := w.Init(); err != nil { + if err := w.Init(context.Background()); err != nil { t.Fatalf("Init failed: %v", err) } if w.controlURL == nil { @@ -69,7 +70,7 @@ func TestHelpAndDeinit(t *testing.T) { if h == "" || !strings.Contains(h, "WiFi Socket") { t.Fatalf("help seems wrong") } - if err := w.Deinit(); err != nil { + if err := w.Deinit(context.Background()); err != nil { t.Fatalf("Deinit returned error: %v", err) } }