diff --git a/AGENTS.md b/AGENTS.md index f38ca904b..fad57a53d 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -45,11 +45,14 @@ - Use `Wet(host, dryMsg, funcs...)` and `DryMsg(host, msg)` (both on `GenericPhase`) so dry-run output is an accurate per-host plan. - If a phase needs alternate dry-run behavior, implement the dry-run interface instead of partially running mutating logic. -## Logging -- Use `log "github.com/sirupsen/logrus"` — it is the only logger in this project. -- Per-host messages must prefix the host: `log.Infof("%s: doing thing", h)`. +## Logging and display +- Use `log "github.com/k0sproject/k0sctl/internal/log"` — a thin printf-style facade over `log/slog`; it is the only logger in this project. +- Host-scoped messages go through the host's logger: `h.Log().Infof("doing thing")` — this attaches the `host` attribute so records can be routed per host. Do not prefix messages with `%s: ` manually. +- In code that receives a `context.Context` from a per-host operation (e.g. retry helpers), use `log.FromContext(ctx)` to inherit the host scope. - Use `log.Debug`/`log.Debugf` for internal state, `log.Info`/`log.Infof` for user-visible progress, `log.Warn`/`log.Warnf` for recoverable problems. -- Do not use `fmt.Print*` for diagnostic output. +- Structured attributes use rig v2's attribute keys (`log.KeyHost`, `log.KeyError`, `log.KeyDuration`) so k0sctl and rig records stay uniform. k0sctl adds `log.KeyPhase` (phase lifecycle records emitted by phase/manager.go) and `log.KeyAttempt` (retry counters from pkg/retry). +- The screen is rendered by `internal/display` (a slog handler): a live TTY renderer with per-host status rows and log tails, or a plain line renderer for non-TTY/CI/--debug/--dry-run. Displays route records by attributes — never parse log message text to detect state, and never embed ANSI colors in log messages. +- Do not use `fmt.Print*` for diagnostic output. Direct writes to `Manager.Writer` are only for final reports (dry-run summary, kubeconfig) that happen while no live display is running. ## Error Wrapping - Wrap errors with context using `fmt.Errorf("doing X: %w", err)`. diff --git a/action/apply.go b/action/apply.go index e51505372..192acfcd4 100644 --- a/action/apply.go +++ b/action/apply.go @@ -2,7 +2,6 @@ package action import ( "context" - "fmt" "io" "os" "os/exec" @@ -12,7 +11,7 @@ import ( "github.com/k0sproject/k0sctl/phase" - log "github.com/sirupsen/logrus" + log "github.com/k0sproject/k0sctl/internal/log" ) type ApplyOptions struct { @@ -111,7 +110,7 @@ func (a Apply) Run(ctx context.Context) error { var result error if result = a.Manager.Run(ctx); result != nil { - log.Info(phase.Colorize.Red("==> Apply failed").String()) + log.Error("==> Apply failed") return result } @@ -122,8 +121,7 @@ func (a Apply) Run(ctx context.Context) error { } duration := time.Since(start).Truncate(time.Second) - text := fmt.Sprintf("==> Finished in %s", duration) - log.Info(phase.Colorize.Green(text).String()) + log.Infof("==> Finished in %s", duration) for _, host := range a.Manager.Config.Spec.Hosts { if host.Reset { @@ -159,7 +157,7 @@ func (a Apply) Run(ctx context.Context) error { } log.Info("Tip: To access the cluster you can now fetch the admin kubeconfig using:") - log.Info(" " + phase.Colorize.Cyan(cmd.String()).String()) + log.Info(" " + cmd.String()) } return nil diff --git a/action/backup.go b/action/backup.go index dd31b2b48..d51eaf3d2 100644 --- a/action/backup.go +++ b/action/backup.go @@ -6,8 +6,8 @@ import ( "io" "time" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/phase" - log "github.com/sirupsen/logrus" ) type Backup struct { @@ -40,6 +40,6 @@ func (b Backup) Run(ctx context.Context) error { duration := time.Since(start).Truncate(time.Second) text := fmt.Sprintf("==> Finished in %s", duration) - log.Info(phase.Colorize.Green(text).String()) + log.Info(text) return nil } diff --git a/action/kubeconfig.go b/action/kubeconfig.go index 077f9a952..e6cdc1089 100644 --- a/action/kubeconfig.go +++ b/action/kubeconfig.go @@ -22,12 +22,12 @@ func (k *Kubeconfig) Run(ctx context.Context) error { // do not need to connect to all nodes k.Manager.Config.Spec.Hosts = cluster.Hosts{k.Manager.Config.Spec.K0sLeader()} - k.Manager.AddPhase( - &phase.Connect{}, - &phase.DetectOS{}, - &phase.GetKubeconfig{APIAddress: k.KubeconfigAPIAddress, User: k.KubeconfigUser, Cluster: k.KubeconfigCluster}, - &phase.Disconnect{}, - ) + k.Manager.AddPhase( + &phase.Connect{}, + &phase.DetectOS{}, + &phase.GetKubeconfig{APIAddress: k.KubeconfigAPIAddress, User: k.KubeconfigUser, Cluster: k.KubeconfigCluster}, + &phase.Disconnect{}, + ) return k.Manager.Run(ctx) } diff --git a/action/reset.go b/action/reset.go index a8c404c42..63bc3f5b1 100644 --- a/action/reset.go +++ b/action/reset.go @@ -7,8 +7,8 @@ import ( "os" "time" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/phase" - log "github.com/sirupsen/logrus" "github.com/AlecAivazis/survey/v2" "github.com/mattn/go-isatty" @@ -71,7 +71,7 @@ func (r Reset) Run(ctx context.Context) error { duration := time.Since(start).Truncate(time.Second) text := fmt.Sprintf("==> Finished in %s", duration) - log.Info(phase.Colorize.Green(text).String()) + log.Info(text) return nil } diff --git a/cmd/apply.go b/cmd/apply.go index 2c324d92f..cc6d8be57 100644 --- a/cmd/apply.go +++ b/cmd/apply.go @@ -7,9 +7,9 @@ import ( "strings" "github.com/k0sproject/k0sctl/action" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/phase" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" - log "github.com/sirupsen/logrus" "github.com/urfave/cli/v2" ) diff --git a/cmd/backup.go b/cmd/backup.go index 047274a1d..dea457cad 100644 --- a/cmd/backup.go +++ b/cmd/backup.go @@ -8,8 +8,8 @@ import ( "time" "github.com/k0sproject/k0sctl/action" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/phase" - log "github.com/sirupsen/logrus" "github.com/urfave/cli/v2" ) diff --git a/cmd/flags.go b/cmd/flags.go index efe4d7423..c307ce5c1 100644 --- a/cmd/flags.go +++ b/cmd/flags.go @@ -5,26 +5,30 @@ import ( "context" "fmt" "io" + "log/slog" "os" "path" "path/filepath" "runtime" + "slices" "strings" "time" "github.com/a8m/envsubst" "github.com/adrg/xdg" glob "github.com/bmatcuk/doublestar/v4" + "github.com/charmbracelet/lipgloss" + "github.com/charmbracelet/x/term" "github.com/k0sproject/dig" + "github.com/k0sproject/k0sctl/internal/display" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/phase" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/manifest" "github.com/k0sproject/k0sctl/pkg/retry" k0sctl "github.com/k0sproject/k0sctl/version" "github.com/k0sproject/rig/v2/cmd" - "github.com/logrusorgru/aurora" "github.com/shiena/ansicolor" - log "github.com/sirupsen/logrus" "github.com/urfave/cli/v2" ) @@ -132,8 +136,6 @@ var ( return nil }, } - - Colorize = aurora.NewAurora(false) ) func cancelTimeout(_ *cli.Context) error { @@ -279,17 +281,21 @@ func warnOldCache(_ *cli.Context) error { } func warnRigMigration(ctx *cli.Context) error { - var warningRows []string - warningRows = append(warningRows, "") - warningRows = append(warningRows, "▌ This release replaces k0sctl's host connection and remote execution ") - warningRows = append(warningRows, "▌ layer (rig v2). This is the only difference between this and the previous ") - warningRows = append(warningRows, "▌ release (k0sctl v0.31.1). Behavior should be unchanged, but if you hit ") - warningRows = append(warningRows, "▌ unexpected connection, sudo, OS detection or file transfer issues, please ") - warningRows = append(warningRows, "▌ report them at https://github.com/k0sproject/k0sctl/issues and roll back ") - warningRows = append(warningRows, "▌ to v0.31.1 until the issue is resolved. ") - warningRows = append(warningRows, "") + style := lipgloss.NewRenderer(ctx.App.ErrWriter).NewStyle(). + Foreground(lipgloss.Color("11")). + Background(lipgloss.Color("4")) + warningRows := []string{ + "", + "▌ This release replaces k0sctl's host connection and remote execution ", + "▌ layer (rig v2). This is the only difference between this and the previous ", + "▌ release (k0sctl v0.31.1). Behavior should be unchanged, but if you hit ", + "▌ unexpected connection, sudo, OS detection or file transfer issues, please ", + "▌ report them at https://github.com/k0sproject/k0sctl/issues and roll back ", + "▌ to v0.31.1 until the issue is resolved. ", + "", + } for _, row := range warningRows { - fmt.Fprintln(ctx.App.ErrWriter, Colorize.BgBlue(Colorize.BrightYellow(row))) + fmt.Fprintln(ctx.App.ErrWriter, style.Render(row)) } return nil } @@ -397,47 +403,95 @@ func initManager(ctx *cli.Context) error { // initLogging initializes the logger func initLogging(ctx *cli.Context) error { - log.SetLevel(log.TraceLevel) - log.SetOutput(io.Discard) - initScreenLogger(ctx, logLevelFromCtx(ctx, log.InfoLevel)) cmd.DisableRedact = ctx.Bool("no-redact") - return initFileLogger(ctx) + return setupLogging(ctx, logLevelFromCtx(ctx, slog.LevelInfo)) } // initSilentLogging initializes the logger in silent mode -// TODO too similar to initLogging func initSilentLogging(ctx *cli.Context) error { - log.SetLevel(log.TraceLevel) - log.SetOutput(io.Discard) cmd.DisableRedact = ctx.Bool("no-redact") - initScreenLogger(ctx, logLevelFromCtx(ctx, log.FatalLevel)) - return initFileLogger(ctx) + return setupLogging(ctx, logLevelFromCtx(ctx, log.LevelFatal)) } -func logLevelFromCtx(ctx *cli.Context, defaultLevel log.Level) log.Level { +func logLevelFromCtx(ctx *cli.Context, defaultLevel slog.Level) slog.Level { if ctx.Bool("trace") { - return log.TraceLevel + return log.LevelTrace } else if ctx.Bool("debug") { - return log.DebugLevel + return slog.LevelDebug } else { return defaultLevel } } -func initScreenLogger(ctx *cli.Context, lvl log.Level) { - log.AddHook(screenLoggerHook(ctx, lvl)) +// activeDisplay is the display of the currently running command, stopped in +// the app-level After hook so the terminal is restored before the process +// exits or an error is printed. +var activeDisplay *display.Display + +func stopDisplay(_ *cli.Context) error { + if activeDisplay != nil { + activeDisplay.Stop() + } + return nil } -func initFileLogger(ctx *cli.Context) error { +// setupLogging builds the display and file handlers and installs the fanout +// of the two as the logger behind the internal/log package functions. +func setupLogging(ctx *cli.Context, screenLevel slog.Level) error { + writer := ctx.App.Writer + + outTTY := writerIsTerminal(writer) + colors := outTTY + if runtime.GOOS == "windows" && !outTTY { + // legacy consoles may not report as terminals but still want the + // ansi translation layer + writer = ansicolor.NewAnsiColorWriter(ctx.App.Writer) + colors = true + } + + // the live TTY display runs only at the default log level on a real + // terminal; --debug/--trace, --dry-run and quiet modes use plain lines + useTTY := outTTY && screenLevel == slog.LevelInfo && !ctx.Bool("dry-run") + + if useTTY { + interactive := false + if inF, ok := ctx.App.Reader.(*os.File); ok && !slices.Contains(ctx.StringSlice("config"), "-") { + interactive = term.IsTerminal(inF.Fd()) + } + // note: the callback runs inside the display's update loop and must + // not log; the display renders its own abort notice + activeDisplay = display.NewTTY(writer, screenLevel, interactive, func() { + if globalCancel != nil { + globalCancel() + } + }) + } else { + activeDisplay = display.NewPlain(writer, screenLevel, colors) + } + lf, err := LogFile() if err != nil { return err } - log.AddHook(fileLoggerHook(lf)) + // the file always gets debug; --trace widens it to trace as well + fileLevel := min(slog.LevelDebug, screenLevel) + + log.SetLogger(slog.New(log.NewFanoutHandler( + activeDisplay, + log.NewFileHandler(lf, fileLevel), + ))) + ctx.Context = context.WithValue(ctx.Context, ctxLogFileKey{}, lf.Name()) return nil } +func writerIsTerminal(w io.Writer) bool { + if f, ok := w.(*os.File); ok { + return term.IsTerminal(f.Fd()) + } + return false +} + const logPath = "k0sctl/k0sctl.log" func LogFile() (*os.File, error) { @@ -454,7 +508,7 @@ func LogFile() (*os.File, error) { return nil, fmt.Errorf("failed to open log %s: %s", fn, err.Error()) } - fmt.Fprintf(logFile, "time=\"%s\" level=info msg=\"###### New session ######\"\n", time.Now().Format(time.RFC822)) + fmt.Fprintf(logFile, "time=%s level=INFO msg=\"###### New session ######\"\n", time.Now().Format(time.RFC3339)) return logFile, nil } @@ -503,80 +557,6 @@ func configReader(ctx *cli.Context, f string) (io.ReadCloser, error) { return nil, fmt.Errorf("failed to locate configuration") } -type loghook struct { - Writer io.Writer - Formatter log.Formatter - - levels []log.Level -} - -func (h *loghook) SetLevel(level log.Level) { - h.levels = []log.Level{} - for _, l := range log.AllLevels { - if level >= l { - h.levels = append(h.levels, l) - } - } -} - -func (h *loghook) Levels() []log.Level { - return h.levels -} - -func (h *loghook) Fire(entry *log.Entry) error { - line, err := h.Formatter.Format(entry) - if err != nil { - fmt.Fprintf(os.Stderr, "Unable to format log entry: %v", err) - return err - } - _, err = h.Writer.Write(line) - return err -} - -func screenLoggerHook(ctx *cli.Context, lvl log.Level) *loghook { - var forceColors bool - writer := ctx.App.Writer - if runtime.GOOS == "windows" { - writer = ansicolor.NewAnsiColorWriter((ctx.App.Writer)) - forceColors = true - } else { - if outF, ok := writer.(*os.File); ok { - if fi, _ := outF.Stat(); (fi.Mode() & os.ModeCharDevice) != 0 { - forceColors = true - } - } - } - - if forceColors { - Colorize = aurora.NewAurora(true) - phase.Colorize = Colorize - } - - l := &loghook{ - Writer: writer, - Formatter: &log.TextFormatter{DisableTimestamp: lvl < log.DebugLevel, ForceColors: forceColors}, - } - - l.SetLevel(lvl) - - return l -} - -func fileLoggerHook(logFile io.Writer) *loghook { - l := &loghook{ - Formatter: &log.TextFormatter{ - FullTimestamp: true, - TimestampFormat: time.RFC822, - DisableLevelTruncation: true, - }, - Writer: logFile, - } - - l.SetLevel(log.DebugLevel) - - return l -} - func displayLogo(ctx *cli.Context) error { fmt.Fprint(ctx.App.Writer, logo) return nil diff --git a/cmd/root.go b/cmd/root.go index 95fef4126..9978131e6 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -7,7 +7,7 @@ import ( "os/signal" "syscall" - log "github.com/sirupsen/logrus" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/urfave/cli/v2" ) @@ -73,6 +73,9 @@ func NewK0sctl(in io.Reader, out, errOut io.Writer) *cli.App { return nil }, After: func(ctx *cli.Context) error { + // stop the live display (restores the terminal) before any + // error output is printed + _ = stopDisplay(ctx) return cancelTimeout(ctx) }, Reader: in, diff --git a/configurer/linux.go b/configurer/linux.go index 2fa466704..dd598f835 100644 --- a/configurer/linux.go +++ b/configurer/linux.go @@ -150,7 +150,6 @@ func (l *Linux) PrivateAddress(h Host, iface, publicip string) (string, error) { return "", fmt.Errorf("not found") } - // UpdateEnvironment upserts the given key-value pairs into /etc/environment // (replacing any existing line for the same key) and exports them into the // current shell environment. @@ -192,4 +191,3 @@ func (l *Linux) FixContainer(h Host) error { } return nil } - diff --git a/configurer/windows.go b/configurer/windows.go index d48d2bf8b..a2cab6708 100644 --- a/configurer/windows.go +++ b/configurer/windows.go @@ -163,7 +163,6 @@ func (w *BaseWindows) PrivateAddress(h Host, iface, publicip string) (string, er return ip, nil } - // UpdateEnvironment sets machine-level environment variables on the host func (w *BaseWindows) UpdateEnvironment(h Host, env map[string]string) error { for k, v := range env { @@ -179,4 +178,3 @@ func (w *BaseWindows) UpdateEnvironment(h Host, env map[string]string) error { func (w *BaseWindows) FixContainer(h Host) error { return nil } - diff --git a/configurer/windows/windows.go b/configurer/windows/windows.go index eb3b80ad5..064339bf1 100644 --- a/configurer/windows/windows.go +++ b/configurer/windows/windows.go @@ -15,8 +15,10 @@ type Windows struct { configurer.BaseWindows } -var _ configurer.Configurer = (*Windows)(nil) -var _ configurer.HostValidator = (*Windows)(nil) +var ( + _ configurer.Configurer = (*Windows)(nil) + _ configurer.HostValidator = (*Windows)(nil) +) func init() { configurer.RegisterOSModule( diff --git a/configurer/windows/windows_test.go b/configurer/windows/windows_test.go index 4529be866..191e4f596 100644 --- a/configurer/windows/windows_test.go +++ b/configurer/windows/windows_test.go @@ -14,7 +14,6 @@ import ( "github.com/stretchr/testify/require" ) - func TestValidateHostRequiresContainersFeature(t *testing.T) { featureCmd := ps.Cmd(`(Get-WindowsFeature -Name Containers -ErrorAction SilentlyContinue).InstallState`) optionalCmd := ps.Cmd(`(Get-WindowsOptionalFeature -Online -FeatureName Containers -ErrorAction SilentlyContinue).State`) @@ -69,8 +68,8 @@ func newStubHost(outputs map[string]commandResponse) *stubHost { return &stubHost{execOutputs: outputs} } -func (h *stubHost) String() string { return "stub" } -func (h *stubHost) IsWindows() bool { return false } +func (h *stubHost) String() string { return "stub" } +func (h *stubHost) IsWindows() bool { return false } func (h *stubHost) Exec(string, ...cmd.ExecOption) error { return nil @@ -91,5 +90,5 @@ func (h *stubHost) StartBackground(_ string, _ ...cmd.ExecOption) (protocol.Wait return nil, nil } -func (h *stubHost) Sudo() *rig.Client { return nil } -func (h *stubHost) FS() remotefs.FS { return nil } +func (h *stubHost) Sudo() *rig.Client { return nil } +func (h *stubHost) FS() remotefs.FS { return nil } diff --git a/go.mod b/go.mod index 9244b5575..0a8313a37 100644 --- a/go.mod +++ b/go.mod @@ -14,12 +14,10 @@ require ( github.com/creasty/defaults v1.8.0 github.com/gofrs/uuid v4.4.0+incompatible // indirect github.com/k0sproject/dig v0.4.0 - github.com/logrusorgru/aurora v2.0.3+incompatible github.com/masterzen/simplexml v0.0.0-20190410153822-31eea3082786 // indirect github.com/masterzen/winrm v0.0.0-20260407182533-5570be7f80cf // indirect github.com/mattn/go-isatty v0.0.22 github.com/shiena/ansicolor v0.0.0-20230509054315-a9deabde6e02 - github.com/sirupsen/logrus v1.9.4 github.com/stretchr/testify v1.11.1 github.com/urfave/cli/v2 v2.27.7 golang.org/x/crypto v0.53.0 // indirect @@ -32,10 +30,13 @@ require ( require ( github.com/carlmjohnson/versioninfo v0.22.5 + github.com/charmbracelet/bubbletea v1.3.10 + github.com/charmbracelet/lipgloss v1.1.0 + github.com/charmbracelet/x/ansi v0.10.1 + github.com/charmbracelet/x/term v0.2.1 github.com/jellydator/validation v1.2.0 github.com/k0sproject/rig/v2 v2.0.0 github.com/k0sproject/version v0.8.0 - github.com/samber/slog-logrus/v2 v2.5.4 github.com/sergi/go-diff v1.4.0 k8s.io/apimachinery v0.36.2 k8s.io/client-go v0.36.2 @@ -44,11 +45,15 @@ require ( require ( github.com/Microsoft/go-winio v0.6.2 // indirect github.com/asaskevich/govalidator v0.0.0-20230301143203-a9d515a09cc2 // indirect + github.com/aymanbagabas/go-osc52/v2 v2.0.1 // indirect github.com/bodgit/ntlmssp v0.0.0-20240506230425-31973bb52d9b // indirect github.com/bodgit/windows v1.0.1 // indirect + github.com/charmbracelet/colorprofile v0.2.3-0.20250311203215-f60798e515dc // indirect + github.com/charmbracelet/x/cellbuf v0.0.13-0.20250311204145-2c3ea96c31dd // indirect github.com/cpuguy83/go-md2man/v2 v2.0.7 // indirect github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc // indirect github.com/davidmz/go-pageant v1.0.2 // indirect + github.com/erikgeiser/coninput v0.0.0-20211004153227-1c3628e74d0f // indirect github.com/fxamacker/cbor/v2 v2.9.2 // indirect github.com/go-logr/logr v1.4.3 // indirect github.com/hashicorp/go-cleanhttp v0.5.2 // indirect @@ -62,18 +67,24 @@ require ( github.com/json-iterator/go v1.1.12 // indirect github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 // indirect github.com/kr/text v0.2.0 // indirect + github.com/lucasb-eyer/go-colorful v1.2.0 // indirect github.com/mattn/go-colorable v0.1.15 // indirect + github.com/mattn/go-localereader v0.0.1 // indirect + github.com/mattn/go-runewidth v0.0.16 // indirect github.com/mgutz/ansi v0.0.0-20200706080929-d51e80ef957d // indirect github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect github.com/modern-go/reflect2 v1.0.3-0.20250322232337-35a7c28c31ee // indirect + github.com/muesli/ansi v0.0.0-20230316100256-276c6243b2f6 // indirect + github.com/muesli/cancelreader v0.2.2 // indirect + github.com/muesli/termenv v0.16.0 // indirect github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 // indirect + github.com/rivo/uniseg v0.4.7 // indirect github.com/russross/blackfriday/v2 v2.1.0 // indirect - github.com/samber/lo v1.53.0 // indirect - github.com/samber/slog-common v0.22.0 // indirect github.com/spf13/pflag v1.0.10 // indirect github.com/tidwall/transform v0.0.0-20201103190739-32f242e2dbde // indirect github.com/x448/float16 v0.8.4 // indirect + github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e // indirect github.com/xrash/smetrics v0.0.0-20250705151800-55b8f293f342 // indirect go.yaml.in/yaml/v2 v2.4.4 // indirect golang.org/x/oauth2 v0.36.0 // indirect diff --git a/go.sum b/go.sum index 17aba35e0..6299cf679 100644 --- a/go.sum +++ b/go.sum @@ -15,6 +15,8 @@ github.com/adrg/xdg v0.5.3/go.mod h1:nlTsY+NNiCBGCK2tpm09vRqfVzrc2fLmXGpBLF0zlTQ github.com/asaskevich/govalidator v0.0.0-20210307081110-f21760c49a8d/go.mod h1:WaHUgvxTVq04UNunO+XhnAqY/wQc+bxr74GqbsZ/Jqw= github.com/asaskevich/govalidator v0.0.0-20230301143203-a9d515a09cc2 h1:DklsrG3dyBCFEj5IhUbnKptjxatkF07cF2ak3yi77so= github.com/asaskevich/govalidator v0.0.0-20230301143203-a9d515a09cc2/go.mod h1:WaHUgvxTVq04UNunO+XhnAqY/wQc+bxr74GqbsZ/Jqw= +github.com/aymanbagabas/go-osc52/v2 v2.0.1 h1:HwpRHbFMcZLEVr42D4p7XBqjyuxQH5SMiErDT4WkJ2k= +github.com/aymanbagabas/go-osc52/v2 v2.0.1/go.mod h1:uYgXzlJ7ZpABp8OJ+exZzJJhRNQ2ASbcXHWsFqH8hp8= github.com/bmatcuk/doublestar/v4 v4.10.0 h1:zU9WiOla1YA122oLM6i4EXvGW62DvKZVxIe6TYWexEs= github.com/bmatcuk/doublestar/v4 v4.10.0/go.mod h1:xBQ8jztBU6kakFMg+8WGxn0c6z1fTSPVIjEY1Wr7jzc= github.com/bodgit/ntlmssp v0.0.0-20240506230425-31973bb52d9b h1:baFN6AnR0SeC194X2D292IUZcHDs4JjStpqtE70fjXE= @@ -23,6 +25,18 @@ github.com/bodgit/windows v1.0.1 h1:tF7K6KOluPYygXa3Z2594zxlkbKPAOvqr97etrGNIz4= github.com/bodgit/windows v1.0.1/go.mod h1:a6JLwrB4KrTR5hBpp8FI9/9W9jJfeQ2h4XDXU74ZCdM= github.com/carlmjohnson/versioninfo v0.22.5 h1:O00sjOLUAFxYQjlN/bzYTuZiS0y6fWDQjMRvwtKgwwc= github.com/carlmjohnson/versioninfo v0.22.5/go.mod h1:QT9mph3wcVfISUKd0i9sZfVrPviHuSF+cUtLjm2WSf8= +github.com/charmbracelet/bubbletea v1.3.10 h1:otUDHWMMzQSB0Pkc87rm691KZ3SWa4KUlvF9nRvCICw= +github.com/charmbracelet/bubbletea v1.3.10/go.mod h1:ORQfo0fk8U+po9VaNvnV95UPWA1BitP1E0N6xJPlHr4= +github.com/charmbracelet/colorprofile v0.2.3-0.20250311203215-f60798e515dc h1:4pZI35227imm7yK2bGPcfpFEmuY1gc2YSTShr4iJBfs= +github.com/charmbracelet/colorprofile v0.2.3-0.20250311203215-f60798e515dc/go.mod h1:X4/0JoqgTIPSFcRA/P6INZzIuyqdFY5rm8tb41s9okk= +github.com/charmbracelet/lipgloss v1.1.0 h1:vYXsiLHVkK7fp74RkV7b2kq9+zDLoEU4MZoFqR/noCY= +github.com/charmbracelet/lipgloss v1.1.0/go.mod h1:/6Q8FR2o+kj8rz4Dq0zQc3vYf7X+B0binUUBwA0aL30= +github.com/charmbracelet/x/ansi v0.10.1 h1:rL3Koar5XvX0pHGfovN03f5cxLbCF2YvLeyz7D2jVDQ= +github.com/charmbracelet/x/ansi v0.10.1/go.mod h1:3RQDQ6lDnROptfpWuUVIUG64bD2g2BgntdxH0Ya5TeE= +github.com/charmbracelet/x/cellbuf v0.0.13-0.20250311204145-2c3ea96c31dd h1:vy0GVL4jeHEwG5YOXDmi86oYw2yuYUGqz6a8sLwg0X8= +github.com/charmbracelet/x/cellbuf v0.0.13-0.20250311204145-2c3ea96c31dd/go.mod h1:xe0nKWGd3eJgtqZRaN9RjMtK7xUYchjzPr7q6kcvCCs= +github.com/charmbracelet/x/term v0.2.1 h1:AQeHeLZ1OqSXhrAWpYUtZyX1T3zVxfpZuEQMIQaGIAQ= +github.com/charmbracelet/x/term v0.2.1/go.mod h1:oQ4enTYFV7QN4m0i9mzHrViD7TQKvNEEkHUMCmsxdUg= github.com/cpuguy83/go-md2man/v2 v2.0.7 h1:zbFlGlXEAKlwXpmvle3d8Oe3YnkKIK4xSRTd3sHPnBo= github.com/cpuguy83/go-md2man/v2 v2.0.7/go.mod h1:oOW0eioCTA6cOiMLiUPZOpcVxMig6NIQQ7OS05n1F4g= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= @@ -38,6 +52,8 @@ github.com/davidmz/go-pageant v1.0.2 h1:bPblRCh5jGU+Uptpz6LgMZGD5hJoOt7otgT454Wv github.com/davidmz/go-pageant v1.0.2/go.mod h1:P2EDDnMqIwG5Rrp05dTRITj9z2zpGcD9efWSkTNKLIE= github.com/emicklei/go-restful/v3 v3.13.0 h1:C4Bl2xDndpU6nJ4bc1jXd+uTmYPVUwkD6bFY/oTyCes= github.com/emicklei/go-restful/v3 v3.13.0/go.mod h1:6n3XBCmQQb25CM2LCACGz8ukIrRry+4bhvbpWn3mrbc= +github.com/erikgeiser/coninput v0.0.0-20211004153227-1c3628e74d0f h1:Y/CXytFA4m6baUTXGLOoWe4PQhGxaX0KpnayAqC48p4= +github.com/erikgeiser/coninput v0.0.0-20211004153227-1c3628e74d0f/go.mod h1:vw97MGsxSvLiUE2X8qFplwetxpGLQrlU1Q9AUEIzCaM= github.com/fxamacker/cbor/v2 v2.9.2 h1:X4Ksno9+x3cz0TZv69ec1hxP/+tymuR8PXQJyDwfh78= github.com/fxamacker/cbor/v2 v2.9.2/go.mod h1:vM4b+DJCtHn+zz7h3FFp/hDAI9WNWCsZj23V5ytsSxQ= github.com/go-logr/logr v1.4.3 h1:CjnDlHq8ikf6E492q6eKboGOC0T8CDaOvkHCIg8idEI= @@ -120,8 +136,8 @@ github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= -github.com/logrusorgru/aurora v2.0.3+incompatible h1:tOpm7WcpBTn4fjmVfgpQq0EfczGlG91VSDkswnjF5A8= -github.com/logrusorgru/aurora v2.0.3+incompatible/go.mod h1:7rIyQOR62GCctdiQpZ/zOJlFyk6y+94wXzv6RNZgaR4= +github.com/lucasb-eyer/go-colorful v1.2.0 h1:1nnpGOrhyZZuNyfu1QjKiUICQ74+3FNCN69Aj6K7nkY= +github.com/lucasb-eyer/go-colorful v1.2.0/go.mod h1:R4dSotOR9KMtayYi1e77YzuveK+i7ruzyGqttikkLy0= github.com/masterzen/simplexml v0.0.0-20190410153822-31eea3082786 h1:2ZKn+w/BJeL43sCxI2jhPLRv73oVVOjEKZjKkflyqxg= github.com/masterzen/simplexml v0.0.0-20190410153822-31eea3082786/go.mod h1:kCEbxUJlNDEBNbdQMkPSp6yaKcRXVI6f4ddk8Riv4bc= github.com/masterzen/winrm v0.0.0-20260407182533-5570be7f80cf h1:UxGs98qiSWMqoqQsJxSW4FzCRdPPUFCraQ74ufgmISI= @@ -132,6 +148,10 @@ github.com/mattn/go-colorable v0.1.15/go.mod h1:6LmQG8QLFO4G5z1gPvYEzlUgJ2wF+stg github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= github.com/mattn/go-isatty v0.0.22 h1:j8l17JJ9i6VGPUFUYoTUKPSgKe/83EYU2zBC7YNKMw4= github.com/mattn/go-isatty v0.0.22/go.mod h1:ZXfXG4SQHsB/w3ZeOYbR0PrPwLy+n6xiMrJlRFqopa4= +github.com/mattn/go-localereader v0.0.1 h1:ygSAOl7ZXTx4RdPYinUpg6W99U8jWvWi9Ye2JC/oIi4= +github.com/mattn/go-localereader v0.0.1/go.mod h1:8fBrzywKY7BI3czFoHkuzRoWE9C+EiG4R1k4Cjx5p88= +github.com/mattn/go-runewidth v0.0.16 h1:E5ScNMtiwvlvB5paMFdw9p4kSQzbXFikJ5SQO6TULQc= +github.com/mattn/go-runewidth v0.0.16/go.mod h1:Jdepj2loyihRzMpdS35Xk/zdY8IAYHsh153qUoGf23w= github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b/go.mod h1:01TrycV0kFyexm33Z7vhZRXopbI8J3TDReVlkTgMUxE= github.com/mgutz/ansi v0.0.0-20200706080929-d51e80ef957d h1:5PJl274Y63IEHC+7izoQE9x6ikvDFZS2mDVS3drnohI= github.com/mgutz/ansi v0.0.0-20200706080929-d51e80ef957d/go.mod h1:01TrycV0kFyexm33Z7vhZRXopbI8J3TDReVlkTgMUxE= @@ -141,25 +161,26 @@ github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd/go.mod h1:6dJ github.com/modern-go/reflect2 v1.0.2/go.mod h1:yWuevngMOJpCy52FWWMvUC8ws7m/LJsjYzDa0/r8luk= github.com/modern-go/reflect2 v1.0.3-0.20250322232337-35a7c28c31ee h1:W5t00kpgFdJifH4BDsTlE89Zl93FEloxaWZfGcifgq8= github.com/modern-go/reflect2 v1.0.3-0.20250322232337-35a7c28c31ee/go.mod h1:yWuevngMOJpCy52FWWMvUC8ws7m/LJsjYzDa0/r8luk= +github.com/muesli/ansi v0.0.0-20230316100256-276c6243b2f6 h1:ZK8zHtRHOkbHy6Mmr5D264iyp3TiX5OmNcI5cIARiQI= +github.com/muesli/ansi v0.0.0-20230316100256-276c6243b2f6/go.mod h1:CJlz5H+gyd6CUWT45Oy4q24RdLyn7Md9Vj2/ldJBSIo= +github.com/muesli/cancelreader v0.2.2 h1:3I4Kt4BQjOR54NavqnDogx/MIoWBFa0StPA8ELUXHmA= +github.com/muesli/cancelreader v0.2.2/go.mod h1:3XuTXfFS2VjM+HTLZY9Ak0l6eUKfijIfMUZ4EgX0QYo= +github.com/muesli/termenv v0.16.0 h1:S5AlUN9dENB57rsbnkPyfdGuWIlkmzJjbFf0Tf5FWUc= +github.com/muesli/termenv v0.16.0/go.mod h1:ZRfOIKPFDYQoDFF4Olj7/QJbW60Ol/kL1pU3VfY/Cnk= github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRIccs7FGNTlIRMkT8wgtp5eCXdBlqhYGL6U= github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/rivo/uniseg v0.2.0/go.mod h1:J6wj4VEh+S6ZtnVlnTBMWIodfgj8LQOQFoIToxlJtxc= +github.com/rivo/uniseg v0.4.7 h1:WUdvkW8uEhrYfLC4ZzdpI2ztxP1I582+49Oc5Mq64VQ= +github.com/rivo/uniseg v0.4.7/go.mod h1:FN3SvrM+Zdj16jyLfmOkMNblXMcoc8DfTHruCPUcx88= github.com/russross/blackfriday/v2 v2.1.0 h1:JIOH55/0cWyOuilr9/qlrm0BSXldqnqwMsf35Ld67mk= github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM= -github.com/samber/lo v1.53.0 h1:t975lj2py4kJPQ6haz1QMgtId2gtmfktACxIXArw3HM= -github.com/samber/lo v1.53.0/go.mod h1:4+MXEGsJzbKGaUEQFKBq2xtfuznW9oz/WrgyzMzRoM0= -github.com/samber/slog-common v0.22.0 h1:WyPxYRg/c5xUmxZJbtd0QgysHlLBhRA+MngKdJieHxE= -github.com/samber/slog-common v0.22.0/go.mod h1:d/6OaSlzdkl9PFpfRLgn8FwY1OW6EFmPtBpsHX4MrU0= -github.com/samber/slog-logrus/v2 v2.5.4 h1:ACS0VWNDJcpFRICkgzRvBAI8ms/LH3S7KrOhAB3SQ0g= -github.com/samber/slog-logrus/v2 v2.5.4/go.mod h1:JBnv/7Gn0ef/iVy2RuRnA2qYIAc0ttlr6/9L/me8jVI= github.com/sergi/go-diff v1.4.0 h1:n/SP9D5ad1fORl+llWyN+D6qoUETXNZARKjyY2/KVCw= github.com/sergi/go-diff v1.4.0/go.mod h1:A0bzQcvG0E7Rwjx0REVgAGH58e96+X0MeOfepqsbeW4= github.com/shiena/ansicolor v0.0.0-20230509054315-a9deabde6e02 h1:v9ezJDHA1XGxViAUSIoO/Id7Fl63u6d0YmsAm+/p2hs= github.com/shiena/ansicolor v0.0.0-20230509054315-a9deabde6e02/go.mod h1:RF16/A3L0xSa0oSERcnhd8Pu3IXSDZSK2gmGIMsttFE= -github.com/sirupsen/logrus v1.9.4 h1:TsZE7l11zFCLZnZ+teH4Umoq5BhEIfIzfRDZ1Uzql2w= -github.com/sirupsen/logrus v1.9.4/go.mod h1:ftWc9WdOfJ0a92nsE2jF5u5ZwH8Bv2zdeOC42RjbV2g= github.com/spf13/pflag v1.0.10 h1:4EBh2KAYBwaONj6b2Ye1GiHfwjqyROoF4RwYO+vPwFk= github.com/spf13/pflag v1.0.10/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= @@ -181,6 +202,8 @@ github.com/urfave/cli/v2 v2.27.7 h1:bH59vdhbjLv3LAvIu6gd0usJHgoTTPhCFib8qqOwXYU= github.com/urfave/cli/v2 v2.27.7/go.mod h1:CyNAG/xg+iAOg0N4MPGZqVmv2rCoP267496AOXUZjA4= github.com/x448/float16 v0.8.4 h1:qLwI1I70+NjRFUR3zs1JPUCgaCXSh3SW62uAKT1mSBM= github.com/x448/float16 v0.8.4/go.mod h1:14CWIYCyZA/cWjXOioeEpHeN/83MdbZDRQHoFcYsOfg= +github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e h1:JVG44RsyaB9T2KIHavMF/ppJZNG9ZpyihvCd0w101no= +github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e/go.mod h1:RbqR21r5mrJuqunuUZ/Dhy/avygyECGrLceyNeo4LiM= github.com/xrash/smetrics v0.0.0-20250705151800-55b8f293f342 h1:FnBeRrxr7OU4VvAzt5X7s6266i6cSVkkFPS0TuXWbIg= github.com/xrash/smetrics v0.0.0-20250705151800-55b8f293f342/go.mod h1:Ohn+xnUBiLI6FVj/9LpzZWtj1/D6lUovWYBkxHVV3aM= github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY= @@ -194,6 +217,8 @@ golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5y golang.org/x/crypto v0.6.0/go.mod h1:OFC/31mSvZgRz0V1QTNCzfAI1aIRzbiufJtkMIlEp58= golang.org/x/crypto v0.53.0 h1:QZ4Muo8THX6CizN2vPPd5fBGHyogrdK9fG4wLPFUsto= golang.org/x/crypto v0.53.0/go.mod h1:DNLU434OwVakk9PzuwV8w62mAJpRJL3vsgcfp4Qnsio= +golang.org/x/exp v0.0.0-20220909182711-5c715a9e8561 h1:MDc5xs78ZrZr3HMQugiXOAkSZtfTpbJLDr/lwfgO53E= +golang.org/x/exp v0.0.0-20220909182711-5c715a9e8561/go.mod h1:cyybsKvd6eL0RnXn6p/Grxp8F5bW7iYuBgsNCOHpMYE= golang.org/x/mod v0.6.0-dev.0.20220419223038-86c51ed26bb4/go.mod h1:jJ57K6gSWd91VN4djpZkiMVwK6gcyfeH4XE8wZrZaV4= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20200114155413-6afb5195e5aa/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= @@ -211,6 +236,7 @@ golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5h golang.org/x/sys v0.0.0-20190222072716-a9d3bda3a223/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= diff --git a/internal/display/display.go b/internal/display/display.go new file mode 100644 index 000000000..d78f8c6b7 --- /dev/null +++ b/internal/display/display.go @@ -0,0 +1,155 @@ +package display + +import ( + "context" + "fmt" + "io" + "log/slog" + "sync" + + "github.com/charmbracelet/lipgloss" + log "github.com/k0sproject/k0sctl/internal/log" +) + +// dumpLines is how many recent per-host log lines are shown on failure. +const dumpLines = 15 + +// Display is the slog.Handler that renders k0sctl's screen output. It keeps +// per-host ring buffers of recent records regardless of the visible level so +// that failures can be explained, and delegates visible records either to a +// plain line renderer or to a live TTY renderer. +type Display struct { + st *state + // attrs mirrors handler-scoped attributes (attached via Logger.With) + // so parseEvent sees them alongside the record's own attributes. + attrs []slog.Attr + // screen is the plain line renderer carrying the same scoped attrs. + screen slog.Handler +} + +type state struct { + rings *rings + out io.Writer + level slog.Leveler + tty *ttyRenderer + + mu sync.Mutex + dumped bool +} + +// NewPlain returns a Display that renders classic line output. Used for +// non-TTY output (pipes, CI), --debug/--trace, and as the fallback renderer. +func NewPlain(out io.Writer, level slog.Leveler, colors bool) *Display { + return &Display{ + st: &state{rings: newRings(), out: out, level: level}, + screen: log.NewScreenHandler(out, level, colors), + } +} + +// NewTTY returns a Display that renders a live progress view on the given +// terminal writer. interactive enables keyboard input (stdin is a TTY); +// onInterrupt is called when the user presses ctrl-c, and should cancel the +// ongoing operation. +func NewTTY(out io.Writer, level slog.Leveler, interactive bool, onInterrupt func()) *Display { + st := &state{rings: newRings(), out: out, level: level} + st.tty = newTTYRenderer(st, out, interactive, onInterrupt) + return &Display{ + st: st, + screen: log.NewScreenHandler(out, level, true), + } +} + +// Stop finalizes the display. For the TTY renderer this shuts down the live +// view and restores the terminal. Safe to call multiple times and on plain +// displays. +func (d *Display) Stop() { + if d.st.tty != nil { + d.st.tty.stop() + } +} + +// Enabled implements slog.Handler. The display always wants records: the +// ring buffers capture below-visible-level records for failure forensics. +func (d *Display) Enabled(_ context.Context, _ slog.Level) bool { + return true +} + +// Handle implements slog.Handler. +func (d *Display) Handle(ctx context.Context, r slog.Record) error { + ev := parseEvent(d.attrs, r) + d.st.rings.add(ev) + + // a fatal record ends the run: explain failed hosts before the final + // message, in both plain and TTY modes + if r.Level >= log.LevelFatal { + if d.st.tty != nil { + d.st.tty.stop() + } + d.st.dumpFailures() + } + + if d.st.tty != nil && d.st.tty.running() { + // the live view starts on the first phase record: everything before + // it (logo, banners, config parsing) is direct terminal output that + // must complete before bubbletea switches the terminal to raw mode + if d.st.tty.hasStarted() || ev.Phase != "" { + d.st.tty.send(ev) + return nil + } + } + + if d.screen.Enabled(ctx, r.Level) { + return d.screen.Handle(ctx, r) + } + return nil +} + +// WithAttrs implements slog.Handler. +func (d *Display) WithAttrs(attrs []slog.Attr) slog.Handler { + next := make([]slog.Attr, 0, len(d.attrs)+len(attrs)) + next = append(next, d.attrs...) + next = append(next, attrs...) + return &Display{st: d.st, attrs: next, screen: d.screen.WithAttrs(attrs)} +} + +// WithGroup implements slog.Handler. k0sctl doesn't use attr groups; flatten. +func (d *Display) WithGroup(_ string) slog.Handler { + return d +} + +// levelStyle returns the style used for log tail lines of the given level: +// warnings and errors get their level color, info stays plain, and +// debug/trace chatter renders faint. +func levelStyle(r *lipgloss.Renderer, l slog.Level) lipgloss.Style { + switch { + case l >= slog.LevelError: + return r.NewStyle().Foreground(lipgloss.Color("1")) + case l >= slog.LevelWarn: + return r.NewStyle().Foreground(lipgloss.Color("3")) + case l >= slog.LevelInfo: + return r.NewStyle() + default: + return r.NewStyle().Faint(true) + } +} + +// dumpFailures prints the recent log tail of every host that reported an +// error. It runs at most once per display. Unlike the live tails, dump lines +// carry timestamps: the timing of what led up to the failure is the point. +func (st *state) dumpFailures() { + st.mu.Lock() + defer st.mu.Unlock() + if st.dumped { + return + } + st.dumped = true + + r := lipgloss.NewRenderer(st.out) + for host, events := range st.rings.failures(dumpLines) { + fmt.Fprintf(st.out, "\nlast %d log entries for host %s:\n", len(events), host) + for _, ev := range events { + line := fmt.Sprintf(" %s %s", ev.Time.Format("15:04:05"), ev.line()) + fmt.Fprintln(st.out, levelStyle(r, ev.Level).Render(line)) + } + } +} diff --git a/internal/display/display_test.go b/internal/display/display_test.go new file mode 100644 index 000000000..ca0884ea8 --- /dev/null +++ b/internal/display/display_test.go @@ -0,0 +1,81 @@ +package display + +import ( + "bytes" + "log/slog" + "testing" + + log "github.com/k0sproject/k0sctl/internal/log" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestPlainDisplayRendersVisibleRecords(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewPlain(&buf, slog.LevelInfo, false)) + + logger.Info("visible", log.KeyHost, "h1") + + assert.Equal(t, "INFO h1: visible\n", buf.String()) +} + +func TestPlainDisplayCapturesBelowLevelRecordsInRings(t *testing.T) { + var buf bytes.Buffer + d := NewPlain(&buf, slog.LevelInfo, false) + logger := slog.New(d) + + logger.Debug("hidden detail", log.KeyHost, "h1") + + assert.Empty(t, buf.String(), "below-level record must not render") + tail := d.st.rings.tail("h1", 5) + require.Len(t, tail, 1) + assert.Equal(t, "hidden detail", tail[0].Message) +} + +func TestPlainDisplayWithAttrsRoutesToRings(t *testing.T) { + var buf bytes.Buffer + d := NewPlain(&buf, slog.LevelInfo, false) + logger := slog.New(d).With(log.KeyHost, "scoped") + + logger.Info("via scoped logger") + + assert.Equal(t, "INFO scoped: via scoped logger\n", buf.String()) + require.Len(t, d.st.rings.tail("scoped", 5), 1) +} + +func TestPlainDisplayDumpsFailedHostTailOnFatal(t *testing.T) { + var buf bytes.Buffer + d := NewPlain(&buf, slog.LevelInfo, false) + logger := slog.New(d) + + logger.Debug("step one", log.KeyHost, "h1") + logger.Error("phase failed", log.KeyHost, "h1", log.KeyError, "kaboom") + logger.Info("unrelated", log.KeyHost, "h2") + buf.Reset() + + logger.Log(t.Context(), log.LevelFatal, "run failed") + + out := buf.String() + assert.Contains(t, out, "last 2 log entries for host h1:") + assert.Contains(t, out, "step one") + assert.Contains(t, out, "phase failed error=kaboom") + assert.NotContains(t, out, "h2", "healthy hosts must not be dumped") + assert.Contains(t, out, "FATA run failed") + // the dump must precede the fatal message + assert.Less(t, bytes.Index(buf.Bytes(), []byte("last 2 log entries")), bytes.Index(buf.Bytes(), []byte("FATA"))) + + // a second fatal must not dump again + buf.Reset() + logger.Log(t.Context(), log.LevelFatal, "again") + assert.NotContains(t, buf.String(), "last 2 log entries") +} + +func TestPlainDisplayNoDumpWithoutFailures(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewPlain(&buf, slog.LevelInfo, false)) + + logger.Info("all good", log.KeyHost, "h1") + logger.Log(t.Context(), log.LevelFatal, "fatal anyway") + + assert.NotContains(t, buf.String(), "log entries for host") +} diff --git a/internal/display/event.go b/internal/display/event.go new file mode 100644 index 000000000..0cb579f00 --- /dev/null +++ b/internal/display/event.go @@ -0,0 +1,135 @@ +// Package display renders k0sctl's progress for the user. It consumes the +// same slog record stream that feeds the log file: log records carry +// structured attributes (host, phase, duration, attempt) that displays use +// to route and render without parsing messages. Two modes exist: a plain +// line-based renderer for non-TTY output, --debug/--trace and CI, and a live +// TTY renderer. +package display + +import ( + "log/slog" + "strconv" + "strings" + "time" + + log "github.com/k0sproject/k0sctl/internal/log" +) + +// Event is a parsed log record with k0sctl's routing attributes extracted. +type Event struct { + Time time.Time + Level slog.Level + Message string + Host string + Phase string + Step int64 + Total int64 + Duration time.Duration + Attempt int64 + Err string + // Rest contains the remaining attributes, pre-rendered as "key=value". + Rest []string +} + +// parseEvent extracts routing attributes from handler-scoped attrs (attached +// via Logger.With) and the record's own attrs. +func parseEvent(attrs []slog.Attr, r slog.Record) Event { + ev := Event{Time: r.Time, Level: r.Level, Message: r.Message} + + collect := func(a slog.Attr) { + a.Value = a.Value.Resolve() + switch a.Key { + case log.KeyHost: + if ev.Host == "" { + ev.Host = normalizeHost(a.Value.String()) + } + case log.KeyPhase: + if ev.Phase == "" { + ev.Phase = a.Value.String() + } + case log.KeyPhaseStep: + if a.Value.Kind() == slog.KindInt64 { + ev.Step = a.Value.Int64() + } + case log.KeyPhaseTotal: + if a.Value.Kind() == slog.KindInt64 { + ev.Total = a.Value.Int64() + } + case log.KeyDuration: + if a.Value.Kind() == slog.KindDuration { + ev.Duration = a.Value.Duration() + } + case log.KeyAttempt: + if a.Value.Kind() == slog.KindInt64 { + ev.Attempt = a.Value.Int64() + } + case log.KeyError: + if ev.Err == "" { + ev.Err = a.Value.String() + } + default: + ev.Rest = append(ev.Rest, a.Key+"="+attrValue(a.Value.String())) + } + } + + for _, a := range attrs { + collect(a) + } + r.Attrs(func(a slog.Attr) bool { + collect(a) + return true + }) + + return ev +} + +// line renders the event as a single plain-text line for log tails. It +// carries no timestamp or level tag: the level is conveyed by color at +// render time, and the failure dump prefixes timestamps itself. +func (ev Event) line() string { + var b strings.Builder + b.WriteString(ev.Message) + if ev.Attempt > 0 { + b.WriteString(" attempt=") + b.WriteString(strconv.FormatInt(ev.Attempt, 10)) + } + if ev.Err != "" { + b.WriteString(" error=") + b.WriteString(attrValue(ev.Err)) + } + for _, kv := range ev.Rest { + b.WriteString(" ") + b.WriteString(kv) + } + return b.String() +} + +// normalizeHost merges the two host identities rig uses: before a connection +// exists, rig tags records with the connection config's string, which renders +// as e.g. `ssh.Config{addr:port}`; once connected, records carry plain +// `addr:port`. k0sctl's Host.String() produces the latter, so the config +// wrapper is stripped to route both to the same host. +func normalizeHost(host string) string { + if start := strings.Index(host, ".Config{"); start > 0 && strings.HasSuffix(host, "}") { + if inner := host[start+len(".Config{") : len(host)-1]; inner != "" { + return inner + } + } + return host +} + +// attrValueMax caps rendered attribute values in log tails; remote command +// scripts can be kilobytes of multi-line text. +const attrValueMax = 120 + +// attrValue makes an attribute value fit on a single tail line: control +// characters are escaped and long values truncated. +func attrValue(s string) string { + if len(s) > attrValueMax { + s = s[:attrValueMax] + "…" + } + if strings.ContainsAny(s, " \t\n\r\"") { + return strconv.Quote(s) + } + return s +} diff --git a/internal/display/event_test.go b/internal/display/event_test.go new file mode 100644 index 000000000..cbaa85705 --- /dev/null +++ b/internal/display/event_test.go @@ -0,0 +1,96 @@ +package display + +import ( + "log/slog" + "strings" + "testing" + "time" + + log "github.com/k0sproject/k0sctl/internal/log" + "github.com/stretchr/testify/assert" +) + +func record(t *testing.T, level slog.Level, msg string, args ...any) slog.Record { + t.Helper() + r := slog.NewRecord(time.Date(2026, 7, 2, 12, 34, 56, 0, time.Local), level, msg, 0) + r.Add(args...) + return r +} + +func TestParseEventRoutingAttrs(t *testing.T) { + r := record(t, slog.LevelInfo, "hello", + log.KeyHost, "node1:22", + log.KeyPhase, "Connect", + log.KeyDuration, 1500*time.Millisecond, + log.KeyAttempt, int64(3), + log.KeyError, "boom", + ) + + ev := parseEvent(nil, r) + + assert.Equal(t, "hello", ev.Message) + assert.Equal(t, "node1:22", ev.Host) + assert.Equal(t, "Connect", ev.Phase) + assert.Equal(t, 1500*time.Millisecond, ev.Duration) + assert.Equal(t, int64(3), ev.Attempt) + assert.Equal(t, "boom", ev.Err) + assert.Empty(t, ev.Rest) +} + +func TestParseEventHandlerScopedAttrsWinOverRecordAttrs(t *testing.T) { + scoped := []slog.Attr{slog.String(log.KeyHost, "scoped-host")} + r := record(t, slog.LevelInfo, "msg", log.KeyHost, "record-host") + + ev := parseEvent(scoped, r) + + assert.Equal(t, "scoped-host", ev.Host) +} + +func TestParseEventUnknownAttrsLandInRest(t *testing.T) { + r := record(t, slog.LevelDebug, "exec", "command", "uptime", "sudo", "true") + + ev := parseEvent(nil, r) + + assert.Equal(t, []string{"command=uptime", "sudo=true"}, ev.Rest) +} + +func TestEventLine(t *testing.T) { + r := record(t, slog.LevelInfo, "retrying", + log.KeyAttempt, int64(4), + log.KeyError, "connection refused", + "component", "test", + ) + + line := parseEvent(nil, r).line() + + assert.Equal(t, `retrying attempt=4 error="connection refused" component=test`, line) +} + +func TestNormalizeHostStripsConfigWrapper(t *testing.T) { + // rig tags records with the connection config's string before a + // connection exists; both identities must route to the same host + assert.Equal(t, "10.0.0.1:22", normalizeHost("ssh.Config{10.0.0.1:22}")) + assert.Equal(t, "10.0.0.1:5985", normalizeHost("winrm.Config{10.0.0.1:5985}")) + assert.Equal(t, "10.0.0.1:22", normalizeHost("10.0.0.1:22")) + assert.Equal(t, "localhost", normalizeHost("localhost")) + assert.Equal(t, "x.Config{}", normalizeHost("x.Config{}"), "empty inner keeps original") +} + +func TestParseEventNormalizesHost(t *testing.T) { + r := record(t, slog.LevelDebug, "msg", log.KeyHost, "ssh.Config{10.0.0.1:22}") + + assert.Equal(t, "10.0.0.1:22", parseEvent(nil, r).Host) +} + +func TestEventLineSanitizesMultilineAndLongValues(t *testing.T) { + r := record(t, slog.LevelDebug, "executing command", + "command", "line one\nline two\nline three", + "blob", strings.Repeat("x", 500), + ) + + line := parseEvent(nil, r).line() + + assert.NotContains(t, line, "\n", "tail lines must stay single-line") + assert.Contains(t, line, `command="line one\nline two\nline three"`) + assert.Less(t, len(line), 350, "long values must be truncated") +} diff --git a/internal/display/rings.go b/internal/display/rings.go new file mode 100644 index 000000000..83ff4327a --- /dev/null +++ b/internal/display/rings.go @@ -0,0 +1,92 @@ +package display + +import ( + "log/slog" + "slices" + "sync" +) + +// ringSize is how many recent records are kept per host for failure +// forensics and live log tails. +const ringSize = 100 + +type ring struct { + events [ringSize]Event + next int + count int +} + +func (r *ring) add(ev Event) { + r.events[r.next] = ev + r.next = (r.next + 1) % ringSize + if r.count < ringSize { + r.count++ + } +} + +// tail returns up to n most recent events, oldest first. +func (r *ring) tail(n int) []Event { + if n > r.count { + n = r.count + } + out := make([]Event, 0, n) + for i := r.count - n; i < r.count; i++ { + out = append(out, r.events[(r.next-r.count+i+ringSize*2)%ringSize]) + } + return out +} + +// rings keeps per-host buffers of recent events regardless of the visible +// log level, plus the set of hosts that have reported errors. +type rings struct { + mu sync.Mutex + hosts map[string]*ring + failed []string +} + +func newRings() *rings { + return &rings{hosts: make(map[string]*ring)} +} + +func (rs *rings) add(ev Event) { + if ev.Host == "" { + return + } + rs.mu.Lock() + defer rs.mu.Unlock() + r, ok := rs.hosts[ev.Host] + if !ok { + r = &ring{} + rs.hosts[ev.Host] = r + } + r.add(ev) + if ev.Level >= slog.LevelError && !slices.Contains(rs.failed, ev.Host) { + rs.failed = append(rs.failed, ev.Host) + } +} + +// failures returns the hosts that logged errors and up to n recent events +// for each, oldest first. +func (rs *rings) failures(n int) map[string][]Event { + rs.mu.Lock() + defer rs.mu.Unlock() + if len(rs.failed) == 0 { + return nil + } + out := make(map[string][]Event, len(rs.failed)) + for _, host := range rs.failed { + out[host] = rs.hosts[host].tail(n) + } + return out +} + +// tail returns up to n recent events for a host, oldest first. +func (rs *rings) tail(host string, n int) []Event { + rs.mu.Lock() + defer rs.mu.Unlock() + r, ok := rs.hosts[host] + if !ok { + return nil + } + return r.tail(n) +} diff --git a/internal/display/rings_test.go b/internal/display/rings_test.go new file mode 100644 index 000000000..6b586e4e8 --- /dev/null +++ b/internal/display/rings_test.go @@ -0,0 +1,63 @@ +package display + +import ( + "fmt" + "log/slog" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func hostEvent(host string, level slog.Level, msg string) Event { + return Event{Host: host, Level: level, Message: msg} +} + +func TestRingWrapsAroundKeepingMostRecent(t *testing.T) { + rs := newRings() + for i := range ringSize + 10 { + rs.add(hostEvent("h1", slog.LevelDebug, fmt.Sprintf("msg-%d", i))) + } + + tail := rs.tail("h1", 3) + require.Len(t, tail, 3) + assert.Equal(t, fmt.Sprintf("msg-%d", ringSize+7), tail[0].Message) + assert.Equal(t, fmt.Sprintf("msg-%d", ringSize+8), tail[1].Message) + assert.Equal(t, fmt.Sprintf("msg-%d", ringSize+9), tail[2].Message) +} + +func TestRingTailShorterThanRequested(t *testing.T) { + rs := newRings() + rs.add(hostEvent("h1", slog.LevelInfo, "only")) + + tail := rs.tail("h1", 10) + require.Len(t, tail, 1) + assert.Equal(t, "only", tail[0].Message) +} + +func TestRingsIgnoreHostlessEvents(t *testing.T) { + rs := newRings() + rs.add(Event{Level: slog.LevelError, Message: "no host"}) + + assert.Empty(t, rs.hosts) + assert.Nil(t, rs.failures(5)) +} + +func TestRingsTrackFailedHostsOnce(t *testing.T) { + rs := newRings() + rs.add(hostEvent("h1", slog.LevelError, "fail 1")) + rs.add(hostEvent("h1", slog.LevelError, "fail 2")) + rs.add(hostEvent("h2", slog.LevelInfo, "fine")) + + assert.Equal(t, []string{"h1"}, rs.failed) + + failures := rs.failures(5) + require.Len(t, failures, 1) + require.Len(t, failures["h1"], 2) + assert.Equal(t, "fail 1", failures["h1"][0].Message) +} + +func TestRingsTailUnknownHost(t *testing.T) { + rs := newRings() + assert.Nil(t, rs.tail("nope", 3)) +} diff --git a/internal/display/tty.go b/internal/display/tty.go new file mode 100644 index 000000000..0a6bea905 --- /dev/null +++ b/internal/display/tty.go @@ -0,0 +1,470 @@ +package display + +import ( + "fmt" + "io" + "log/slog" + "os" + "strings" + "sync" + "time" + + tea "github.com/charmbracelet/bubbletea" + "github.com/charmbracelet/lipgloss" + "github.com/charmbracelet/x/ansi" +) + +const ( + // autoTailHosts: per-host log tails show automatically when at most + // this many hosts are active in the current phase + autoTailHosts = 4 + // tailLines is how many recent records a host tail shows + tailLines = 3 + // peekTailLines is the deeper tail shown in peek mode (space key) + peekTailLines = 10 + // maxRows caps the host rows rendered in the live region + maxRows = 12 +) + +var spinnerFrames = []string{"⠋", "⠙", "⠹", "⠸", "⠼", "⠴", "⠦", "⠧", "⠇", "⠏"} + +type ( + eventMsg struct{ ev Event } + stopMsg struct{} + tickMsg struct{} +) + +// ttyRenderer runs the live bubbletea view. It starts lazily on the first +// event and stops before the process exits or a fatal record is printed. +type ttyRenderer struct { + st *state + out io.Writer + interactive bool + onInterrupt func() + + mu sync.Mutex + prog *tea.Program + started bool + stopped bool + forceExit bool + done chan struct{} +} + +func newTTYRenderer(st *state, out io.Writer, interactive bool, onInterrupt func()) *ttyRenderer { + return &ttyRenderer{st: st, out: out, interactive: interactive, onInterrupt: onInterrupt, done: make(chan struct{})} +} + +func (t *ttyRenderer) running() bool { + t.mu.Lock() + defer t.mu.Unlock() + return !t.stopped +} + +func (t *ttyRenderer) hasStarted() bool { + t.mu.Lock() + defer t.mu.Unlock() + return t.started +} + +func (t *ttyRenderer) send(ev Event) { + t.mu.Lock() + if t.stopped { + t.mu.Unlock() + return + } + if !t.started { + t.start() + } + prog := t.prog + t.mu.Unlock() + prog.Send(eventMsg{ev: ev}) +} + +// start launches the bubbletea program. Callers must hold t.mu. +func (t *ttyRenderer) start() { + opts := []tea.ProgramOption{tea.WithOutput(t.out), tea.WithoutSignalHandler()} + if !t.interactive { + opts = append(opts, tea.WithInput(nil)) + } + t.prog = tea.NewProgram(newTTYModel(t), opts...) + t.started = true + go func() { + _, err := t.prog.Run() + t.mu.Lock() + t.stopped = true + force := t.forceExit + t.mu.Unlock() + close(t.done) + if force { + os.Exit(130) + } + if err != nil { + fmt.Fprintf(t.out, "display error: %v\n", err) + } + }() +} + +// stop shuts down the live view and waits for the terminal to be restored. +func (t *ttyRenderer) stop() { + t.mu.Lock() + if !t.started || t.stopped { + t.stopped = true + t.mu.Unlock() + return + } + prog := t.prog + t.mu.Unlock() + prog.Send(stopMsg{}) + select { + case <-t.done: + case <-time.After(2 * time.Second): + prog.Kill() + <-t.done + } +} + +// maxSteps caps the per-host stack of progress messages shown in the +// expanded host view. +const maxSteps = 5 + +// hostStep is one meaningful (info or higher) progress message of a host. +type hostStep struct { + msg string + level slog.Level +} + +type hostRow struct { + host string + steps []hostStep + attempt int64 + err string + level slog.Level +} + +// latest returns the most recent progress message, or "" when none arrived. +func (r *hostRow) latest() string { + if len(r.steps) == 0 { + return "" + } + return r.steps[len(r.steps)-1].msg +} + +type ttyModel struct { + t *ttyRenderer + r *lipgloss.Renderer + width int + spin int + + phase string + phaseStep int64 + phaseTotal int64 + phaseStart time.Time + + order []string + rows map[string]*hostRow + + tailsAll bool + peek bool // deeper tails for all hosts, toggled with space + focus int // index into order, -1 = none + interrupts int + + styleDim lipgloss.Style + styleGreen lipgloss.Style + styleRed lipgloss.Style + styleYellow lipgloss.Style + styleCyan lipgloss.Style +} + +func newTTYModel(t *ttyRenderer) *ttyModel { + r := lipgloss.NewRenderer(t.out) + return &ttyModel{ + t: t, + r: r, + width: 80, + rows: map[string]*hostRow{}, + focus: -1, + styleDim: r.NewStyle().Faint(true), + styleGreen: r.NewStyle().Foreground(lipgloss.Color("2")), + styleRed: r.NewStyle().Foreground(lipgloss.Color("1")), + styleYellow: r.NewStyle().Foreground(lipgloss.Color("3")), + styleCyan: r.NewStyle().Foreground(lipgloss.Color("6")), + } +} + +func tick() tea.Cmd { + return tea.Tick(150*time.Millisecond, func(time.Time) tea.Msg { return tickMsg{} }) +} + +func (m *ttyModel) Init() tea.Cmd { + return tick() +} + +func (m *ttyModel) Update(msg tea.Msg) (tea.Model, tea.Cmd) { + switch msg := msg.(type) { + case tea.WindowSizeMsg: + m.width = msg.Width + case tickMsg: + m.spin++ + return m, tick() + case stopMsg: + m.phase = "" + return m, tea.Quit + case tea.KeyMsg: + return m.handleKey(msg) + case eventMsg: + return m.handleEvent(msg.ev) + } + return m, nil +} + +func (m *ttyModel) handleKey(msg tea.KeyMsg) (tea.Model, tea.Cmd) { + switch key := msg.String(); key { + case "ctrl+c": + m.interrupts++ + if m.interrupts == 1 { + if m.t.onInterrupt != nil { + m.t.onInterrupt() + } + return m, tea.Println(m.styleYellow.Render("Aborting... Press Ctrl-C again to exit now.")) + } + m.t.mu.Lock() + m.t.forceExit = true + m.t.mu.Unlock() + return m, tea.Quit + case "l": + m.tailsAll = !m.tailsAll + m.focus = -1 + case " ": + m.peek = !m.peek + case "esc", "0": + m.focus = -1 + m.tailsAll = false + m.peek = false + default: + if len(key) == 1 && key[0] >= '1' && key[0] <= '9' { + idx := int(key[0] - '1') + if idx < len(m.order) { + if m.focus == idx { + m.focus = -1 + } else { + m.focus = idx + m.tailsAll = false + } + } + } + } + return m, nil +} + +func (m *ttyModel) handleEvent(ev Event) (tea.Model, tea.Cmd) { + // phase completion record: persist a result line above the live region + if ev.Phase != "" && ev.Duration > 0 { + var line string + if ev.Err != "" { + // keep it on one line: multi-line content confuses the live + // region repaint, and the full error follows in the final output + line = m.styleRed.Render(fmt.Sprintf("✘ %s (%s): %s", ev.Phase, ev.Duration.Truncate(100*time.Millisecond), firstLine(ev.Err))) + } else { + line = m.styleGreen.Render("✔ ") + ev.Phase + m.styleDim.Render(fmt.Sprintf(" (%s)", ev.Duration.Truncate(100*time.Millisecond))) + } + if ev.Phase == m.phase { + m.phase = "" + m.order = nil + m.rows = map[string]*hostRow{} + m.focus = -1 + } + return m, tea.Println(line) + } + + // phase start record + if ev.Phase != "" && ev.Level == slog.LevelInfo { + m.phase = ev.Phase + m.phaseStep = ev.Step + m.phaseTotal = ev.Total + m.phaseStart = ev.Time + m.order = nil + m.rows = map[string]*hostRow{} + m.focus = -1 + return m, nil + } + + if ev.Host != "" { + row, ok := m.rows[ev.Host] + if !ok { + row = &hostRow{host: ev.Host} + m.rows[ev.Host] = row + m.order = append(m.order, ev.Host) + } + switch { + case ev.Attempt > 0: + row.attempt = ev.Attempt + row.err = ev.Err + case ev.Level >= slog.LevelInfo: + // meaningful progress messages stack up on the row; debug + // chatter stays in the log feed below the stack + if row.latest() != ev.Message { + row.steps = append(row.steps, hostStep{msg: ev.Message, level: ev.Level}) + if len(row.steps) > maxSteps { + row.steps = row.steps[1:] + } + } + row.attempt = 0 + row.err = ev.Err + } + if ev.Level > row.level { + row.level = ev.Level + } + return m, nil + } + + // non-host records: persist warnings and errors and informative lines + switch { + case ev.Level >= slog.LevelError: + return m, tea.Println(m.styleRed.Render(firstLine(ev.Message))) + case ev.Level >= slog.LevelWarn: + return m, tea.Println(m.styleYellow.Render(firstLine(ev.Message))) + case ev.Level >= slog.LevelInfo: + return m, tea.Println(firstLine(ev.Message)) + } + return m, nil +} + +// retrySuffix renders the live retry counter and error of a host row. +func (m *ttyModel) retrySuffix(row *hostRow) string { + switch { + case row.attempt > 0 && row.err != "": + return m.styleYellow.Render(fmt.Sprintf(" ⟳ %d", row.attempt)) + m.styleDim.Render(fmt.Sprintf(" (%s)", row.err)) + case row.attempt > 0: + return m.styleYellow.Render(fmt.Sprintf(" ⟳ %d", row.attempt)) + case row.err != "": + return m.styleRed.Render(fmt.Sprintf(" (%s)", row.err)) + } + return "" +} + +// feed returns the host's most recent below-info records: the debug stream +// that runs under the step stack. Info and higher records already appear in +// the stack itself. +func (m *ttyModel) feed(host string, n int) []Event { + events := m.t.st.rings.tail(host, ringSize) + var out []Event + for _, ev := range events { + if ev.Level < slog.LevelInfo && ev.Attempt == 0 { + out = append(out, ev) + } + } + if len(out) > n { + out = out[len(out)-n:] + } + return out +} + +// firstLine reduces a possibly multi-line message to its first line; content +// persisted above the live region must be single-line or the repaint garbles. +func firstLine(s string) string { + if first, _, found := strings.Cut(s, "\n"); found { + return first + " …" + } + return s +} + +func (m *ttyModel) View() string { + if m.phase == "" { + return "" + } + + var b strings.Builder + elapsed := time.Since(m.phaseStart).Truncate(time.Second) + b.WriteString(m.styleCyan.Render(spinnerFrames[m.spin%len(spinnerFrames)])) + b.WriteString(" ") + b.WriteString(m.phase) + if m.phaseTotal > 0 { + b.WriteString(m.styleDim.Render(fmt.Sprintf(" · %d/%d", m.phaseStep, m.phaseTotal))) + } + if elapsed >= time.Second { + b.WriteString(m.styleDim.Render(fmt.Sprintf(" (%s)", elapsed))) + } + b.WriteString("\n") + + hostWidth := 0 + for _, h := range m.order { + hostWidth = max(hostWidth, len(h)) + } + + depth := tailLines + if m.peek { + depth = peekTailLines + } + showTail := func(i int) bool { + if m.peek { + return true + } + if m.focus >= 0 { + return m.focus == i + } + return m.tailsAll || len(m.order) <= autoTailHosts + } + + for i, h := range m.order { + if i >= maxRows { + b.WriteString(m.styleDim.Render(fmt.Sprintf(" … %d more hosts", len(m.order)-maxRows))) + b.WriteString("\n") + break + } + row := m.rows[h] + var line strings.Builder + line.WriteString(" ") + if m.t.interactive && len(m.order) > 1 && i < 9 { + line.WriteString(m.styleDim.Render(fmt.Sprintf("%d ", i+1))) + } + name := fmt.Sprintf("%-*s", hostWidth, h) + switch { + case row.level >= slog.LevelError: + line.WriteString(m.styleRed.Render(name)) + case row.level >= slog.LevelWarn: + line.WriteString(m.styleYellow.Render(name)) + default: + line.WriteString(name) + } + + if !showTail(i) { + // collapsed: a single line with the latest progress message + line.WriteString(" ") + if msg := row.latest(); msg != "" { + line.WriteString(msg) + } else if last := m.t.st.rings.tail(h, 1); len(last) > 0 { + // no meaningful status yet: show the latest log activity dimmed + line.WriteString(m.styleDim.Render(last[0].Message)) + } + line.WriteString(m.retrySuffix(row)) + b.WriteString(ansi.Truncate(line.String(), m.width, "…")) + b.WriteString("\n") + continue + } + + // expanded: the host's progress messages stack up under the name + // while the debug feed streams below the stack + b.WriteString(ansi.Truncate(line.String(), m.width, "…")) + b.WriteString("\n") + for si, step := range row.steps { + stepLine := " " + levelStyle(m.r, step.level).Render(step.msg) + if si == len(row.steps)-1 { + stepLine += m.retrySuffix(row) + } + b.WriteString(ansi.Truncate(stepLine, m.width, "…")) + b.WriteString("\n") + } + for _, tev := range m.feed(h, depth) { + b.WriteString(m.styleDim.Render(" │ ")) + b.WriteString(ansi.Truncate(levelStyle(m.r, tev.Level).Render(tev.line()), m.width-8, "…")) + b.WriteString("\n") + } + } + + if m.t.interactive && len(m.order) > 0 { + b.WriteString(m.styleDim.Render(" keys: space peek · 1-9 focus host logs · l all logs · 0 hide · ctrl-c abort")) + b.WriteString("\n") + } + + return b.String() +} diff --git a/internal/display/tty_test.go b/internal/display/tty_test.go new file mode 100644 index 000000000..6129bed64 --- /dev/null +++ b/internal/display/tty_test.go @@ -0,0 +1,216 @@ +package display + +import ( + "bytes" + "fmt" + "log/slog" + "testing" + "time" + + tea "github.com/charmbracelet/bubbletea" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// testModel builds a ttyModel without starting a bubbletea program. +func testModel(t *testing.T, interactive bool, onInterrupt func()) *ttyModel { + t.Helper() + st := &state{rings: newRings(), out: &bytes.Buffer{}, level: slog.LevelInfo} + r := newTTYRenderer(st, &bytes.Buffer{}, interactive, onInterrupt) + return newTTYModel(r) +} + +func update(t *testing.T, m *ttyModel, msg tea.Msg) tea.Cmd { + t.Helper() + _, cmd := m.Update(msg) + return cmd +} + +func phaseStart(title string) Event { + return Event{Phase: title, Level: slog.LevelInfo, Time: time.Now(), Message: "==> Running phase: " + title} +} + +func phaseEnd(title string, err string) Event { + return Event{Phase: title, Level: slog.LevelDebug, Duration: 2 * time.Second, Err: err, Message: "phase completed"} +} + +func TestTTYModelPhaseStartShowsLiveRegion(t *testing.T) { + m := testModel(t, false, nil) + + cmd := update(t, m, eventMsg{ev: phaseStart("Connect to hosts")}) + + assert.Nil(t, cmd) + assert.Contains(t, m.View(), "Connect to hosts") +} + +func TestTTYModelPhaseCompletionClearsLiveRegion(t *testing.T) { + m := testModel(t, false, nil) + update(t, m, eventMsg{ev: phaseStart("Connect to hosts")}) + + cmd := update(t, m, eventMsg{ev: phaseEnd("Connect to hosts", "")}) + + require.NotNil(t, cmd, "phase completion must persist a line via tea.Println") + assert.Empty(t, m.View()) +} + +func TestTTYModelStepStack(t *testing.T) { + m := testModel(t, false, nil) + update(t, m, eventMsg{ev: phaseStart("Install controllers")}) + steps := []string{"uploading k0s binary", "starting service", "waiting for service"} + for _, s := range steps { + update(t, m, eventMsg{ev: Event{Host: "h1", Level: slog.LevelInfo, Message: s}}) + } + // consecutive duplicates don't stack + update(t, m, eventMsg{ev: Event{Host: "h1", Level: slog.LevelInfo, Message: "waiting for service"}}) + + require.Len(t, m.rows["h1"].steps, 3) + view := m.View() + for _, s := range steps { + assert.Contains(t, view, s, "all progress steps stay visible in the stack") + } + + // the stack is capped at maxSteps, dropping the oldest + for i := range maxSteps { + update(t, m, eventMsg{ev: Event{Host: "h1", Level: slog.LevelInfo, Message: fmt.Sprintf("step-%d", i)}}) + } + require.Len(t, m.rows["h1"].steps, maxSteps) + assert.NotContains(t, m.View(), "uploading k0s binary") +} + +func TestTTYModelHostRowsInOrderWithRetryCounter(t *testing.T) { + m := testModel(t, false, nil) + update(t, m, eventMsg{ev: phaseStart("Upgrade")}) + update(t, m, eventMsg{ev: Event{Host: "h1", Level: slog.LevelInfo, Message: "starting upgrade"}}) + update(t, m, eventMsg{ev: Event{Host: "h2", Level: slog.LevelInfo, Message: "waiting"}}) + // retry event keeps the last status message, adds the counter + update(t, m, eventMsg{ev: Event{Host: "h1", Level: slog.LevelDebug, Message: "retrying", Attempt: 4, Err: "conn refused"}}) + + assert.Equal(t, []string{"h1", "h2"}, m.order) + view := m.View() + assert.Contains(t, view, "starting upgrade") + assert.Contains(t, view, "⟳ 4") + assert.Contains(t, view, "conn refused") + + // a regular event clears the retry counter again + update(t, m, eventMsg{ev: Event{Host: "h1", Level: slog.LevelInfo, Message: "service started"}}) + assert.NotContains(t, m.View(), "⟳") +} + +func TestTTYModelHostErrorMarksRow(t *testing.T) { + m := testModel(t, false, nil) + update(t, m, eventMsg{ev: phaseStart("Upgrade")}) + + cmd := update(t, m, eventMsg{ev: Event{Host: "h1", Level: slog.LevelError, Message: "phase failed", Err: "kaboom"}}) + + assert.Nil(t, cmd, "host records must not persist lines") + assert.Equal(t, slog.LevelError, m.rows["h1"].level) + assert.Contains(t, m.View(), "h1") +} + +func TestTTYModelNonHostRecordsPersist(t *testing.T) { + m := testModel(t, false, nil) + + assert.NotNil(t, update(t, m, eventMsg{ev: Event{Level: slog.LevelInfo, Message: "info line"}})) + assert.NotNil(t, update(t, m, eventMsg{ev: Event{Level: slog.LevelWarn, Message: "warn line"}})) + assert.NotNil(t, update(t, m, eventMsg{ev: Event{Level: slog.LevelError, Message: "error line"}})) + assert.Nil(t, update(t, m, eventMsg{ev: Event{Level: slog.LevelDebug, Message: "debug line"}})) +} + +func TestTTYModelTailKeys(t *testing.T) { + m := testModel(t, true, nil) + update(t, m, eventMsg{ev: phaseStart("Upgrade")}) + for i := range 6 { + update(t, m, eventMsg{ev: Event{Host: fmt.Sprintf("h%d", i), Level: slog.LevelInfo, Message: "working"}}) + } + + update(t, m, tea.KeyMsg{Type: tea.KeyRunes, Runes: []rune("l")}) + assert.True(t, m.tailsAll) + + update(t, m, tea.KeyMsg{Type: tea.KeyRunes, Runes: []rune("2")}) + assert.Equal(t, 1, m.focus) + assert.False(t, m.tailsAll) + + // same key again toggles focus off + update(t, m, tea.KeyMsg{Type: tea.KeyRunes, Runes: []rune("2")}) + assert.Equal(t, -1, m.focus) + + // out of range is ignored + update(t, m, tea.KeyMsg{Type: tea.KeyRunes, Runes: []rune("9")}) + assert.Equal(t, -1, m.focus) +} + +func TestTTYModelSpaceTogglesPeek(t *testing.T) { + m := testModel(t, true, nil) + update(t, m, eventMsg{ev: phaseStart("Upgrade")}) + for i := range 6 { + ev := Event{Host: fmt.Sprintf("h%d", i), Level: slog.LevelInfo, Message: "working"} + update(t, m, eventMsg{ev: ev}) + // in production Display.Handle feeds the rings before the model; + // the feed under the step stack renders below-info records + m.t.st.rings.add(ev) + m.t.st.rings.add(Event{Host: ev.Host, Level: slog.LevelDebug, Message: "executing command"}) + } + + // 6 hosts: tails hidden by default + assert.NotContains(t, m.View(), "│") + + update(t, m, tea.KeyMsg{Type: tea.KeySpace}) + assert.True(t, m.peek) + assert.Contains(t, m.View(), "│", "peek shows tails for all hosts") + + update(t, m, tea.KeyMsg{Type: tea.KeySpace}) + assert.False(t, m.peek) + + // esc clears peek too + update(t, m, tea.KeyMsg{Type: tea.KeySpace}) + update(t, m, tea.KeyMsg{Type: tea.KeyEscape}) + assert.False(t, m.peek) +} + +func TestTTYModelCtrlCInterruptsThenForces(t *testing.T) { + interrupted := false + m := testModel(t, true, func() { interrupted = true }) + + cmd := update(t, m, tea.KeyMsg{Type: tea.KeyCtrlC}) + require.NotNil(t, cmd, "first ctrl-c must print the abort notice") + assert.True(t, interrupted) + assert.False(t, m.t.forceExit) + + cmd = update(t, m, tea.KeyMsg{Type: tea.KeyCtrlC}) + require.NotNil(t, cmd) + assert.True(t, m.t.forceExit) +} + +func TestTTYModelManyHostsCapped(t *testing.T) { + m := testModel(t, false, nil) + update(t, m, eventMsg{ev: phaseStart("Upgrade")}) + for i := range maxRows + 3 { + update(t, m, eventMsg{ev: Event{Host: fmt.Sprintf("host-%02d", i), Level: slog.LevelInfo, Message: "working"}}) + } + + assert.Contains(t, m.View(), "… 3 more hosts") +} + +func TestFirstLine(t *testing.T) { + assert.Equal(t, "one line", firstLine("one line")) + assert.Equal(t, "first …", firstLine("first\nsecond\nthird")) +} + +func TestTTYModelPhaseStepCounterInHeader(t *testing.T) { + m := testModel(t, false, nil) + ev := phaseStart("Upgrade") + ev.Step, ev.Total = 6, 24 + update(t, m, eventMsg{ev: ev}) + + assert.Contains(t, m.View(), "6/24") +} + +func TestTTYModelStopQuits(t *testing.T) { + m := testModel(t, false, nil) + update(t, m, eventMsg{ev: phaseStart("Upgrade")}) + + cmd := update(t, m, stopMsg{}) + + require.NotNil(t, cmd) + assert.Empty(t, m.View()) +} diff --git a/internal/log/handlers.go b/internal/log/handlers.go new file mode 100644 index 000000000..26fcf51d9 --- /dev/null +++ b/internal/log/handlers.go @@ -0,0 +1,207 @@ +package log + +import ( + "context" + "errors" + "fmt" + "io" + "log/slog" + "strings" + "sync" +) + +// NewFanoutHandler returns a handler that forwards records to all given +// handlers that are enabled for the record's level. +func NewFanoutHandler(handlers ...slog.Handler) slog.Handler { + return &fanoutHandler{handlers: handlers} +} + +type fanoutHandler struct { + handlers []slog.Handler +} + +func (f *fanoutHandler) Enabled(ctx context.Context, level slog.Level) bool { + for _, h := range f.handlers { + if h.Enabled(ctx, level) { + return true + } + } + return false +} + +func (f *fanoutHandler) Handle(ctx context.Context, r slog.Record) error { + var errs []error + for _, h := range f.handlers { + if h.Enabled(ctx, r.Level) { + errs = append(errs, h.Handle(ctx, r.Clone())) + } + } + return errors.Join(errs...) +} + +func (f *fanoutHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + next := make([]slog.Handler, len(f.handlers)) + for i, h := range f.handlers { + next[i] = h.WithAttrs(attrs) + } + return &fanoutHandler{handlers: next} +} + +func (f *fanoutHandler) WithGroup(name string) slog.Handler { + next := make([]slog.Handler, len(f.handlers)) + for i, h := range f.handlers { + next[i] = h.WithGroup(name) + } + return &fanoutHandler{handlers: next} +} + +// NewFileHandler returns a handler that writes structured logfmt records, +// used for the persistent log file. +func NewFileHandler(w io.Writer, level slog.Leveler) slog.Handler { + return slog.NewTextHandler(w, &slog.HandlerOptions{ + Level: level, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.LevelKey { + if lvl, ok := a.Value.Any().(slog.Level); ok { + a.Value = slog.StringValue(levelName(lvl)) + } + } + return a + }, + }) +} + +const ( + ansiReset = "\x1b[0m" + ansiGray = "\x1b[90m" + ansiCyan = "\x1b[36m" + ansiYellow = "\x1b[33m" + ansiRed = "\x1b[31m" + ansiGreen = "\x1b[32m" +) + +func levelColor(l slog.Level) string { + switch { + case l < slog.LevelInfo: + return ansiGray + case l < slog.LevelWarn: + return ansiCyan + case l < slog.LevelError: + return ansiYellow + default: + return ansiRed + } +} + +// levelTag returns the 4-letter level tag used on screen. +func levelTag(l slog.Level) string { + return (levelName(l) + " ")[:4] +} + +// NewScreenHandler returns the handler that renders records for the terminal: +// a colored level tag, the host attribute as a message prefix, the message, +// and any remaining attributes as trailing key=value pairs. This handler is +// the seam where a richer display implementation can be plugged in later. +func NewScreenHandler(w io.Writer, level slog.Leveler, colors bool) slog.Handler { + return &screenHandler{w: w, level: level, colors: colors, mu: &sync.Mutex{}} +} + +type screenHandler struct { + w io.Writer + level slog.Leveler + colors bool + mu *sync.Mutex + attrs []slog.Attr +} + +func (s *screenHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= s.level.Level() +} + +func (s *screenHandler) Handle(_ context.Context, r slog.Record) error { + var host, phase string + var rest []slog.Attr + + collect := func(a slog.Attr) { + a.Value = a.Value.Resolve() + if a.Key == KeyHost && host == "" { + host = a.Value.String() + return + } + // phase banner attrs are consumed by the banner rendering on info + // level; on other levels (e.g. debug "phase completed") they stay + // visible + if r.Level == slog.LevelInfo { + switch a.Key { + case KeyPhase: + if phase == "" { + phase = a.Value.String() + } + return + case KeyPhaseStep, KeyPhaseTotal: + return + } + } + if a.Key == KeyError && a.Value.String() == "" { + return + } + rest = append(rest, a) + } + for _, a := range s.attrs { + collect(a) + } + r.Attrs(func(a slog.Attr) bool { + collect(a) + return true + }) + + var b strings.Builder + color := "" + reset := "" + if s.colors { + color = levelColor(r.Level) + reset = ansiReset + } + b.WriteString(color) + b.WriteString(levelTag(r.Level)) + b.WriteString(reset) + b.WriteString(" ") + if host != "" { + b.WriteString(host) + b.WriteString(": ") + } + // phase banners (info-level records carrying the phase attr) render green + if phase != "" && r.Level == slog.LevelInfo && s.colors { + b.WriteString(ansiGreen) + b.WriteString(r.Message) + b.WriteString(ansiReset) + } else { + b.WriteString(r.Message) + } + for _, a := range rest { + b.WriteString(" ") + b.WriteString(color) + b.WriteString(a.Key) + b.WriteString(reset) + fmt.Fprintf(&b, "=%q", a.Value.String()) + } + b.WriteString("\n") + + s.mu.Lock() + defer s.mu.Unlock() + _, err := io.WriteString(s.w, b.String()) + return err +} + +func (s *screenHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + next := *s + next.attrs = make([]slog.Attr, 0, len(s.attrs)+len(attrs)) + next.attrs = append(next.attrs, s.attrs...) + next.attrs = append(next.attrs, attrs...) + return &next +} + +func (s *screenHandler) WithGroup(_ string) slog.Handler { + // k0sctl doesn't use attr groups; flatten them. + return s +} diff --git a/internal/log/handlers_test.go b/internal/log/handlers_test.go new file mode 100644 index 000000000..97a118d88 --- /dev/null +++ b/internal/log/handlers_test.go @@ -0,0 +1,289 @@ +package log + +import ( + "bytes" + "context" + "errors" + "io" + "log/slog" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestScreenHandlerBasicFormat(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + logger.Info("hello world") + + assert.Equal(t, "INFO hello world\n", buf.String()) +} + +func TestScreenHandlerLevelTags(t *testing.T) { + tests := []struct { + name string + level slog.Level + tag string + }{ + {"trace", LevelTrace, "TRAC"}, + {"debug", slog.LevelDebug, "DEBU"}, + {"info", slog.LevelInfo, "INFO"}, + {"warn", slog.LevelWarn, "WARN"}, + {"error", slog.LevelError, "ERRO"}, + {"fatal", LevelFatal, "FATA"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, LevelTrace, false)) + + logger.Log(context.Background(), tt.level, "msg") + + want := tt.tag + " msg\n" + assert.Equal(t, want, buf.String()) + }) + } +} + +func TestScreenHandlerHostAttrRendersAsPrefix(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + logger.Info("connecting", KeyHost, "10.0.0.1") + + assert.Equal(t, "INFO 10.0.0.1: connecting\n", buf.String()) +} + +func TestScreenHandlerHostAttrFromWithAttrs(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)).With(KeyHost, "node1") + + logger.Info("connected") + + assert.Equal(t, "INFO node1: connected\n", buf.String()) +} + +func TestScreenHandlerOtherAttrsRenderTrailing(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + logger.Info("did something", "component", "test") + + assert.Equal(t, `INFO did something component="test"`+"\n", buf.String()) +} + +func TestScreenHandlerHostAndTrailingAttrsCombined(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + logger.Info("msg", KeyHost, "node1", "component", "test") + + assert.Equal(t, `INFO node1: msg component="test"`+"\n", buf.String()) +} + +func TestScreenHandlerPhaseBannerConsumesAttrOnInfo(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + // info-level records carrying the phase attr are phase banners: the + // attr is consumed and (with colors on) the message renders green + logger.Info("==> Running phase: apply", KeyPhase, "apply") + + assert.Equal(t, "INFO ==> Running phase: apply\n", buf.String()) +} + +func TestScreenHandlerPhaseBannerColors(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, true)) + + logger.Info("==> Running phase: apply", KeyPhase, "apply") + + assert.Contains(t, buf.String(), "\x1b[32m==> Running phase: apply\x1b[0m") +} + +func TestScreenHandlerPhaseAttrVisibleOnDebug(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + // non-info records keep the phase attr visible + logger.Debug("phase completed", KeyPhase, "apply") + + assert.Equal(t, `DEBU phase completed phase="apply"`+"\n", buf.String()) +} + +func TestScreenHandlerDropsEmptyErrorAttr(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + logger.Info("ok", KeyError, "") + + assert.Equal(t, "INFO ok\n", buf.String()) +} + +func TestScreenHandlerKeepsNonEmptyErrorAttr(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + logger.Error("failed", KeyError, "boom") + + assert.Equal(t, `ERRO failed error="boom"`+"\n", buf.String()) +} + +func TestScreenHandlerColorsOff(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)) + + logger.Warn("careful") + + assert.NotContains(t, buf.String(), "\x1b[") +} + +func TestScreenHandlerColorsOn(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, true)) + + logger.Warn("careful") + + out := buf.String() + assert.Contains(t, out, ansiYellow, "warn level should be colored yellow") + assert.Contains(t, out, ansiReset) +} + +func TestScreenHandlerEnabledRespectsLevel(t *testing.T) { + h := NewScreenHandler(io.Discard, slog.LevelWarn, false) + + assert.False(t, h.Enabled(context.Background(), slog.LevelInfo)) + assert.True(t, h.Enabled(context.Background(), slog.LevelWarn)) + assert.True(t, h.Enabled(context.Background(), slog.LevelError)) +} + +func TestScreenHandlerFiltersRecordsBelowLevel(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelWarn, false)) + + logger.Info("should not appear") + logger.Warn("should appear") + + assert.Equal(t, "WARN should appear\n", buf.String()) +} + +func TestScreenHandlerWithGroupFlattensInsteadOfNesting(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewScreenHandler(&buf, slog.LevelDebug, false)).WithGroup("g").With("k", "v") + + logger.Info("msg") + + assert.Equal(t, `INFO msg k="v"`+"\n", buf.String()) +} + +func TestFileHandlerLogfmtOutput(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewFileHandler(&buf, slog.LevelDebug)) + + logger.Info("hello", KeyHost, "node1") + + out := buf.String() + assert.Contains(t, out, "level=INFO") + assert.Contains(t, out, "msg=hello") + assert.Contains(t, out, "host=node1") +} + +func TestFileHandlerCustomLevelNames(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewFileHandler(&buf, LevelTrace)) + + logger.Log(context.Background(), LevelTrace, "trace msg") + logger.Log(context.Background(), LevelFatal, "fatal msg") + + out := buf.String() + assert.Contains(t, out, "level=TRACE") + assert.Contains(t, out, "level=FATAL") + assert.NotContains(t, out, "DEBUG-4") + assert.NotContains(t, out, "ERROR+4") +} + +func TestFileHandlerRespectsLevel(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(NewFileHandler(&buf, slog.LevelWarn)) + + logger.Info("skip me") + logger.Warn("keep me") + + out := buf.String() + assert.NotContains(t, out, "skip me") + assert.Contains(t, out, "keep me") +} + +func TestFanoutHandlerForwardsToAllEnabledHandlers(t *testing.T) { + var screenBuf, fileBuf bytes.Buffer + h1 := NewScreenHandler(&screenBuf, slog.LevelDebug, false) + h2 := NewFileHandler(&fileBuf, slog.LevelDebug) + logger := slog.New(NewFanoutHandler(h1, h2)) + + logger.Info("hello") + + assert.Contains(t, screenBuf.String(), "hello") + assert.Contains(t, fileBuf.String(), "msg=hello") +} + +func TestFanoutHandlerRespectsIndividualHandlerLevels(t *testing.T) { + var screenBuf, fileBuf bytes.Buffer + h1 := NewScreenHandler(&screenBuf, slog.LevelInfo, false) // filters debug + h2 := NewFileHandler(&fileBuf, slog.LevelDebug) // allows debug + logger := slog.New(NewFanoutHandler(h1, h2)) + + logger.Debug("debug message") + + assert.Empty(t, screenBuf.String(), "handler above the record's level should not receive it") + assert.Contains(t, fileBuf.String(), "debug message") +} + +func TestFanoutHandlerEnabledIfAnyHandlerEnabled(t *testing.T) { + strict := NewScreenHandler(io.Discard, slog.LevelError, false) + lenient := NewFileHandler(io.Discard, slog.LevelDebug) + + both := NewFanoutHandler(strict, lenient) + assert.True(t, both.Enabled(context.Background(), slog.LevelDebug), "fanout should be enabled if any handler is enabled") + + onlyStrict := NewFanoutHandler(strict) + assert.False(t, onlyStrict.Enabled(context.Background(), slog.LevelDebug)) +} + +func TestFanoutHandlerWithAttrsPropagatesToAllHandlers(t *testing.T) { + var screenBuf, fileBuf bytes.Buffer + h1 := NewScreenHandler(&screenBuf, slog.LevelDebug, false) + h2 := NewFileHandler(&fileBuf, slog.LevelDebug) + logger := slog.New(NewFanoutHandler(h1, h2)).With(KeyHost, "node1") + + logger.Info("connected") + + assert.Contains(t, screenBuf.String(), "node1: connected") + assert.Contains(t, fileBuf.String(), "host=node1") +} + +func TestFanoutHandlerStillForwardsToOtherHandlersWhenOneFails(t *testing.T) { + failing := &alwaysErrorHandler{} + var fileBuf bytes.Buffer + ok := NewFileHandler(&fileBuf, slog.LevelDebug) + + fanout := NewFanoutHandler(failing, ok) + err := fanout.Handle(context.Background(), slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0)) + + require.Error(t, err, "fanout should surface the failing handler's error") + assert.Contains(t, fileBuf.String(), "msg=msg", "the other handler should still receive the record") +} + +// alwaysErrorHandler is a slog.Handler that always fails, used to verify the +// fanout handler still forwards to the remaining handlers and joins errors +// rather than aborting. +type alwaysErrorHandler struct{} + +func (a *alwaysErrorHandler) Enabled(context.Context, slog.Level) bool { return true } +func (a *alwaysErrorHandler) Handle(context.Context, slog.Record) error { + return errors.New("always fails") +} +func (a *alwaysErrorHandler) WithAttrs(_ []slog.Attr) slog.Handler { return a } +func (a *alwaysErrorHandler) WithGroup(_ string) slog.Handler { return a } diff --git a/internal/log/log.go b/internal/log/log.go new file mode 100644 index 000000000..8d7748f66 --- /dev/null +++ b/internal/log/log.go @@ -0,0 +1,167 @@ +// Package log is k0sctl's logging facade: a thin printf-style API over +// log/slog with an added trace level and support for scoped loggers that +// carry structured attributes such as the host they relate to. +package log + +import ( + "context" + "fmt" + "log/slog" + "os" + "sync/atomic" + + riglog "github.com/k0sproject/rig/v2/log" +) + +// Levels in addition to the standard log/slog levels. +const ( + LevelTrace = slog.LevelDebug - 4 + LevelFatal = slog.LevelError + 4 +) + +// Attribute keys shared with rig so that records from both sources can be +// routed and filtered uniformly, plus k0sctl's own keys for progress events. +const ( + KeyHost = riglog.KeyHost + KeyError = riglog.KeyError + KeyDuration = riglog.KeyDuration + KeyExitCode = riglog.KeyExitCode + + // KeyPhase marks records that carry phase lifecycle information: the + // phase manager attaches it to phase start/completion records so that + // displays can track progress without parsing messages. + KeyPhase = "phase" + // KeyPhaseStep and KeyPhaseTotal carry the phase's position in the + // planned phase list on phase start records. + KeyPhaseStep = "step" + KeyPhaseTotal = "of" + // KeyAttempt carries the retry attempt number on records emitted by + // pkg/retry, letting displays render live retry counters. + KeyAttempt = "attempt" +) + +var base atomic.Pointer[slog.Logger] + +func init() { + base.Store(slog.New(NewScreenHandler(os.Stderr, slog.LevelInfo, false))) +} + +// SetLogger replaces the logger used by the package level functions and +// loggers derived via With. +func SetLogger(l *slog.Logger) { + base.Store(l) +} + +// Base returns the current base logger without any attached attributes, +// suitable for injecting into libraries such as rig that tag their own +// records. +func Base() *slog.Logger { + return base.Load() +} + +// Logger is a printf-style logger bound to a set of structured attributes. +type Logger struct { + sl *slog.Logger +} + +// With returns a Logger carrying the given attributes. The arguments are +// interpreted like [slog.Logger.With]: alternating keys and values, or +// [slog.Attr] values. +func With(args ...any) *Logger { + return &Logger{sl: Base().With(args...)} +} + +// With returns a Logger carrying the receiver's attributes plus the given ones. +func (l *Logger) With(args ...any) *Logger { + return &Logger{sl: l.sl.With(args...)} +} + +// Slog returns the underlying *slog.Logger. +func (l *Logger) Slog() *slog.Logger { + return l.sl +} + +func (l *Logger) log(level slog.Level, msg string) { + l.sl.Log(context.Background(), level, msg) +} + +func (l *Logger) Tracef(format string, args ...any) { l.log(LevelTrace, fmt.Sprintf(format, args...)) } +func (l *Logger) Debugf(format string, args ...any) { + l.log(slog.LevelDebug, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Infof(format string, args ...any) { + l.log(slog.LevelInfo, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Warnf(format string, args ...any) { + l.log(slog.LevelWarn, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Errorf(format string, args ...any) { + l.log(slog.LevelError, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Trace(args ...any) { l.log(LevelTrace, fmt.Sprint(args...)) } +func (l *Logger) Debug(args ...any) { l.log(slog.LevelDebug, fmt.Sprint(args...)) } +func (l *Logger) Info(args ...any) { l.log(slog.LevelInfo, fmt.Sprint(args...)) } +func (l *Logger) Warn(args ...any) { l.log(slog.LevelWarn, fmt.Sprint(args...)) } +func (l *Logger) Error(args ...any) { l.log(slog.LevelError, fmt.Sprint(args...)) } + +// Fatal logs at fatal level and exits the process, like logrus Fatal did. +func (l *Logger) Fatal(args ...any) { + l.log(LevelFatal, fmt.Sprint(args...)) + os.Exit(1) +} + +// Fatalf logs at fatal level and exits the process, like logrus Fatalf did. +func (l *Logger) Fatalf(format string, args ...any) { + l.log(LevelFatal, fmt.Sprintf(format, args...)) + os.Exit(1) +} + +func std() *Logger { return &Logger{sl: Base()} } + +func Tracef(format string, args ...any) { std().Tracef(format, args...) } +func Debugf(format string, args ...any) { std().Debugf(format, args...) } +func Infof(format string, args ...any) { std().Infof(format, args...) } +func Warnf(format string, args ...any) { std().Warnf(format, args...) } +func Errorf(format string, args ...any) { std().Errorf(format, args...) } +func Fatalf(format string, args ...any) { std().Fatalf(format, args...) } + +func Trace(args ...any) { std().Trace(args...) } +func Debug(args ...any) { std().Debug(args...) } +func Info(args ...any) { std().Info(args...) } +func Warn(args ...any) { std().Warn(args...) } +func Error(args ...any) { std().Error(args...) } +func Fatal(args ...any) { std().Fatal(args...) } + +type ctxKey struct{} + +// IntoContext returns a context carrying the given logger. Deep helpers such +// as pkg/retry use it to log with the caller's scope (e.g. the host) attached. +func IntoContext(ctx context.Context, l *Logger) context.Context { + return context.WithValue(ctx, ctxKey{}, l) +} + +// FromContext returns the logger carried by the context, or a logger backed +// by the base logger when the context has none. +func FromContext(ctx context.Context) *Logger { + if l, ok := ctx.Value(ctxKey{}).(*Logger); ok { + return l + } + return std() +} + +// levelName returns the display name for a level, covering the custom trace +// and fatal levels that slog would render as "DEBUG-4" and "ERROR+4". +func levelName(l slog.Level) string { + switch { + case l < slog.LevelDebug: + return "TRACE" + case l >= LevelFatal: + return "FATAL" + default: + return l.String() + } +} diff --git a/internal/log/log_test.go b/internal/log/log_test.go new file mode 100644 index 000000000..75f8fbce3 --- /dev/null +++ b/internal/log/log_test.go @@ -0,0 +1,286 @@ +package log + +import ( + "context" + "log/slog" + "sync" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// testRecord is a flattened view of a captured slog.Record, merging both the +// handler's accumulated attrs (from WithAttrs) and the record's own attrs, in +// the same way a real handler would when rendering output. +type testRecord struct { + level slog.Level + message string + attrs []slog.Attr +} + +func (r testRecord) attr(key string) (slog.Attr, bool) { + for _, a := range r.attrs { + if a.Key == key { + return a, true + } + } + return slog.Attr{}, false +} + +// recordingHandler is a minimal slog.Handler that records every record it +// receives, along with any attrs attached via WithAttrs, so tests can assert +// on what package-level funcs and Logger methods actually emit. +type recordingHandler struct { + mu *sync.Mutex + records *[]testRecord + attrs []slog.Attr +} + +func newRecordingHandler() *recordingHandler { + return &recordingHandler{mu: &sync.Mutex{}, records: &[]testRecord{}} +} + +func (h *recordingHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (h *recordingHandler) Handle(_ context.Context, r slog.Record) error { + attrs := append([]slog.Attr{}, h.attrs...) + r.Attrs(func(a slog.Attr) bool { + attrs = append(attrs, a) + return true + }) + + h.mu.Lock() + defer h.mu.Unlock() + *h.records = append(*h.records, testRecord{level: r.Level, message: r.Message, attrs: attrs}) + return nil +} + +func (h *recordingHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + next := *h + next.attrs = append(append([]slog.Attr{}, h.attrs...), attrs...) + return &next +} + +func (h *recordingHandler) WithGroup(_ string) slog.Handler { return h } + +func (h *recordingHandler) Records() []testRecord { + h.mu.Lock() + defer h.mu.Unlock() + out := make([]testRecord, len(*h.records)) + copy(out, *h.records) + return out +} + +// installRecordingHandler swaps the package base logger for one backed by a +// recordingHandler and restores the original when the test ends. +func installRecordingHandler(t *testing.T) *recordingHandler { + t.Helper() + orig := Base() + t.Cleanup(func() { SetLogger(orig) }) + + h := newRecordingHandler() + SetLogger(slog.New(h)) + return h +} + +func TestLevelConstants(t *testing.T) { + assert.Equal(t, slog.LevelDebug-4, LevelTrace, "LevelTrace should be 4 below LevelDebug") + assert.Equal(t, slog.LevelError+4, LevelFatal, "LevelFatal should be 4 above LevelError") +} + +func TestPackageLevelFormattedFuncsRouteAtCorrectLevels(t *testing.T) { + h := installRecordingHandler(t) + + Tracef("trace %d", 1) + Debugf("debug %d", 2) + Infof("info %d", 3) + Warnf("warn %d", 4) + Errorf("error %d", 5) + + recs := h.Records() + require.Len(t, recs, 5) + + want := []struct { + level slog.Level + msg string + }{ + {LevelTrace, "trace 1"}, + {slog.LevelDebug, "debug 2"}, + {slog.LevelInfo, "info 3"}, + {slog.LevelWarn, "warn 4"}, + {slog.LevelError, "error 5"}, + } + for i, w := range want { + assert.Equal(t, w.level, recs[i].level, "record %d level", i) + assert.Equal(t, w.msg, recs[i].message, "record %d message", i) + } +} + +func TestPackageLevelFuncsRouteAtCorrectLevels(t *testing.T) { + h := installRecordingHandler(t) + + Trace("trace", "-1") + Debug("debug", "-2") + Info("info", "-3") + Warn("warn", "-4") + Error("error", "-5") + + recs := h.Records() + require.Len(t, recs, 5) + + want := []struct { + level slog.Level + msg string + }{ + {LevelTrace, "trace-1"}, + {slog.LevelDebug, "debug-2"}, + {slog.LevelInfo, "info-3"}, + {slog.LevelWarn, "warn-4"}, + {slog.LevelError, "error-5"}, + } + for i, w := range want { + assert.Equal(t, w.level, recs[i].level, "record %d level", i) + assert.Equal(t, w.msg, recs[i].message, "record %d message", i) + } +} + +func TestSetLoggerAndBase(t *testing.T) { + orig := Base() + t.Cleanup(func() { SetLogger(orig) }) + + l := slog.New(newRecordingHandler()) + SetLogger(l) + assert.Same(t, l, Base()) +} + +func TestWithAttachesAttrs(t *testing.T) { + h := installRecordingHandler(t) + + With(KeyHost, "node1").Info("hello") + + recs := h.Records() + require.Len(t, recs, 1) + assert.Equal(t, "hello", recs[0].message) + + a, ok := recs[0].attr(KeyHost) + require.True(t, ok, "expected host attr to be present") + assert.Equal(t, "node1", a.Value.String()) +} + +func TestLoggerWithChains(t *testing.T) { + h := installRecordingHandler(t) + + With(KeyHost, "node1").With("phase", "apply").Warnf("uh oh %d", 1) + + recs := h.Records() + require.Len(t, recs, 1) + assert.Equal(t, slog.LevelWarn, recs[0].level) + assert.Equal(t, "uh oh 1", recs[0].message) + + host, ok := recs[0].attr(KeyHost) + require.True(t, ok, "expected host attr from the first With call") + assert.Equal(t, "node1", host.Value.String()) + + phase, ok := recs[0].attr("phase") + require.True(t, ok, "expected phase attr from the chained With call") + assert.Equal(t, "apply", phase.Value.String()) +} + +func TestLoggerWithDoesNotMutateParent(t *testing.T) { + h := installRecordingHandler(t) + + base := With(KeyHost, "node1") + child := base.With("phase", "apply") + + base.Info("from base") + child.Info("from child") + + recs := h.Records() + require.Len(t, recs, 2) + + if _, ok := recs[0].attr("phase"); ok { + t.Errorf("base logger record should not carry the phase attr added only to the child") + } + if _, ok := recs[1].attr("phase"); !ok { + t.Errorf("child logger record should carry the phase attr") + } +} + +func TestLoggerSlogReturnsUnderlying(t *testing.T) { + h := installRecordingHandler(t) + + l := With(KeyHost, "node1") + l.Slog().Info("via slog") + + recs := h.Records() + require.Len(t, recs, 1) + assert.Equal(t, "via slog", recs[0].message) + _, ok := recs[0].attr(KeyHost) + assert.True(t, ok, "attrs attached via With should still apply when using Slog() directly") +} + +func TestIntoContextFromContextRoundTrip(t *testing.T) { + h := installRecordingHandler(t) + + l := With(KeyHost, "node1") + ctx := IntoContext(context.Background(), l) + + got := FromContext(ctx) + require.Same(t, l, got, "FromContext should return the exact logger stored by IntoContext") + + got.Info("via context") + + recs := h.Records() + require.Len(t, recs, 1) + a, ok := recs[0].attr(KeyHost) + require.True(t, ok) + assert.Equal(t, "node1", a.Value.String()) +} + +func TestFromContextFallsBackToBaseLogger(t *testing.T) { + h := installRecordingHandler(t) + + got := FromContext(context.Background()) + got.Info("fallback") + + recs := h.Records() + require.Len(t, recs, 1) + assert.Equal(t, "fallback", recs[0].message) +} + +func TestFromContextIgnoresValuesOfTheWrongType(t *testing.T) { + h := installRecordingHandler(t) + + // A value stored under the same key type but wrong dynamic type should + // not be mistaken for a *Logger. + ctx := context.WithValue(context.Background(), ctxKey{}, "not-a-logger") + got := FromContext(ctx) + got.Info("fallback2") + + recs := h.Records() + require.Len(t, recs, 1) + assert.Equal(t, "fallback2", recs[0].message) +} + +func TestLevelName(t *testing.T) { + tests := []struct { + name string + level slog.Level + want string + }{ + {"trace", LevelTrace, "TRACE"}, + {"below trace", LevelTrace - 100, "TRACE"}, + {"debug", slog.LevelDebug, "DEBUG"}, + {"info", slog.LevelInfo, "INFO"}, + {"warn", slog.LevelWarn, "WARN"}, + {"error", slog.LevelError, "ERROR"}, + {"fatal", LevelFatal, "FATAL"}, + {"above fatal", LevelFatal + 100, "FATAL"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert.Equal(t, tt.want, levelName(tt.level), "levelName(%v)", tt.level) + }) + } +} diff --git a/main.go b/main.go index d16a91837..947702aac 100644 --- a/main.go +++ b/main.go @@ -4,7 +4,7 @@ import ( "os" "github.com/k0sproject/k0sctl/cmd" - log "github.com/sirupsen/logrus" + log "github.com/k0sproject/k0sctl/internal/log" // blank import to make sure versioninfo is included in the binary _ "github.com/carlmjohnson/versioninfo" diff --git a/phase/apply_manifests.go b/phase/apply_manifests.go index 41d784a6a..8d97efbc9 100644 --- a/phase/apply_manifests.go +++ b/phase/apply_manifests.go @@ -7,7 +7,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" - log "github.com/sirupsen/logrus" ) // ApplyManifests is a phase that applies additional manifests to the cluster @@ -51,7 +50,7 @@ func (p *ApplyManifests) apply(ctx context.Context, name string, content []byte) return nil } - log.Infof("%s: apply manifest %s (%d bytes)", p.leader, name, len(content)) + p.leader.Log().Infof("apply manifest %s (%d bytes)", name, len(content)) kubectlCmd := p.leader.Configurer.KubectlCmdf(p.leader, p.leader.K0sDataDir(), "apply -f -") var stdout, stderr bytes.Buffer @@ -66,6 +65,6 @@ func (p *ApplyManifests) apply(ctx context.Context, name string, content []byte) if err := waiter.Wait(); err != nil { return fmt.Errorf("kubectl apply failed for manifest %s: %w (stderr: %s)", name, err, stderr.String()) } - log.Infof("%s: kubectl apply: %s", p.leader, stdout.String()) + p.leader.Log().Infof("kubectl apply: %s", stdout.String()) return nil } diff --git a/phase/arm_prepare.go b/phase/arm_prepare.go index f32a5fbe6..994be4806 100644 --- a/phase/arm_prepare.go +++ b/phase/arm_prepare.go @@ -5,7 +5,6 @@ import ( "strings" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" @@ -40,7 +39,7 @@ func (p *PrepareArm) Prepare(config *v1beta1.Cluster) error { arch, err := h.Arch() if err != nil { - log.Warnf("%s: failed to detect architecture: %v", h, err) + h.Log().Warnf("failed to detect architecture: %v", err) return false } @@ -76,7 +75,7 @@ func (p *PrepareArm) etcdUnsupportedArch(_ context.Context, h *cluster.Host) err if err != nil { return err } - log.Warnf("%s: enabling ETCD_UNSUPPORTED_ARCH=%s override - you may encounter problems with etcd", h, arch) + h.Log().Warnf("enabling ETCD_UNSUPPORTED_ARCH=%s override - you may encounter problems with etcd", arch) h.Environment["ETCD_UNSUPPORTED_ARCH"] = arch return nil diff --git a/phase/backup.go b/phase/backup.go index f73bf07c6..a3e798e28 100644 --- a/phase/backup.go +++ b/phase/backup.go @@ -10,7 +10,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) var _ Phase = &Backup{} @@ -74,7 +73,7 @@ func (p *Backup) ShouldRun() bool { func (p *Backup) Run(_ context.Context) error { h := p.leader - log.Infof("%s: backing up", h) + h.Log().Infof("backing up") var backupDir string err := p.Wet(h, "create a tempdir using `mktemp -d`", func() error { b, err := h.FS().MkdirTemp("", "") @@ -117,12 +116,12 @@ func (p *Backup) Run(_ context.Context) error { defer func() { if p.IsWet() { - log.Debugf("%s: cleaning up %s", h, remotePath) + h.Log().Debugf("cleaning up %s", remotePath) if err := h.Sudo().FS().Remove(remotePath); err != nil { - log.Warnf("%s: failed to clean up backup temp file %s: %s", h, remotePath, err) + h.Log().Warnf("failed to clean up backup temp file %s: %s", remotePath, err) } if err := h.Sudo().FS().Remove(backupDir); err != nil { - log.Warnf("%s: failed to clean up backup temp directory %s: %s", h, backupDir, err) + h.Log().Warnf("failed to clean up backup temp directory %s: %s", backupDir, err) } } else { p.DryMsg(h, "delete the tempdir") @@ -136,7 +135,7 @@ func (p *Backup) Run(_ context.Context) error { } defer func() { if err := f.Close(); err != nil { - log.Warnf("%s: failed to close backup file %s: %v", h, remotePath, err) + h.Log().Warnf("failed to close backup file %s: %v", remotePath, err) } }() if _, err := io.Copy(p.Out, f); err != nil { diff --git a/phase/configure_k0s.go b/phase/configure_k0s.go index ee913c63c..62938a59b 100644 --- a/phase/configure_k0s.go +++ b/phase/configure_k0s.go @@ -11,6 +11,7 @@ import ( "time" "github.com/k0sproject/dig" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" @@ -18,7 +19,6 @@ import ( "github.com/k0sproject/rig/v2/sh" "github.com/k0sproject/version" "github.com/sergi/go-diff/diffmatchpatch" - log "github.com/sirupsen/logrus" "gopkg.in/yaml.v2" ) @@ -128,7 +128,7 @@ func (p *ConfigureK0s) Prepare(config *v1beta1.Cluster) error { } defer func() { if err := h.Sudo().FS().Remove(tempConfigPath); err != nil { - log.Warnf("%s: failed to delete temporary file %s: %s", h, tempConfigPath, err) + h.Log().Warnf("failed to delete temporary file %s: %s", tempConfigPath, err) } }() @@ -160,11 +160,11 @@ func (p *ConfigureK0s) Prepare(config *v1beta1.Cluster) error { } if bytes.Equal(cfgAString, cfgBString) { - log.Debugf("%s: configuration will not change", h) + h.Log().Debugf("configuration will not change") continue } - log.Debugf("%s: configuration will change", h) + h.Log().Debugf("configuration will change") h.Metadata.K0sNewConfig = cfgNew p.hosts = append(p.hosts, h) } @@ -192,7 +192,7 @@ func (p *ConfigureK0s) DryRun() error { p.DryMsgf(h, "configuration changes:\n%s", dmp.DiffPrettyText(diffs)) if h.Metadata.K0sRunningVersion != nil && !h.Metadata.NeedsUpgrade { - p.DryMsg(h, Colorize.BrightRed("restart the k0s service").String()) + p.DryMsg(h, "restart the k0s service") } } return nil @@ -204,7 +204,7 @@ func (p *ConfigureK0s) ShouldRun() bool { } func (p *ConfigureK0s) generateDefaultConfig() (string, error) { - log.Debugf("%s: generating default configuration", p.leader) + p.leader.Log().Debugf("generating default configuration") var cmd string if p.leader.Metadata.K0sBinaryVersion.GreaterThanOrEqual(configCreateSince) { cmd = p.leader.Configurer.K0sCmdf("config create --data-dir=%s", p.leader.K0sDataDir()) @@ -242,7 +242,7 @@ func requiresIPv6NodeLocalAPIAddress(cfg dig.Mapping) bool { } func (p *ConfigureK0s) validateConfig(ctx context.Context, h *cluster.Host, configPath string) error { - log.Infof("%s: validating configuration", h) + h.Log().Infof("validating configuration") if h.Metadata.K0sBinaryTempFile != "" { oldK0sBinaryPath := h.K0sInstallLocation() @@ -271,11 +271,11 @@ func (p *ConfigureK0s) buildConfigValidateCommand(h *cluster.Host, configPath st cmd := h.Configurer.K0sCmdf(`config validate --config="%s"`, configPath) if fg := h.InstallFlags.GetValue("--feature-gates"); fg != "" { cmd += fmt.Sprintf(" --feature-gates=%s", sh.Quote(fg)) - log.Debugf("%s: added --feature-gates from installFlags to config validation: %s", h, cmd) + h.Log().Debugf("added --feature-gates from installFlags to config validation: %s", cmd) } return cmd } - log.Debugf("%s: using legacy config validation command", h) + h.Log().Debugf("using legacy config validation command") return h.Configurer.K0sCmdf(`validate config --config "%s"`, configPath) } @@ -284,14 +284,14 @@ func (p *ConfigureK0s) configureK0s(ctx context.Context, h *cluster.Host) error if h.FS().FileExist(path) { if ok, _ := h.Sudo().FS().FileContains(path, " generated-by-k0sctl"); !ok { newpath := path + ".old" - log.Warnf("%s: an existing config was found and will be backed up as %s", h, newpath) + h.Log().Warnf("an existing config was found and will be backed up as %s", newpath) if err := h.Sudo().FS().Rename(path, newpath); err != nil { return err } } } - log.Debugf("%s: writing k0s configuration", h) + h.Log().Debugf("writing k0s configuration") tempConfigPath, err := h.FS().CreateTemp("", "") if err != nil { return fmt.Errorf("failed to create temporary file for config: %w", err) @@ -301,7 +301,7 @@ func (p *ConfigureK0s) configureK0s(ctx context.Context, h *cluster.Host) error return err } - log.Infof("%s: installing new configuration", h) + h.Log().Infof("installing new configuration") configPath := h.K0sConfigPath() configDir := gopath.Dir(configPath) @@ -315,11 +315,11 @@ func (p *ConfigureK0s) configureK0s(ctx context.Context, h *cluster.Host) error return fmt.Errorf("failed to install k0s configuration: %w", err) } if err := chmodWithMode(h, configPath, fs.FileMode(0o600)); err != nil { - log.Debugf("%s: failed to chmod configuration file %s: %v", h, configPath, err) + h.Log().Debugf("failed to chmod configuration file %s: %v", configPath, err) } if h.Metadata.K0sRunningVersion != nil && !h.Metadata.NeedsUpgrade { - log.Infof("%s: restarting k0s service", h) + h.Log().Infof("restarting k0s service") svc, err := h.Sudo().Service(h.K0sServiceName()) if err != nil { return fmt.Errorf("get service %s: %w", h.K0sServiceName(), err) @@ -328,7 +328,7 @@ func (p *ConfigureK0s) configureK0s(ctx context.Context, h *cluster.Host) error return err } - log.Infof("%s: waiting for k0s service to start", h) + h.Log().Infof("waiting for k0s service to start") return retry.WithDefaultTimeout(ctx, node.ServiceRunningFunc(h, h.K0sServiceName())) } @@ -340,10 +340,10 @@ func (p *ConfigureK0s) configFor(h *cluster.Host) (string, error) { if p.Config.Spec.K0s.DynamicConfig { if h == p.leader && h.Metadata.K0sRunningVersion == nil { - log.Debugf("%s: leader will get a full config on initialize ", h) + h.Log().Debugf("leader will get a full config on initialize ") cfg = p.newBaseConfig.Dup() } else { - log.Debugf("%s: using a stripped down config for dynamic config", h) + h.Log().Debugf("using a stripped down config for dynamic config") cfg = p.Config.Spec.K0s.NodeConfig() } } else { diff --git a/phase/connect.go b/phase/connect.go index cb018ee0e..14bee23cb 100644 --- a/phase/connect.go +++ b/phase/connect.go @@ -9,7 +9,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/retry" "github.com/k0sproject/rig/v2" - log "github.com/sirupsen/logrus" ) // Connect connects to each of the hosts @@ -34,7 +33,7 @@ func (p *Connect) Run(ctx context.Context) error { return err } - log.Infof("%s: connected", h) + h.Log().Infof("connected") return nil }) diff --git a/phase/daemon_reload.go b/phase/daemon_reload.go index 89e140f58..3d9b11273 100644 --- a/phase/daemon_reload.go +++ b/phase/daemon_reload.go @@ -6,7 +6,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/rig/v2/initsystem" - log "github.com/sirupsen/logrus" ) // DaemonReload phase runs `systemctl daemon-reload` or equivalent on hosts whose @@ -46,7 +45,7 @@ func (p *DaemonReload) ShouldRun() bool { // Run the phase func (p *DaemonReload) Run(ctx context.Context) error { return p.parallelDo(ctx, p.hosts, func(ctx context.Context, h *cluster.Host) error { - log.Infof("%s: reloading service manager", h) + h.Log().Infof("reloading service manager") sudo := h.Sudo() mgr, err := sudo.ServiceManager() if err != nil { @@ -57,7 +56,7 @@ func (p *DaemonReload) Run(ctx context.Context) error { return nil } if err := reloader.DaemonReload(ctx, sudo); err != nil { - log.Warnf("%s: failed to reload service manager: %s", h, err.Error()) + h.Log().Warnf("failed to reload service manager: %s", err.Error()) } return nil }) diff --git a/phase/default_k0s_version.go b/phase/default_k0s_version.go index f9aa45ddc..d1b85fa80 100644 --- a/phase/default_k0s_version.go +++ b/phase/default_k0s_version.go @@ -6,7 +6,7 @@ import ( "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" + log "github.com/k0sproject/k0sctl/internal/log" ) type DefaultK0sVersion struct { diff --git a/phase/detect_os.go b/phase/detect_os.go index b3e5256c1..e2942ea53 100644 --- a/phase/detect_os.go +++ b/phase/detect_os.go @@ -14,8 +14,6 @@ import ( _ "github.com/k0sproject/k0sctl/configurer/linux/enterpriselinux" // anonymous import is needed to load the os configurers _ "github.com/k0sproject/k0sctl/configurer/windows" - - log "github.com/sirupsen/logrus" ) // DetectOS performs remote OS detection @@ -32,7 +30,7 @@ func (p *DetectOS) Title() string { func (p *DetectOS) Run(ctx context.Context) error { return p.parallelDo(ctx, p.Config.Spec.Hosts, func(_ context.Context, h *cluster.Host) error { if h.OSIDOverride != "" { - log.Infof("%s: OS ID has been manually set to %s", h, h.OSIDOverride) + h.Log().Infof("OS ID has been manually set to %s", h.OSIDOverride) } if err := h.ResolveConfigurer(); err != nil { // ID_LIKE fallback only applies to detected releases, not to a @@ -40,11 +38,11 @@ func (p *DetectOS) Run(ctx context.Context) error { if h.OSIDOverride == "" { if release, osErr := h.OS(); osErr == nil && len(release.IDLike) > 0 { osStr := release.String() - log.Debugf("%s: trying to find a fallback OS support module for %s using os-release ID_LIKE %v", h, osStr, release.IDLike) + h.Log().Debugf("trying to find a fallback OS support module for %s using os-release ID_LIKE %v", osStr, release.IDLike) for _, id := range release.IDLike { h.OSRelease = &rigos.Release{ID: id, IDLike: release.IDLike, Name: release.Name, Version: release.Version} if err := h.ResolveConfigurer(); err == nil { - log.Warnf("%s: using '%s' as OS support fallback for %s", h, id, osStr) + h.Log().Warnf("using '%s' as OS support fallback for %s", id, osStr) return nil } } @@ -55,10 +53,10 @@ func (p *DetectOS) Run(ctx context.Context) error { } return err } - log.Infof("%s: is running %s", h, h.OSRelease.String()) + h.Log().Infof("is running %s", h.OSRelease.String()) // Needed to make configurer.K0sBinaryPath() to work inside the configurer itself as it can't call host.K0sInstallLocation(). - log.Debugf("%s: k0s install path is %s", h, h.K0sInstallLocation()) + h.Log().Debugf("k0s install path is %s", h.K0sInstallLocation()) h.Configurer.SetPath("K0sBinaryPath", h.K0sInstallLocation()) return nil diff --git a/phase/ensure_join_token_workaround.go b/phase/ensure_join_token_workaround.go index 48b85f45c..787d8173c 100644 --- a/phase/ensure_join_token_workaround.go +++ b/phase/ensure_join_token_workaround.go @@ -19,7 +19,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) // workerTokenWorkaroundVersion is the k0s version affected by https://github.com/k0sproject/k0s/issues/7202. @@ -126,15 +125,15 @@ func (p *EnsureJoinTokenWorkaround) Run(_ context.Context) error { tokenPath := h.K0sJoinTokenPath() data, err := h.FS().ReadFile(tokenPath) if err != nil { - log.Debugf("%s: could not read join token file %s, skipping workaround: %v", h, tokenPath, err) + h.Log().Debugf("could not read join token file %s, skipping workaround: %v", tokenPath, err) continue } content := string(data) if isBase64(strings.TrimSpace(content)) { - log.Debugf("%s: join token file %s already contains base64 content, no workaround needed", h, tokenPath) + h.Log().Debugf("join token file %s already contains base64 content, no workaround needed", tokenPath) continue } - log.Infof("%s: applying a workaround for k0s issue #7202", h) + h.Log().Infof("applying a workaround for k0s issue #7202") if err := p.Wet(h, "write dummy token to fix k0s join token file", func() error { dummyToken, err := buildDummyJoinToken() if err != nil { @@ -142,7 +141,7 @@ func (p *EnsureJoinTokenWorkaround) Run(_ context.Context) error { } return h.Sudo().FS().WriteFile(tokenPath, []byte(dummyToken), 0o600) }); err != nil { - log.Warnf("%s: failed to write dummy token to %s: %v", h, tokenPath, err) + h.Log().Warnf("failed to write dummy token to %s: %v", tokenPath, err) } } return nil diff --git a/phase/gather_facts.go b/phase/gather_facts.go index 87f7388ee..79c9af1ee 100644 --- a/phase/gather_facts.go +++ b/phase/gather_facts.go @@ -8,7 +8,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) // Note: Passwordless sudo has not yet been confirmed when this runs @@ -56,7 +55,7 @@ func (p *GatherFacts) investigateHost(_ context.Context, h *cluster.Host) error if err != nil { return err } - log.Infof("%s: detected %s architecture", h, arch) + h.Log().Infof("detected %s architecture", arch) if !p.SkipMachineIDs && p.Config.Spec.K0s.Version.LessThan(uniqueMachineIDSince) { id, err := h.FS().MachineID() @@ -78,31 +77,31 @@ func (p *GatherFacts) investigateHost(_ context.Context, h *cluster.Host) error if h.HostnameOverride != "" { h.Metadata.Hostname = strings.ToLower(h.HostnameOverride) - log.Infof("%s: using %s from configuration as hostname", h, h.Metadata.Hostname) + h.Log().Infof("using %s from configuration as hostname", h.Metadata.Hostname) } else { n, _ := h.FS().Hostname() if n == "" { return fmt.Errorf("%s: failed to resolve a hostname", h) } h.Metadata.Hostname = strings.ToLower(n) - log.Infof("%s: using %s as hostname", h, n) + h.Log().Infof("using %s as hostname", n) } if h.PrivateAddress == "" { if h.PrivateInterface == "" { if iface, err := h.Configurer.PrivateInterface(h); err == nil { h.PrivateInterface = iface - log.Infof("%s: discovered %s as private interface", h, iface) + h.Log().Infof("discovered %s as private interface", iface) } } if h.PrivateInterface != "" { if addr, err := h.Configurer.PrivateAddress(h, h.PrivateInterface, h.Address()); err == nil { if _, isVIP := p.cplbVIPs[addr]; isVIP { - log.Debugf("%s: skipping autodetected private address %s because it is a control plane load balancing virtual IP", h, addr) + h.Log().Debugf("skipping autodetected private address %s because it is a control plane load balancing virtual IP", addr) } else { h.PrivateAddress = addr - log.Infof("%s: discovered %s as private address", h, addr) + h.Log().Infof("discovered %s as private address", addr) } } } @@ -118,7 +117,7 @@ func (p *GatherFacts) investigateHost(_ context.Context, h *cluster.Host) error if err != nil { return fmt.Errorf("%s: useExistingK0s=true but no 'k0s' binary found in PATH, set k0sInstallPath to use a custom path", h) } - log.Infof("%s: found existing 'k0s' binary at %s", h, path) + h.Log().Infof("found existing 'k0s' binary at %s", path) h.K0sInstallPath = path h.Configurer.SetPath("K0sBinaryPath", path) } else if !h.FS().FileExist(h.K0sBinaryPath) { diff --git a/phase/gather_k0s_facts.go b/phase/gather_k0s_facts.go index aef350cfd..b469cf017 100644 --- a/phase/gather_k0s_facts.go +++ b/phase/gather_k0s_facts.go @@ -18,7 +18,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/node" ps "github.com/k0sproject/rig/v2/powershell" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) type k0sstatus struct { @@ -117,23 +116,23 @@ func (p *GatherK0sFacts) reportUseExistingHosts() error { if binaryDiffersRunning { // Binary version differs from running version — service will be restarted. - log.Infof("%s: useExistingK0s=true, pre-placed k0s binary %s differs from running %s, service will be restarted", h, h.Metadata.K0sBinaryVersion, h.Metadata.K0sRunningVersion) + h.Log().Infof("useExistingK0s=true, pre-placed k0s binary %s differs from running %s, service will be restarted", h.Metadata.K0sBinaryVersion, h.Metadata.K0sRunningVersion) if !p.IsWet() { p.DryMsgf(h, "reuse pre-placed k0s binary %s; skip downloads/uploads; restart service (was %s)", h.Metadata.K0sBinaryVersion, h.Metadata.K0sRunningVersion) } } else { // No detected binary version mismatch; restart is due to supplemental/configuration changes. if h.Metadata.K0sRunningVersion != nil { - log.Infof("%s: useExistingK0s=true, k0s %s will be restarted (running %s; supplemental files changed)", h, h.Metadata.K0sBinaryVersion, h.Metadata.K0sRunningVersion) + h.Log().Infof("useExistingK0s=true, k0s %s will be restarted (running %s; supplemental files changed)", h.Metadata.K0sBinaryVersion, h.Metadata.K0sRunningVersion) } else { - log.Infof("%s: useExistingK0s=true, k0s %s will be restarted (supplemental files changed)", h, h.Metadata.K0sBinaryVersion) + h.Log().Infof("useExistingK0s=true, k0s %s will be restarted (supplemental files changed)", h.Metadata.K0sBinaryVersion) } if !p.IsWet() { p.DryMsgf(h, "reuse pre-placed k0s binary %s; skip downloads/uploads; restart service", h.Metadata.K0sBinaryVersion) } } } else { - log.Infof("%s: useExistingK0s=true, reusing existing k0s %s", h, h.Metadata.K0sBinaryVersion) + h.Log().Infof("useExistingK0s=true, reusing existing k0s %s", h.Metadata.K0sBinaryVersion) if !p.IsWet() { p.DryMsgf(h, "reuse existing k0s %s; skip downloads/uploads/upgrades", h.Metadata.K0sBinaryVersion) } @@ -148,7 +147,7 @@ func (p *GatherK0sFacts) reportUseExistingHosts() error { continue } - log.Warnf("%s: spec.k0s.version is %s but host has k0s binary %s because useExistingK0s=true", h, desired, h.Metadata.K0sBinaryVersion) + h.Log().Warnf("spec.k0s.version is %s but host has k0s binary %s because useExistingK0s=true", desired, h.Metadata.K0sBinaryVersion) if !p.IsWet() { p.DryMsgf(h, "WARNING: host has k0s binary %s while spec.k0s.version=%s (useExistingK0s=true)", h.Metadata.K0sBinaryVersion, desired) } @@ -167,37 +166,37 @@ func (p *GatherK0sFacts) isInternalEtcd() bool { } if p.Config.Spec.K0s == nil || p.Config.Spec.K0s.Config == nil { - log.Debugf("%s: k0s config not found, expecting default internal etcd", p.leader) + p.leader.Log().Debugf("k0s config not found, expecting default internal etcd") return true } - log.Debugf("%s: checking storage config for etcd", p.leader) + p.leader.Log().Debugf("checking storage config for etcd") if storageConfig, ok := p.Config.Spec.K0s.Config.Dig("spec", "storage").(dig.Mapping); ok { storageType := storageConfig.DigString("type") switch storageType { case "etcd": if _, ok := storageConfig.Dig("etcd", "externalCluster").(dig.Mapping); ok { - log.Debugf("%s: storage is configured with external etcd", p.leader) + p.leader.Log().Debugf("storage is configured with external etcd") return false } - log.Debugf("%s: storage type is etcd", p.leader) + p.leader.Log().Debugf("storage type is etcd") return true case "": - log.Debugf("%s: storage type is default", p.leader) + p.leader.Log().Debugf("storage type is default") return true default: - log.Debugf("%s: storage type is %s", p.leader, storageType) + p.leader.Log().Debugf("storage type is %s", storageType) return false } } - log.Debugf("%s: storage config not found, expecting default internal etcd", p.leader) + p.leader.Log().Debugf("storage config not found, expecting default internal etcd") return true } func (p *GatherK0sFacts) investigateEtcd(ctx context.Context) error { if !p.isInternalEtcd() { - log.Debugf("%s: skipping etcd member list", p.leader) + p.leader.Log().Debugf("skipping etcd member list") return nil } @@ -209,7 +208,7 @@ func (p *GatherK0sFacts) investigateEtcd(ctx context.Context) error { } func (p *GatherK0sFacts) listEtcdMembers(ctx context.Context, h *cluster.Host) error { - log.Infof("%s: listing etcd members", h) + h.Log().Infof("listing etcd members") // etcd member-list outputs json like: // {"members":{"controller0":"https://172.17.0.2:2380","controller1":"https://172.17.0.3:2380"}} // on versions like ~1.21.x etcd member-list outputs to stderr with extra fields (from logrus). @@ -265,7 +264,7 @@ func (p *GatherK0sFacts) listEtcdMembers(ctx context.Context, h *cluster.Host) e if err != nil { return fmt.Errorf("failed to split etcd member URL: %w", err) } - log.Debugf("%s: detected etcd member %s", h, memberHost) + h.Log().Debugf("detected etcd member %s", memberHost) etcdMembers = append(etcdMembers, memberHost) } } @@ -278,7 +277,7 @@ func (p *GatherK0sFacts) listEtcdMembers(ctx context.Context, h *cluster.Host) e func (p *GatherK0sFacts) investigateK0s(ctx context.Context, h *cluster.Host) error { output, err := h.Sudo().ExecOutput(h.Configurer.K0sCmdf("version")) if err != nil { - log.Debugf("%s: no 'k0s' binary in PATH", h) + h.Log().Debugf("no 'k0s' binary in PATH") return nil } @@ -289,13 +288,13 @@ func (p *GatherK0sFacts) investigateK0s(ctx context.Context, h *cluster.Host) er h.Metadata.K0sBinaryVersion = binVersion - log.Debugf("%s: has k0s binary version %s", h, h.Metadata.K0sBinaryVersion) + h.Log().Debugf("has k0s binary version %s", h.Metadata.K0sBinaryVersion) if h.IsController() && h.FS().FileExist(h.K0sConfigPath()) { cfgData, err := h.FS().ReadFile(h.K0sConfigPath()) cfg := string(cfgData) if cfg != "" && err == nil { - log.Infof("%s: found existing configuration", h) + h.Log().Infof("found existing configuration") h.Metadata.K0sExistingConfig = cfg } } @@ -325,12 +324,12 @@ func (p *GatherK0sFacts) investigateK0s(ctx context.Context, h *cluster.Host) er output, err = h.Sudo().ExecOutput(h.Configurer.K0sCmdf("status -o json")) if err != nil { if existingServiceScript == "" { - log.Debugf("%s: an existing k0s instance is not running and does not seem to have been installed as a service", h) + h.Log().Debugf("an existing k0s instance is not running and does not seem to have been installed as a service") return nil } if Force { - log.Warnf("%s: an existing k0s instance is not running but has been installed as a service at %s - ignoring because --force was given", h, existingServiceScript) + h.Log().Warnf("an existing k0s instance is not running but has been installed as a service at %s - ignoring because --force was given", existingServiceScript) return nil } @@ -344,12 +343,12 @@ func (p *GatherK0sFacts) investigateK0s(ctx context.Context, h *cluster.Host) er status := k0sstatus{} if err := json.Unmarshal([]byte(output), &status); err != nil { - log.Warnf("%s: failed to decode k0s status output: %s", h, err.Error()) + h.Log().Warnf("failed to decode k0s status output: %s", err.Error()) return nil } if status.Version == nil || status.Role == "" || status.Pid == 0 { - log.Debugf("%s: k0s is not running", h) + h.Log().Debugf("k0s is not running") return nil } @@ -394,12 +393,12 @@ func (p *GatherK0sFacts) investigateK0s(ctx context.Context, h *cluster.Host) er } h.Metadata.K0sStatusArgs = args - log.Infof("%s: is running k0s %s version %s", h, h.Role, h.Metadata.K0sRunningVersion) + h.Log().Infof("is running k0s %s version %s", h.Role, h.Metadata.K0sRunningVersion) if h.IsController() { for _, a := range h.Metadata.K0sStatusArgs { if strings.HasPrefix(a, "--enable-dynamic-config") && !strings.HasSuffix(a, "false") { if !p.Config.Spec.K0s.DynamicConfig { - log.Warnf("%s: controller has dynamic config enabled, but spec.k0s.dynamicConfig was not set in configuration, proceeding in dynamic config mode", h) + h.Log().Warnf("controller has dynamic config enabled, but spec.k0s.dynamicConfig was not set in configuration, proceeding in dynamic config mode") p.Config.Spec.K0s.DynamicConfig = true } } @@ -407,7 +406,7 @@ func (p *GatherK0sFacts) investigateK0s(ctx context.Context, h *cluster.Host) er if h.InstallFlags.Include("--enable-dynamic-config") { if val := h.InstallFlags.GetValue("--enable-dynamic-config"); val != "false" { if !p.Config.Spec.K0s.DynamicConfig { - log.Warnf("%s: controller has --enable-dynamic-config in installFlags, but spec.k0s.dynamicConfig was not set in configuration, proceeding in dynamic config mode", h) + h.Log().Warnf("controller has --enable-dynamic-config in installFlags, but spec.k0s.dynamicConfig was not set in configuration, proceeding in dynamic config mode") } p.Config.Spec.K0s.DynamicConfig = true } @@ -419,17 +418,17 @@ func (p *GatherK0sFacts) investigateK0s(ctx context.Context, h *cluster.Host) er } if h.Role == "controller+worker" && !h.NoTaints { - log.Warnf("%s: the controller+worker node will not schedule regular workloads without toleration for node-role.kubernetes.io/master:NoSchedule unless 'noTaints: true' is set", h) + h.Log().Warnf("the controller+worker node will not schedule regular workloads without toleration for node-role.kubernetes.io/master:NoSchedule unless 'noTaints: true' is set") } if h.Metadata.NeedsUpgrade { - log.Warnf("%s: k0s will be upgraded", h) + h.Log().Warnf("k0s will be upgraded") } if !h.IsController() { - log.Infof("%s: checking if worker %s has joined", p.leader, h.KubernetesNodeName()) + p.leader.Log().Infof("checking if worker %s has joined", h.KubernetesNodeName()) if err := node.KubeNodeReadyFunc(h)(ctx); err != nil { - log.Debugf("%s: failed to get ready status: %s", h, err.Error()) + h.Log().Debugf("failed to get ready status: %s", err.Error()) } else { h.Metadata.Ready = true } @@ -447,7 +446,7 @@ func (p *GatherK0sFacts) handleRoleMismatch(h *cluster.Host, detectedRole string return fmt.Errorf("%s: is configured as k0s %s but is already running as %s - role change is not supported, use --force to ignore the mismatch during reset", h, h.Role, detectedRole) } - log.Warnf("%s: was configured as %s but is already running as %s - proceeding with reset using the discovered role because --force was given", h, h.Role, detectedRole) + h.Log().Warnf("was configured as %s but is already running as %s - proceeding with reset using the discovered role because --force was given", h.Role, detectedRole) h.Role = detectedRole return nil } @@ -458,7 +457,7 @@ func (p *GatherK0sFacts) needsUpgrade(h *cluster.Host) (bool, error) { } for _, f := range h.Files { if f.IsURL() { - log.Debugf("%s: marked for upgrade because there are URL source file uploads for the host", h) + h.Log().Debugf("marked for upgrade because there are URL source file uploads for the host") return true, nil } for _, s := range f.Sources { @@ -468,7 +467,7 @@ func (p *GatherK0sFacts) needsUpgrade(h *cluster.Host) (bool, error) { } src := path.Join(f.Base, s.Path) if h.FileChanged(src, dest) { - log.Debugf("%s: marked for upgrade because file was changed for upload %s", h, src) + h.Log().Debugf("marked for upgrade because file was changed for upload %s", src) return true, nil } } diff --git a/phase/get_kubeconfig.go b/phase/get_kubeconfig.go index 730d85c73..e46e62768 100644 --- a/phase/get_kubeconfig.go +++ b/phase/get_kubeconfig.go @@ -8,8 +8,6 @@ import ( "github.com/k0sproject/rig/v2/cmd" "k8s.io/client-go/tools/clientcmd" "k8s.io/client-go/tools/clientcmd/api" - - log "github.com/sirupsen/logrus" ) // GetKubeconfig is a phase to get and dump the admin kubeconfig @@ -27,7 +25,7 @@ func (p *GetKubeconfig) Title() string { var readKubeconfig = func(h *cluster.Host) (string, error) { dataDir := h.FS().NativePath(h.K0sDataDir()) - log.Debugf("%s: running %v", h, h.Configurer.K0sCmdf("kubeconfig admin --data-dir=%s", h.FS().ShellQuote(dataDir))) + h.Log().Debugf("running %v", h.Configurer.K0sCmdf("kubeconfig admin --data-dir=%s", h.FS().ShellQuote(dataDir))) output, err := h.Sudo().ExecOutput(h.Configurer.K0sCmdf("kubeconfig admin --data-dir=%s", h.FS().ShellQuote(dataDir)), cmd.HideOutput()) if err != nil { return "", fmt.Errorf("get kubeconfig from host: %w", err) diff --git a/phase/initialize_k0s.go b/phase/initialize_k0s.go index fa43acd96..86556da9e 100644 --- a/phase/initialize_k0s.go +++ b/phase/initialize_k0s.go @@ -5,11 +5,11 @@ import ( "fmt" "strings" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) // InitializeK0s sets up the "initial" k0s controller @@ -58,17 +58,17 @@ func (p *InitializeK0s) ShouldRun() bool { func (p *InitializeK0s) CleanUp() { h := p.leader - log.Infof("%s: cleaning up", h) + h.Log().Infof("cleaning up") if len(h.Environment) > 0 { if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if err := svc.SetEnvironment(context.Background(), map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %s", h, err.Error()) + h.Log().Warnf("failed to clean up service environment: %s", err.Error()) } } if h.Metadata.K0sInstalled { if err := h.Sudo().Exec(h.K0sResetCommand()); err != nil { - log.Warnf("%s: k0s reset failed", h) + h.Log().Warnf("k0s reset failed") } } } @@ -76,6 +76,7 @@ func (p *InitializeK0s) CleanUp() { // Run the phase func (p *InitializeK0s) Run(ctx context.Context) error { h := p.leader + ctx = log.IntoContext(ctx, h.Log()) h.Metadata.IsK0sLeader = true if p.Config.Spec.K0s.DynamicConfig || (h.InstallFlags.Include("--enable-dynamic-config") && h.InstallFlags.GetValue("--enable-dynamic-config") != "false") { @@ -84,11 +85,11 @@ func (p *InitializeK0s) Run(ctx context.Context) error { } if Force { - log.Warnf("%s: --force given, using k0s install with --force", h) + h.Log().Warnf("--force given, using k0s install with --force") h.InstallFlags.AddOrReplace("--force=true") } - log.Infof("%s: installing k0s controller", h) + h.Log().Infof("installing k0s controller") cmd, err := h.K0sInstallCommand() if err != nil { return err @@ -108,7 +109,7 @@ func (p *InitializeK0s) Run(ctx context.Context) error { if len(h.Environment) > 0 { err = p.Wet(h, "configure k0s service environment variables", func() error { - log.Infof("%s: updating service environment", h) + h.Log().Infof("updating service environment") svc, err := h.Sudo().Service(h.K0sServiceName()) if err != nil { return fmt.Errorf("get service %s: %w", h.K0sServiceName(), err) @@ -134,12 +135,12 @@ func (p *InitializeK0s) Run(ctx context.Context) error { return err } - log.Infof("%s: waiting for the k0s service to start", h) + h.Log().Infof("waiting for the k0s service to start") if err := retry.WithDefaultTimeout(ctx, node.ServiceRunningFunc(h, h.K0sServiceName())); err != nil { return err } - log.Infof("%s: wait for kubernetes to reach ready state", h) + h.Log().Infof("wait for kubernetes to reach ready state") err = retry.WithDefaultTimeout(ctx, func(_ context.Context) error { out, err := h.Sudo().ExecOutput(h.Configurer.KubectlCmdf(h, h.K0sDataDir(), "get --raw='/readyz'")) if out != "ok" { diff --git a/phase/install_binaries.go b/phase/install_binaries.go index f2d870b7e..f408b36da 100644 --- a/phase/install_binaries.go +++ b/phase/install_binaries.go @@ -5,9 +5,9 @@ import ( "fmt" "io/fs" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" - "github.com/sirupsen/logrus" ) // InstallBinaries installs the k0s binaries from the temp location of UploadBinaries or InstallBinaries @@ -26,27 +26,27 @@ func (p *InstallBinaries) Prepare(config *v1beta1.Cluster) error { p.Config = config p.hosts = p.Config.Spec.Hosts.Filter(func(h *cluster.Host) bool { if h.Reset && h.Metadata.K0sBinaryVersion != nil { - logrus.Debugf("%s: skipping binary install (reset with existing binary %s)", h, h.Metadata.K0sBinaryVersion) + h.Log().Debugf("skipping binary install (reset with existing binary %s)", h.Metadata.K0sBinaryVersion) return false } // Upgrade is handled in UpgradeControllers/UpgradeWorkers phases if h.Metadata.NeedsUpgrade { - logrus.Debugf("%s: skipping binary install (upgrade handled by upgrade phase)", h) + h.Log().Debugf("skipping binary install (upgrade handled by upgrade phase)") return false } if h.UseExistingK0s { - logrus.Debugf("%s: skipping binary install (useExistingK0s)", h) + h.Log().Debugf("skipping binary install (useExistingK0s)") return false } if h.Metadata.K0sBinaryTempFile == "" { - logrus.Debugf("%s: skipping binary install (no staged binary)", h) + h.Log().Debugf("skipping binary install (no staged binary)") return false } - logrus.Debugf("%s: will install k0s binary from staged file %s", h, h.Metadata.K0sBinaryTempFile) + h.Log().Debugf("will install k0s binary from staged file %s", h.Metadata.K0sBinaryTempFile) return true }) return nil @@ -65,7 +65,7 @@ func (p *InstallBinaries) DryRun() error { func(_ context.Context, h *cluster.Host) error { p.DryMsgf(h, "install k0s %s binary from %s to %s", p.Config.Spec.K0s.Version, h.Metadata.K0sBinaryTempFile, h.K0sInstallLocation()) if err := chmodWithMode(h, h.Metadata.K0sBinaryTempFile, fs.FileMode(0o755)); err != nil { - logrus.Warnf("%s: failed to chmod k0s temp binary for dry-run: %s", h, err.Error()) + h.Log().Warnf("failed to chmod k0s temp binary for dry-run: %s", err.Error()) } h.Configurer.SetPath("K0sBinaryPath", h.Metadata.K0sBinaryTempFile) h.Metadata.K0sBinaryVersion = p.Config.Spec.K0s.Version @@ -80,7 +80,7 @@ func (p *InstallBinaries) Run(ctx context.Context) error { } func (p *InstallBinaries) installBinary(_ context.Context, h *cluster.Host) error { - logrus.Debugf("%s: installing k0s binary from tempfile %s to %s", h, h.Metadata.K0sBinaryTempFile, h.K0sInstallLocation()) + h.Log().Debugf("installing k0s binary from tempfile %s to %s", h.Metadata.K0sBinaryTempFile, h.K0sInstallLocation()) if err := h.UpdateK0sBinary(h.Metadata.K0sBinaryTempFile, p.Config.Spec.K0s.Version); err != nil { return fmt.Errorf("failed to install k0s binary: %w", err) } @@ -94,11 +94,11 @@ func (p *InstallBinaries) CleanUp() { if h.Metadata.K0sBinaryTempFile == "" { return nil } - logrus.Infof("%s: cleaning up k0s binary tempfile", h) + h.Log().Infof("cleaning up k0s binary tempfile") _ = h.Sudo().FS().Remove(h.Metadata.K0sBinaryTempFile) return nil }) if err != nil { - logrus.Debugf("failed to clean up tempfiles: %v", err) + log.Debugf("failed to clean up tempfiles: %v", err) } } diff --git a/phase/install_controllers.go b/phase/install_controllers.go index 7455faefc..098713dcb 100644 --- a/phase/install_controllers.go +++ b/phase/install_controllers.go @@ -7,11 +7,11 @@ import ( "strings" "time" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) // InstallControllers installs k0s controllers and joins them to the cluster @@ -60,17 +60,17 @@ func (p *InstallControllers) CleanUp() { _ = p.hosts.Filter(func(h *cluster.Host) bool { return !h.Metadata.Ready }).ParallelEach(context.Background(), func(_ context.Context, h *cluster.Host) error { - log.Infof("%s: cleaning up", h) + h.Log().Infof("cleaning up") if len(h.Environment) > 0 { if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if err := svc.SetEnvironment(context.Background(), map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %v", h, err) + h.Log().Warnf("failed to clean up service environment: %v", err) } } if h.Metadata.K0sInstalled && p.IsWet() { if err := h.Sudo().Exec(h.K0sResetCommand()); err != nil { - log.Warnf("%s: k0s reset failed", h) + h.Log().Warnf("k0s reset failed") } } return nil @@ -89,15 +89,15 @@ func (p *InstallControllers) After() error { } h.Metadata.K0sTokenData.Token = "" err := p.Wet(p.leader, fmt.Sprintf("invalidate k0s join token for controller %s", h), func() error { - log.Debugf("%s: invalidating join token for controller %d", p.leader, i+1) + p.leader.Log().Debugf("invalidating join token for controller %d", i+1) return p.leader.Sudo().Exec(p.leader.Configurer.K0sCmdf("token invalidate --data-dir=%s %s", p.leader.K0sDataDir(), h.Metadata.K0sTokenData.ID)) }) if err != nil { - log.Warnf("%s: failed to invalidate controller join token: %v", p.leader, err) + p.leader.Log().Warnf("failed to invalidate controller join token: %v", err) } _ = p.Wet(h, "overwrite k0s join token file", func() error { if err := h.Sudo().FS().WriteFile(h.K0sJoinTokenPath(), []byte("# overwritten by k0sctl after join\n"), 0o600); err != nil { - log.Warnf("%s: failed to overwrite the join token file at %s", h, h.K0sJoinTokenPath()) + h.Log().Warnf("failed to overwrite the join token file at %s", h.K0sJoinTokenPath()) } return nil }) @@ -109,7 +109,7 @@ func (p *InstallControllers) After() error { func (p *InstallControllers) Run(ctx context.Context) error { for _, h := range p.hosts { if p.IsWet() { - log.Infof("%s: generate join token for %s", p.leader, h) + p.leader.Log().Infof("generate join token for %s", h) token, err := p.Config.Spec.K0s.GenerateToken( ctx, p.leader, @@ -130,14 +130,14 @@ func (p *InstallControllers) Run(ctx context.Context) error { h.Metadata.K0sTokenData.URL = p.Config.Spec.KubeAPIURL() } } - err := p.parallelDo(ctx, p.hosts, func(_ context.Context, h *cluster.Host) error { + err := p.parallelDo(ctx, p.hosts, func(ctx context.Context, h *cluster.Host) error { if p.IsWet() || !p.leader.Metadata.DryRunFakeLeader { - log.Infof("%s: validating api connection to %s", h, h.Metadata.K0sTokenData.URL) + h.Log().Infof("validating api connection to %s", h.Metadata.K0sTokenData.URL) if err := retry.WithDefaultTimeout(ctx, node.HTTPStatusFunc(h, h.Metadata.K0sTokenData.URL, 200, 401, 404)); err != nil { return fmt.Errorf("failed to connect from controller to kubernetes api - check networking: %w", err) } } else { - log.Warnf("%s: dry-run: skipping api connection validation to because cluster is not actually running", h) + h.Log().Warnf("dry-run: skipping api connection validation to because cluster is not actually running") } return nil }) @@ -209,8 +209,9 @@ func (p *InstallControllers) Run(ctx context.Context) error { } func (p *InstallControllers) installK0s(ctx context.Context, h *cluster.Host) error { + ctx = log.IntoContext(ctx, h.Log()) tokenPath := h.K0sJoinTokenPath() - log.Infof("%s: writing join token to %s", h, tokenPath) + h.Log().Infof("writing join token to %s", tokenPath) err := p.Wet(h, fmt.Sprintf("write k0s join token to %s", tokenPath), func() error { return h.Sudo().FS().WriteFile(tokenPath, []byte(h.Metadata.K0sTokenData.Token), 0o600) }) @@ -223,7 +224,7 @@ func (p *InstallControllers) installK0s(ctx context.Context, h *cluster.Host) er } if Force { - log.Warnf("%s: --force given, using k0s install with --force", h) + h.Log().Warnf("--force given, using k0s install with --force") h.InstallFlags.AddOrReplace("--force=true") } @@ -231,7 +232,7 @@ func (p *InstallControllers) installK0s(ctx context.Context, h *cluster.Host) er if err != nil { return err } - log.Infof("%s: installing k0s controller", h) + h.Log().Infof("installing k0s controller") err = p.Wet(h, fmt.Sprintf("install k0s controller using `%s", strings.ReplaceAll(cmd, h.K0sInstallLocation(), "k0s")), func() error { var stdout, stderr bytes.Buffer @@ -243,7 +244,7 @@ func (p *InstallControllers) installK0s(ctx context.Context, h *cluster.Host) er return fmt.Errorf("run k0s install: %w", err) } if err := waiter.Wait(); err != nil { - log.Errorf("%s: k0s install failed: %s %s", h, stdout.String(), stderr.String()) + h.Log().Errorf("k0s install failed: %s %s", stdout.String(), stderr.String()) return fmt.Errorf("k0s install failed: %w", err) } @@ -262,18 +263,18 @@ func (p *InstallControllers) installK0s(ctx context.Context, h *cluster.Host) er } if len(h.Environment) > 0 { - log.Infof("%s: updating service environment", h) + h.Log().Infof("updating service environment") if err := svc.SetEnvironment(ctx, h.Environment); err != nil { return err } } - log.Infof("%s: starting service", h) + h.Log().Infof("starting service") if err := svc.Start(ctx); err != nil { return err } - log.Infof("%s: waiting for the k0s service to start", h) + h.Log().Infof("waiting for the k0s service to start") if err := retry.WithDefaultTimeout(ctx, node.ServiceRunningFunc(h, h.K0sServiceName())); err != nil { return err } diff --git a/phase/install_workers.go b/phase/install_workers.go index e883bb30d..aea79af42 100644 --- a/phase/install_workers.go +++ b/phase/install_workers.go @@ -11,7 +11,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" "github.com/k0sproject/rig/v2/cmd" - log "github.com/sirupsen/logrus" ) // InstallWorkers installs k0s on worker hosts and joins them to the cluster @@ -58,7 +57,7 @@ func (p *InstallWorkers) After() error { if NoWait { for _, h := range p.hosts { if h.Metadata.K0sTokenData.Token != "" { - log.Warnf("%s: --no-wait given, created join tokens will remain valid for 10 minutes", p.leader) + p.leader.Log().Warnf("--no-wait given, created join tokens will remain valid for 10 minutes") break } } @@ -70,16 +69,16 @@ func (p *InstallWorkers) After() error { continue } err := p.Wet(p.leader, fmt.Sprintf("invalidate k0s join token for worker %s", h), func() error { - log.Debugf("%s: invalidating join token for worker %d", p.leader, i+1) + p.leader.Log().Debugf("invalidating join token for worker %d", i+1) return p.leader.Sudo().Exec(p.leader.Configurer.K0sCmdf("token invalidate --data-dir=%s %s", p.leader.K0sDataDir(), h.Metadata.K0sTokenData.ID)) }) if err != nil { - log.Warnf("%s: failed to invalidate worker join token: %v", p.leader, err) + p.leader.Log().Warnf("failed to invalidate worker join token: %v", err) } _ = p.Wet(h, "overwrite k0s join token file", func() error { content := "# overwritten by k0sctl after join\n" if p.Config.Spec.K0s.Version.Equal(workerTokenWorkaroundVersion) { - log.Debugf("%s: configured k0s version is %s, using workaround content for join token file", h, p.Config.Spec.K0s.Version) + h.Log().Debugf("configured k0s version is %s, using workaround content for join token file", p.Config.Spec.K0s.Version) dummyToken, err := buildDummyJoinToken() if err != nil { return fmt.Errorf("build dummy join token: %w", err) @@ -87,7 +86,7 @@ func (p *InstallWorkers) After() error { content = dummyToken } if err := h.Sudo().FS().WriteFile(h.K0sJoinTokenPath(), []byte(content), 0o600); err != nil { - log.Warnf("%s: failed to overwrite the join token file at %s", h, h.K0sJoinTokenPath()) + h.Log().Warnf("failed to overwrite the join token file at %s", h.K0sJoinTokenPath()) } return nil }) @@ -100,17 +99,17 @@ func (p *InstallWorkers) CleanUp() { _ = p.hosts.Filter(func(h *cluster.Host) bool { return !h.Metadata.Ready }).ParallelEach(context.Background(), func(_ context.Context, h *cluster.Host) error { - log.Infof("%s: cleaning up", h) + h.Log().Infof("cleaning up") if len(h.Environment) > 0 { if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if err := svc.SetEnvironment(context.Background(), map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %v", h, err) + h.Log().Warnf("failed to clean up service environment: %v", err) } } if h.Metadata.K0sInstalled && p.IsWet() { if err := h.Sudo().Exec(h.K0sResetCommand()); err != nil { - log.Warnf("%s: k0s reset failed", h) + h.Log().Warnf("k0s reset failed") } } return nil @@ -120,7 +119,7 @@ func (p *InstallWorkers) CleanUp() { // Run the phase func (p *InstallWorkers) Run(ctx context.Context) error { for i, h := range p.hosts { - log.Infof("%s: generating a join token for worker %d", p.leader, i+1) + p.leader.Log().Infof("generating a join token for worker %d", i+1) err := p.Wet(p.leader, fmt.Sprintf("generate a k0s join token for worker %s", h), func() error { t, err := p.Config.Spec.K0s.GenerateToken( ctx, @@ -154,9 +153,9 @@ func (p *InstallWorkers) Run(ctx context.Context) error { tokenPath := h.K0sJoinTokenPath() err := p.Wet(h, fmt.Sprintf("write k0s join token to %s", tokenPath), func() error { if err := h.Sudo().FS().MkdirAll(h.FS().Dir(tokenPath), 0o700); err != nil { - log.Warnf("%s: failed to create k0s config dir %s: %v", h, h.K0sDataDir(), err) + h.Log().Warnf("failed to create k0s config dir %s: %v", h.K0sDataDir(), err) } - log.Infof("%s: writing join token to %s", h, tokenPath) + h.Log().Infof("writing join token to %s", tokenPath) return h.Sudo().FS().WriteFile(tokenPath, []byte(h.Metadata.K0sTokenData.Token), 0o600) }) if err != nil { @@ -164,21 +163,21 @@ func (p *InstallWorkers) Run(ctx context.Context) error { } err = p.Wet(h, "validate api connection to control plane", func() error { - log.Infof("%s: validating api connection to %s using join token", h, h.Metadata.K0sTokenData.URL) + h.Log().Infof("validating api connection to %s using join token", h.Metadata.K0sTokenData.URL) tempfile, err := h.FS().CreateTemp("", "") if err != nil { return fmt.Errorf("failed to create temp file for kubeconfig: %w", err) } - log.Debugf("%s: temp file path: %q", h, tempfile) + h.Log().Debugf("temp file path: %q", tempfile) tempfileHostPath := h.FS().NativePath(tempfile) - log.Debugf("%s: writing temp kubeconfig file %q", h, tempfileHostPath) + h.Log().Debugf("writing temp kubeconfig file %q", tempfileHostPath) if err := h.Sudo().FS().WriteFile(tempfile, h.Metadata.K0sTokenData.Kubeconfig, 0o600); err != nil { return fmt.Errorf("failed to write temp kubeconfig file: %w", err) } defer func() { if err := h.Sudo().FS().Remove(tempfile); err != nil { - log.Warnf("%s: failed to delete temp kubeconfig file %s: %v", h, tempfileHostPath, err) + h.Log().Warnf("failed to delete temp kubeconfig file %s: %v", tempfileHostPath, err) } }() @@ -204,7 +203,7 @@ func (p *InstallWorkers) Run(ctx context.Context) error { } if svc.IsRunning(ctx) { err := p.Wet(h, "stop existing k0s service", func() error { - log.Infof("%s: stopping service", h) + h.Log().Infof("stopping service") return svc.Stop(ctx) }) if err != nil { @@ -222,9 +221,9 @@ func (p *InstallWorkers) Run(ctx context.Context) error { } } - log.Infof("%s: installing k0s worker", h) + h.Log().Infof("installing k0s worker") if Force { - log.Warnf("%s: --force given, using k0s install with --force", h) + h.Log().Warnf("--force given, using k0s install with --force") h.InstallFlags.AddOrReplace("--force=true") } @@ -247,7 +246,7 @@ func (p *InstallWorkers) Run(ctx context.Context) error { if len(h.Environment) > 0 { err := p.Wet(h, "update service environment variables", func() error { - log.Infof("%s: updating service environment", h) + h.Log().Infof("updating service environment") return svc.SetEnvironment(ctx, h.Environment) }) if err != nil { @@ -256,17 +255,17 @@ func (p *InstallWorkers) Run(ctx context.Context) error { } if p.IsWet() { - log.Infof("%s: starting service", h) + h.Log().Infof("starting service") if err := svc.Start(ctx); err != nil { return err } } if NoWait { - log.Debugf("%s: not waiting because --no-wait given", h) + h.Log().Debugf("not waiting because --no-wait given") h.Metadata.Ready = true } else { - log.Infof("%s: waiting for node to become ready", h) + h.Log().Infof("waiting for node to become ready") if p.IsWet() { if err := retry.WithDefaultTimeout(ctx, node.KubeNodeReadyFunc(h)); err != nil { diff --git a/phase/lock.go b/phase/lock.go index 41976b1f9..5d1a4b8ff 100644 --- a/phase/lock.go +++ b/phase/lock.go @@ -11,7 +11,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) // Lock acquires an exclusive k0sctl lock on hosts @@ -77,17 +76,17 @@ func (p *Lock) startTicker(ctx context.Context, h *cluster.Host) error { p.m.Unlock() go func() { - log.Tracef("%s: started periodic update of lock file %s timestamp", h, lfp) + h.Log().Tracef("started periodic update of lock file %s timestamp", lfp) for { select { case <-ticker.C: if err := h.Sudo().FS().Touch(lfp, time.Now()); err != nil { - log.Debugf("%s: failed to touch lock file: %s", h, err) + h.Log().Debugf("failed to touch lock file: %s", err) } case <-ctx.Done(): - log.Tracef("%s: stopped lock cycle, removing file", h) + h.Log().Tracef("stopped lock cycle, removing file") if err := h.Sudo().FS().Remove(lfp); err != nil { - log.Debugf("%s: failed to remove host lock file, k0sctl may have been previously aborted or crashed. the start of next invocation may be delayed until it expires: %s", h, err) + h.Log().Debugf("failed to remove host lock file, k0sctl may have been previously aborted or crashed. the start of next invocation may be delayed until it expires: %s", err) } p.wg.Done() return diff --git a/phase/manager.go b/phase/manager.go index e48fe102e..7eef8f9cb 100644 --- a/phase/manager.go +++ b/phase/manager.go @@ -6,11 +6,12 @@ import ( "io" "os" "sync" + "time" + "github.com/charmbracelet/lipgloss" "github.com/creasty/defaults" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" - "github.com/logrusorgru/aurora" - log "github.com/sirupsen/logrus" ) // NoWait is used by various phases to decide if node ready state should be waited for or not @@ -19,9 +20,6 @@ var NoWait bool // Force is used by various phases to attempt a forced installation var Force bool -// Colorize is an instance of "aurora", used to colorize the output -var Colorize = aurora.NewAurora(false) - // Phase represents a runnable phase which can be added to Manager. type Phase interface { Run(context.Context) error @@ -198,28 +196,35 @@ func (m *Manager) Run(ctx context.Context) error { if result != nil { for _, p := range ran { if c, ok := p.(withcleanup); ok { - log.Infof(Colorize.Red("* Running clean-up for phase: %s").String(), p.Title()) + log.With(log.KeyPhase, p.Title()).Warnf("* Running clean-up for phase: %s", p.Title()) c.CleanUp() } } } if m.DryRun { + r := lipgloss.NewRenderer(m.Writer) + green := r.NewStyle().Foreground(lipgloss.Color("10")) + brightRed := r.NewStyle().Foreground(lipgloss.Color("9")) + red := r.NewStyle().Foreground(lipgloss.Color("1")) + bold := r.NewStyle().Bold(true) + if len(m.dryMessages) == 0 { - fmt.Fprintln(m.Writer, Colorize.BrightGreen("dry-run: no cluster state altering actions would be performed")) + fmt.Fprintln(m.Writer, green.Render("dry-run: no cluster state altering actions would be performed")) return } - fmt.Fprintln(m.Writer, Colorize.BrightRed("dry-run: cluster state altering actions would be performed:")) + fmt.Fprintln(m.Writer, brightRed.Render("dry-run: cluster state altering actions would be performed:")) for host, msgs := range m.dryMessages { - fmt.Fprintln(m.Writer, Colorize.BrightRed("dry-run:"), Colorize.Bold(fmt.Sprintf("* %s :", host))) + fmt.Fprintln(m.Writer, brightRed.Render("dry-run:"), bold.Render(fmt.Sprintf("* %s :", host))) for _, msg := range msgs { - fmt.Fprintln(m.Writer, Colorize.BrightRed("dry-run:"), Colorize.Red(" -"), msg) + fmt.Fprintln(m.Writer, brightRed.Render("dry-run:"), red.Render(" -"), msg) } } } }() - for _, p := range m.phases { + total := len(m.phases) + for i, p := range m.phases { title := p.Title() if err := ctx.Err(); err != nil { @@ -255,15 +260,17 @@ func (m *Manager) Run(ctx context.Context) error { } } - text := Colorize.Green("==> Running phase: %s").String() - log.Infof(text, title) + log.With(log.KeyPhase, title, log.KeyPhaseStep, i+1, log.KeyPhaseTotal, total).Infof("==> Running phase: %s", title) + phaseStart := time.Now() if dp, ok := p.(withDryRun); ok && m.DryRun { ran = append(ran, p) if err := dp.DryRun(); err != nil { + logPhaseEnd(title, phaseStart, err) result = err return result } + logPhaseEnd(title, phaseStart, nil) continue } @@ -276,12 +283,15 @@ func (m *Manager) Run(ctx context.Context) error { if ap, ok := p.(withAfter); ok { log.Debugf("running after for phase '%s'", p.Title()) if herr := ap.After(); herr != nil { + logPhaseEnd(title, phaseStart, herr) result = herr return result } } } + logPhaseEnd(title, phaseStart, result) + if result != nil { return result } @@ -289,3 +299,15 @@ func (m *Manager) Run(ctx context.Context) error { return nil } + +// logPhaseEnd emits a phase completion record carrying the phase title, +// duration and any error as structured attributes. It goes out at debug +// level: displays and the log file consume it, the plain info-level screen +// output does not show it. +func logPhaseEnd(title string, start time.Time, err error) { + l := log.With(log.KeyPhase, title, log.KeyDuration, time.Since(start)) + if err != nil { + l = l.With(log.KeyError, err.Error()) + } + l.Debug("phase completed") +} diff --git a/phase/prepare_hosts.go b/phase/prepare_hosts.go index d145d6e8f..166461969 100644 --- a/phase/prepare_hosts.go +++ b/phase/prepare_hosts.go @@ -12,7 +12,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/retry" "github.com/k0sproject/rig/v2" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) var iptablesEmbeddedSince = version.MustParse("v1.22.1+k0s.0") @@ -51,7 +50,7 @@ func (p *PrepareHosts) updateEnvironment(ctx context.Context, h *cluster.Host) e // preserved across multiple ssh sessions. We need to write the environment // and then reopen the ssh session. Go's ssh client.Setenv() depends on ssh // server configuration (sshd only accepts LC_* variables by default). - log.Infof("%s: reconnecting to apply new environment", h) + h.Log().Infof("reconnecting to apply new environment") h.Disconnect() return retry.Timeout(ctx, 10*time.Minute, func(ctx context.Context) error { if err := h.Connect(ctx); err != nil { @@ -72,7 +71,7 @@ func (p *PrepareHosts) prepareHost(ctx context.Context, h *cluster.Host) error { } if len(h.Environment) > 0 { - log.Infof("%s: updating environment", h) + h.Log().Infof("updating environment") if err := p.updateEnvironment(ctx, h); err != nil { return fmt.Errorf("failed to updated environment: %w", err) } @@ -95,7 +94,7 @@ func (p *PrepareHosts) prepareHost(ctx context.Context, h *cluster.Host) error { if len(pkgs) > 0 { if err := p.Wet(h, fmt.Sprintf("install packages: %s", strings.Join(pkgs, ", ")), func() error { - log.Infof("%s: installing packages: %s", h, strings.Join(pkgs, ", ")) + h.Log().Infof("installing packages: %s", strings.Join(pkgs, ", ")) pm := h.Sudo().PackageManager() if err := pm.Update(ctx); err != nil { return fmt.Errorf("failed to update package lists: %w", err) @@ -107,7 +106,7 @@ func (p *PrepareHosts) prepareHost(ctx context.Context, h *cluster.Host) error { } if isContainer, _ := h.FS().IsContainer(); isContainer { - log.Infof("%s: is a container, applying a fix", h) + h.Log().Infof("is a container, applying a fix") if err := h.Configurer.FixContainer(h); err != nil { return err } diff --git a/phase/reinstall.go b/phase/reinstall.go index 05128dd11..0d07d60ca 100644 --- a/phase/reinstall.go +++ b/phase/reinstall.go @@ -6,11 +6,11 @@ import ( "math" "strings" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) type Reinstall struct { @@ -81,7 +81,7 @@ func (p *Reinstall) reinstall(ctx context.Context, h *cluster.Host) error { if err != nil { return err } - log.Infof("%s: reinstalling k0s", h) + h.Log().Infof("reinstalling k0s") err = p.Wet(h, fmt.Sprintf("reinstall k0s using `%s", strings.ReplaceAll(cmd, h.K0sInstallLocation(), "k0s")), func() error { if err := h.Sudo().Exec(cmd); err != nil { return fmt.Errorf("failed to reinstall k0s: %w", err) @@ -100,7 +100,7 @@ func (p *Reinstall) reinstall(ctx context.Context, h *cluster.Host) error { if err := svc.Restart(ctx); err != nil { return fmt.Errorf("failed to restart k0s: %w", err) } - log.Infof("%s: waiting for the k0s service to start", h) + h.Log().Infof("waiting for the k0s service to start") if err := retry.WithDefaultTimeout(ctx, node.ServiceRunningFunc(h, h.K0sServiceName())); err != nil { return fmt.Errorf("k0s did not restart: %w", err) } diff --git a/phase/reset_controllers.go b/phase/reset_controllers.go index 26742618b..1e73d91b6 100644 --- a/phase/reset_controllers.go +++ b/phase/reset_controllers.go @@ -5,11 +5,11 @@ import ( "context" "fmt" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) // ResetControllers phase removes controllers marked for reset from the kubernetes and etcd clusters @@ -70,14 +70,15 @@ func (p *ResetControllers) DryRun() error { // Run the phase func (p *ResetControllers) Run(ctx context.Context) error { for _, h := range p.hosts { + ctx := log.IntoContext(ctx, h.Log()) if t := p.Config.Spec.Options.EvictTaint; t.Enabled && t.ControllerWorkers && h.Role != "controller" { - log.Debugf("%s: add taint: %s", h, t.String()) + h.Log().Debugf("add taint: %s", t.String()) if err := p.leader.AddTaint(h, t.String()); err != nil { return fmt.Errorf("add taint: %w", err) } } if !p.NoDrain && h.Role != "controller" { - log.Debugf("%s: draining node", h) + h.Log().Debugf("draining node") if err := p.leader.DrainNode( &cluster.Host{ Metadata: cluster.HostMetadata{ @@ -86,46 +87,46 @@ func (p *ResetControllers) Run(ctx context.Context) error { }, p.Config.Spec.Options.Drain, ); err != nil { - log.Warnf("%s: failed to drain node: %s", h, err.Error()) + h.Log().Warnf("failed to drain node: %s", err.Error()) } } - log.Debugf("%s: draining node completed", h) + h.Log().Debugf("draining node completed") if !p.NoDelete && h.Role != "controller" { - log.Debugf("%s: deleting node...", h) + h.Log().Debugf("deleting node...") if err := p.leader.DeleteNode(&cluster.Host{ Metadata: cluster.HostMetadata{ Hostname: h.KubernetesNodeName(), }, }); err != nil { - log.Warnf("%s: failed to delete node: %s", h, err.Error()) + h.Log().Warnf("failed to delete node: %s", err.Error()) } } if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if svc.IsRunning(ctx) { - log.Debugf("%s: stopping k0s...", h) + h.Log().Debugf("stopping k0s...") if err := svc.Stop(ctx); err != nil { - log.Warnf("%s: failed to stop k0s: %s", h, err.Error()) + h.Log().Warnf("failed to stop k0s: %s", err.Error()) } - log.Debugf("%s: waiting for k0s to stop", h) + h.Log().Debugf("waiting for k0s to stop") if err := retry.WithDefaultTimeout(ctx, node.ServiceStoppedFunc(h, h.K0sServiceName())); err != nil { - log.Warnf("%s: failed to wait for k0s to stop: %v", h, err) + h.Log().Warnf("failed to wait for k0s to stop: %v", err) } - log.Debugf("%s: stopping k0s completed", h) + h.Log().Debugf("stopping k0s completed") } if !p.NoLeave { - log.Debugf("%s: leaving etcd...", h) + h.Log().Debugf("leaving etcd...") if err := h.Sudo().Exec(h.Configurer.K0sCmdf("etcd leave --peer-address %s --datadir %s", h.PrivateAddress, h.K0sDataDir())); err != nil { - log.Warnf("%s: failed to leave etcd: %s", h, err.Error()) + h.Log().Warnf("failed to leave etcd: %s", err.Error()) } - log.Debugf("%s: leaving etcd completed", h) + h.Log().Debugf("leaving etcd completed") } - log.Debugf("%s: resetting k0s...", h) + h.Log().Debugf("resetting k0s...") var stdoutbuf, stderrbuf bytes.Buffer proc := h.Sudo().Proc(h.K0sResetCommand()) proc.Stdout = &stdoutbuf @@ -135,31 +136,31 @@ func (p *ResetControllers) Run(ctx context.Context) error { return fmt.Errorf("failed to run k0s reset: %w", err) } if err := waiter.Wait(); err != nil { - log.Warnf("%s: k0s reset reported failure: %s %s", h, stderrbuf.String(), stdoutbuf.String()) + h.Log().Warnf("k0s reset reported failure: %s %s", stderrbuf.String(), stdoutbuf.String()) } - log.Debugf("%s: resetting k0s completed", h) + h.Log().Debugf("resetting k0s completed") - log.Debugf("%s: removing config...", h) + h.Log().Debugf("removing config...") if dErr := h.Sudo().FS().Remove(h.Configurer.K0sConfigPath()); dErr != nil { - log.Warnf("%s: failed to remove existing configuration %s: %s", h, h.Configurer.K0sConfigPath(), dErr) + h.Log().Warnf("failed to remove existing configuration %s: %s", h.Configurer.K0sConfigPath(), dErr) } - log.Debugf("%s: removing config completed", h) + h.Log().Debugf("removing config completed") - log.Debugf("%s: removing k0s binary...", h) + h.Log().Debugf("removing k0s binary...") if dErr := h.Sudo().FS().Remove(h.Configurer.K0sBinaryPath()); dErr != nil { - log.Warnf("%s: failed to remove existing binary %s: %s", h, h.Configurer.K0sConfigPath(), dErr) + h.Log().Warnf("failed to remove existing binary %s: %s", h.Configurer.K0sConfigPath(), dErr) } - log.Debugf("%s: removing binary completed", h) + h.Log().Debugf("removing binary completed") if len(h.Environment) > 0 { if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if err := svc.SetEnvironment(ctx, map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %s", h, err.Error()) + h.Log().Warnf("failed to clean up service environment: %s", err.Error()) } } - log.Infof("%s: reset", h) + h.Log().Infof("reset") } return nil } diff --git a/phase/reset_leader.go b/phase/reset_leader.go index 4da61baf3..57fcf8176 100644 --- a/phase/reset_leader.go +++ b/phase/reset_leader.go @@ -4,11 +4,11 @@ import ( "context" "fmt" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) // ResetLeader phase removes the leader from the cluster and thus destroys the cluster @@ -47,56 +47,57 @@ func (p *ResetLeader) DryRun() error { // Run the phase func (p *ResetLeader) Run(ctx context.Context) error { + ctx = log.IntoContext(ctx, p.leader.Log()) if t := p.Config.Spec.Options.EvictTaint; t.Enabled && t.ControllerWorkers && p.leader.Role != "controller" { - log.Debugf("%s: add taint %s", p.leader, t.String()) + p.leader.Log().Debugf("add taint %s", t.String()) if err := p.leader.AddTaint(p.leader, t.String()); err != nil { return fmt.Errorf("add taint: %w", err) } } if leaderSvc, err := p.leader.Sudo().Service(p.leader.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", p.leader, p.leader.K0sServiceName(), err) + p.leader.Log().Warnf("failed to get service %s: %v", p.leader.K0sServiceName(), err) } else if leaderSvc.IsRunning(ctx) { - log.Debugf("%s: stopping k0s...", p.leader) + p.leader.Log().Debugf("stopping k0s...") if err := leaderSvc.Stop(ctx); err != nil { - log.Warnf("%s: failed to stop k0s: %s", p.leader, err.Error()) + p.leader.Log().Warnf("failed to stop k0s: %s", err.Error()) } - log.Debugf("%s: waiting for k0s to stop", p.leader) + p.leader.Log().Debugf("waiting for k0s to stop") if err := retry.WithDefaultTimeout(ctx, node.ServiceStoppedFunc(p.leader, p.leader.K0sServiceName())); err != nil { - log.Warnf("%s: k0s service stop: %s", p.leader, err.Error()) + p.leader.Log().Warnf("k0s service stop: %s", err.Error()) } - log.Debugf("%s: stopping k0s completed", p.leader) + p.leader.Log().Debugf("stopping k0s completed") } - log.Debugf("%s: resetting k0s...", p.leader) + p.leader.Log().Debugf("resetting k0s...") out, err := p.leader.Sudo().ExecOutput(p.leader.K0sResetCommand()) if err != nil { - log.Debugf("%s: k0s reset failed: %s", p.leader, out) - log.Warnf("%s: k0s reported failure: %v", p.leader, err) + p.leader.Log().Debugf("k0s reset failed: %s", out) + p.leader.Log().Warnf("k0s reported failure: %v", err) } - log.Debugf("%s: resetting k0s completed", p.leader) + p.leader.Log().Debugf("resetting k0s completed") - log.Debugf("%s: removing config...", p.leader) + p.leader.Log().Debugf("removing config...") if dErr := p.leader.Sudo().FS().Remove(p.leader.Configurer.K0sConfigPath()); dErr != nil { - log.Warnf("%s: failed to remove existing configuration %s: %s", p.leader, p.leader.Configurer.K0sConfigPath(), dErr) + p.leader.Log().Warnf("failed to remove existing configuration %s: %s", p.leader.Configurer.K0sConfigPath(), dErr) } - log.Debugf("%s: removing config completed", p.leader) + p.leader.Log().Debugf("removing config completed") - log.Debugf("%s: removing k0s binary...", p.leader) + p.leader.Log().Debugf("removing k0s binary...") if dErr := p.leader.Sudo().FS().Remove(p.leader.Configurer.K0sBinaryPath()); dErr != nil { - log.Warnf("%s: failed to remove existing binary %s: %s", p.leader, p.leader.Configurer.K0sConfigPath(), dErr) + p.leader.Log().Warnf("failed to remove existing binary %s: %s", p.leader.Configurer.K0sConfigPath(), dErr) } - log.Debugf("%s: removing binary completed", p.leader) + p.leader.Log().Debugf("removing binary completed") if len(p.leader.Environment) > 0 { if svc, err := p.leader.Sudo().Service(p.leader.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", p.leader, p.leader.K0sServiceName(), err) + p.leader.Log().Warnf("failed to get service %s: %v", p.leader.K0sServiceName(), err) } else if err := svc.SetEnvironment(ctx, map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %s", p.leader, err.Error()) + p.leader.Log().Warnf("failed to clean up service environment: %s", err.Error()) } } - log.Infof("%s: reset", p.leader) + p.leader.Log().Infof("reset") return nil } diff --git a/phase/reset_workers.go b/phase/reset_workers.go index 5700ed98e..280b28468 100644 --- a/phase/reset_workers.go +++ b/phase/reset_workers.go @@ -5,11 +5,11 @@ import ( "context" "fmt" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) // ResetControllers phase removes workers marked for reset from the kubernetes cluster @@ -68,15 +68,15 @@ func (p *ResetWorkers) DryRun() error { // Run the phase func (p *ResetWorkers) Run(ctx context.Context) error { - return p.parallelDo(ctx, p.hosts, func(_ context.Context, h *cluster.Host) error { + return p.parallelDo(ctx, p.hosts, func(ctx context.Context, h *cluster.Host) error { if t := p.Config.Spec.Options.EvictTaint; t.Enabled { - log.Debugf("%s: add taint: %s", h, t.String()) + h.Log().Debugf("add taint: %s", t.String()) if err := p.leader.AddTaint(h, t.String()); err != nil { return fmt.Errorf("add taint: %w", err) } } if !p.NoDrain { - log.Debugf("%s: draining node", h) + h.Log().Debugf("draining node") if err := p.leader.DrainNode( &cluster.Host{ Metadata: cluster.HostMetadata{ @@ -85,38 +85,38 @@ func (p *ResetWorkers) Run(ctx context.Context) error { }, p.Config.Spec.Options.Drain, ); err != nil { - log.Warnf("%s: failed to drain node: %s", h, err.Error()) + h.Log().Warnf("failed to drain node: %s", err.Error()) } } - log.Debugf("%s: draining node completed", h) + h.Log().Debugf("draining node completed") - log.Debugf("%s: deleting node...", h) + h.Log().Debugf("deleting node...") if !p.NoDelete { if err := p.leader.DeleteNode(&cluster.Host{ Metadata: cluster.HostMetadata{ Hostname: h.KubernetesNodeName(), }, }); err != nil { - log.Warnf("%s: failed to delete node: %s", h, err.Error()) + h.Log().Warnf("failed to delete node: %s", err.Error()) } } - log.Debugf("%s: deleting node", h) + h.Log().Debugf("deleting node") if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if svc.IsRunning(ctx) { - log.Debugf("%s: stopping k0s...", h) + h.Log().Debugf("stopping k0s...") if err := svc.Stop(ctx); err != nil { - log.Warnf("%s: failed to stop k0s: %s", h, err.Error()) + h.Log().Warnf("failed to stop k0s: %s", err.Error()) } - log.Debugf("%s: waiting for k0s to stop", h) + h.Log().Debugf("waiting for k0s to stop") if err := retry.WithDefaultTimeout(ctx, node.ServiceStoppedFunc(h, h.K0sServiceName())); err != nil { - log.Warnf("%s: failed to wait for k0s to stop: %s", h, err.Error()) + h.Log().Warnf("failed to wait for k0s to stop: %s", err.Error()) } - log.Debugf("%s: stopping k0s completed", h) + h.Log().Debugf("stopping k0s completed") } - log.Debugf("%s: resetting k0s...", h) + h.Log().Debugf("resetting k0s...") var stdoutbuf, stderrbuf bytes.Buffer proc := h.Sudo().Proc(h.K0sResetCommand()) proc.Stdout = &stdoutbuf @@ -126,31 +126,31 @@ func (p *ResetWorkers) Run(ctx context.Context) error { return fmt.Errorf("failed to run k0s reset: %w", err) } if err := waiter.Wait(); err != nil { - log.Warnf("%s: k0s reset reported failure: %s %s", h, stderrbuf.String(), stdoutbuf.String()) + h.Log().Warnf("k0s reset reported failure: %s %s", stderrbuf.String(), stdoutbuf.String()) } - log.Debugf("%s: resetting k0s completed", h) + h.Log().Debugf("resetting k0s completed") - log.Debugf("%s: removing config...", h) + h.Log().Debugf("removing config...") if dErr := h.Sudo().FS().Remove(h.Configurer.K0sConfigPath()); dErr != nil { - log.Warnf("%s: failed to remove existing configuration %s: %s", h, h.Configurer.K0sConfigPath(), dErr) + h.Log().Warnf("failed to remove existing configuration %s: %s", h.Configurer.K0sConfigPath(), dErr) } - log.Debugf("%s: removing config completed", h) + h.Log().Debugf("removing config completed") - log.Debugf("%s: removing k0s binary...", h) + h.Log().Debugf("removing k0s binary...") if dErr := h.Sudo().FS().Remove(h.Configurer.K0sBinaryPath()); dErr != nil { - log.Warnf("%s: failed to remove existing binary %s: %s", h, h.Configurer.K0sConfigPath(), dErr) + h.Log().Warnf("failed to remove existing binary %s: %s", h.Configurer.K0sConfigPath(), dErr) } - log.Debugf("%s: removing binary completed", h) + h.Log().Debugf("removing binary completed") if len(h.Environment) > 0 { if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if err := svc.SetEnvironment(ctx, map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %s", h, err.Error()) + h.Log().Warnf("failed to clean up service environment: %s", err.Error()) } } - log.Infof("%s: reset", h) + h.Log().Infof("reset") return nil }) } diff --git a/phase/restore.go b/phase/restore.go index 08c8a6676..0513b5c5c 100644 --- a/phase/restore.go +++ b/phase/restore.go @@ -6,10 +6,10 @@ import ( "fmt" "path" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/rig/v2/remotefs" - log "github.com/sirupsen/logrus" ) type Restore struct { @@ -64,16 +64,16 @@ func (p *Restore) Run(ctx context.Context) error { defer func() { if err := h.Sudo().FS().Remove(dstFile); err != nil { - log.Warnf("%s: failed to remove backup file %s: %s", h, dstFile, err) + h.Log().Warnf("failed to remove backup file %s: %s", dstFile, err) } if err := h.Sudo().FS().Remove(tmpDir); err != nil { - log.Warnf("%s: failed to remove backup temp dir %s: %s", h, tmpDir, err) + h.Log().Warnf("failed to remove backup temp dir %s: %s", tmpDir, err) } }() // Run restore - log.Infof("%s: restoring cluster state", h) + h.Log().Infof("restoring cluster state") var stdout, stderr bytes.Buffer proc := h.Sudo().Proc(h.K0sRestoreCommand(dstFile)) proc.Stdout = &stdout @@ -84,8 +84,8 @@ func (p *Restore) Run(ctx context.Context) error { } if err := waiter.Wait(); err != nil { - log.Debugf("%s: restore stdout: %s", h, stdout.String()) - log.Errorf("%s: restore failed: %s", h, stderr.String()) + h.Log().Debugf("restore stdout: %s", stdout.String()) + h.Log().Errorf("restore failed: %s", stderr.String()) return fmt.Errorf("restore failed: %w", err) } diff --git a/phase/stage_binaries.go b/phase/stage_binaries.go index f81e072a2..21053e9e2 100644 --- a/phase/stage_binaries.go +++ b/phase/stage_binaries.go @@ -7,7 +7,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" k0s "github.com/k0sproject/k0sctl/pkg/k0s" - log "github.com/sirupsen/logrus" ) // StageBinaries stages k0s binaries on hosts that need them using the host's configured BinaryProvider. @@ -27,7 +26,7 @@ func (p *StageBinaries) Prepare(config *v1beta1.Cluster) error { var prepareErr error p.hosts = p.Config.Spec.Hosts.Filter(func(h *cluster.Host) bool { if h.Reset { - log.Debugf("%s: skipping binary staging (reset)", h) + h.Log().Debugf("skipping binary staging (reset)") return false } provider, err := h.K0sBinaryProvider(p.Config.Spec.K0s.Version) @@ -40,10 +39,10 @@ func (p *StageBinaries) Prepare(config *v1beta1.Cluster) error { metaNeeds := h.Metadata.NeedsUpgrade providerNeeds := provider.NeedsUpgrade() if providerNeeds { - log.Debugf("%s: will stage binary via %T (metaNeedsUpgrade=%v, providerNeedsUpgrade=%v)", h, provider, metaNeeds, providerNeeds) + h.Log().Debugf("will stage binary via %T (metaNeedsUpgrade=%v, providerNeedsUpgrade=%v)", provider, metaNeeds, providerNeeds) return true } - log.Debugf("%s: binary staging not needed (metaNeedsUpgrade=%v, providerNeedsUpgrade=%v)", h, metaNeeds, providerNeeds) + h.Log().Debugf("binary staging not needed (metaNeedsUpgrade=%v, providerNeedsUpgrade=%v)", metaNeeds, providerNeeds) return false }) return prepareErr @@ -105,13 +104,13 @@ func (p *StageBinaries) stageForHost(ctx context.Context, h *cluster.Host) error if err != nil { return err } - log.Debugf("%s: staging k0s binary using %T", h, provider) + h.Log().Debugf("staging k0s binary using %T", provider) tmp, err := provider.Stage(ctx) if err != nil { return err } if tmp != "" { - log.Debugf("%s: staged k0s binary to %s", h, tmp) + h.Log().Debugf("staged k0s binary to %s", tmp) } h.Metadata.K0sBinaryTempFile = tmp return nil @@ -154,7 +153,7 @@ func (p *StageBinaries) populateCaches(ctx context.Context, hosts cluster.Hosts) func (p *StageBinaries) CleanUp() { _ = p.parallelDo(context.Background(), p.hosts, func(ctx context.Context, h *cluster.Host) error { if h.Metadata.K0sBinaryTempFile != "" { - log.Debugf("%s: cleaning up k0s binary temp file", h) + h.Log().Debugf("cleaning up k0s binary temp file") } if provider, err := h.K0sBinaryProvider(p.Config.Spec.K0s.Version); err == nil { provider.CleanUp(ctx) diff --git a/phase/unlock.go b/phase/unlock.go index 059a20b52..4b7228a44 100644 --- a/phase/unlock.go +++ b/phase/unlock.go @@ -3,8 +3,8 @@ package phase import ( "context" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" - log "github.com/sirupsen/logrus" ) // Unlock acquires an exclusive k0sctl lock on hosts diff --git a/phase/upgrade_controllers.go b/phase/upgrade_controllers.go index 9b4511281..fa65f82ad 100644 --- a/phase/upgrade_controllers.go +++ b/phase/upgrade_controllers.go @@ -5,11 +5,11 @@ import ( "fmt" "slices" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" - log "github.com/sirupsen/logrus" ) // UpgradeControllers upgrades the controllers one-by-one @@ -63,9 +63,9 @@ func (p *UpgradeControllers) CleanUp() { for _, h := range p.hosts { if len(h.Environment) > 0 { if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if err := svc.SetEnvironment(context.Background(), map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %s", h, err.Error()) + h.Log().Warnf("failed to clean up service environment: %s", err.Error()) } } } @@ -74,7 +74,8 @@ func (p *UpgradeControllers) CleanUp() { // Run the phase func (p *UpgradeControllers) Run(ctx context.Context) error { for _, h := range p.hosts { - log.Infof("%s: starting upgrade", h) + ctx := log.IntoContext(ctx, h.Log()) + h.Log().Infof("starting upgrade") if h.Metadata.K0sBinaryTempFile != "" && !h.FS().FileExist(h.Metadata.K0sBinaryTempFile) { return fmt.Errorf("%s: k0s binary tempfile not found: %s", h, h.Metadata.K0sBinaryTempFile) @@ -83,11 +84,11 @@ func (p *UpgradeControllers) Run(ctx context.Context) error { if t := p.Config.Spec.Options.EvictTaint; t.Enabled && t.ControllerWorkers && h.Role != "controller" { leader := p.Config.Spec.K0sLeader() err := p.Wet(leader, "apply taint to node", func() error { - log.Warnf("%s: add taint %s on %s", leader, t.String(), h) + leader.Log().Warnf("add taint %s on %s", t.String(), h) if err := leader.AddTaint(h, t.String()); err != nil { return fmt.Errorf("add taint: %w", err) } - log.Debugf("%s: wait for taint to be applied", h) + h.Log().Debugf("wait for taint to be applied") err := retry.WithDefaultTimeout(ctx, func(_ context.Context) error { taints, err := leader.Taints(h) if err != nil { @@ -105,7 +106,7 @@ func (p *UpgradeControllers) Run(ctx context.Context) error { } } - log.Debugf("%s: stop service", h) + h.Log().Debugf("stop service") svc, svcErr := h.Sudo().Service(h.K0sServiceName()) if svcErr != nil { return fmt.Errorf("get service %s: %w", h.K0sServiceName(), svcErr) @@ -124,7 +125,7 @@ func (p *UpgradeControllers) Run(ctx context.Context) error { } if h.Metadata.K0sBinaryTempFile != "" { - log.Debugf("%s: update binary", h) + h.Log().Debugf("update binary") err = p.Wet(h, "replace k0s binary", func() error { return h.UpdateK0sBinary(h.Metadata.K0sBinaryTempFile, p.Config.Spec.K0s.Version) }) @@ -133,11 +134,11 @@ func (p *UpgradeControllers) Run(ctx context.Context) error { } h.Metadata.K0sBinaryTempFile = "" } else { - log.Debugf("%s: binary already in-place at %s, skipping binary replacement", h, h.K0sInstallLocation()) + h.Log().Debugf("binary already in-place at %s, skipping binary replacement", h.K0sInstallLocation()) } if len(h.Environment) > 0 { - log.Infof("%s: updating service environment", h) + h.Log().Infof("updating service environment") err := p.Wet(h, "update service environment", func() error { return svc.SetEnvironment(ctx, h.Environment) }) @@ -168,12 +169,12 @@ func (p *UpgradeControllers) Run(ctx context.Context) error { } h.Metadata.K0sInstalled = true - log.Debugf("%s: restart service", h) + h.Log().Debugf("restart service") err = p.Wet(h, "start k0s service with the new binary", func() error { if err := svc.Start(ctx); err != nil { return err } - log.Infof("%s: waiting for the k0s service to start", h) + h.Log().Infof("waiting for the k0s service to start") if err := retry.WithDefaultTimeout(ctx, node.ServiceRunningFunc(h, h.K0sServiceName())); err != nil { return fmt.Errorf("k0s service start: %w", err) } @@ -199,14 +200,14 @@ func (p *UpgradeControllers) Run(ctx context.Context) error { if t := p.Config.Spec.Options.EvictTaint; t.Enabled && t.ControllerWorkers && h.Role != "controller" { leader := p.Config.Spec.K0sLeader() err := p.Wet(leader, "remove taint from node", func() error { - log.Infof("%s: remove taint %s on %s", leader, t.String(), h) + leader.Log().Infof("remove taint %s on %s", t.String(), h) if err := leader.RemoveTaint(h, t.String()); err != nil { return fmt.Errorf("remove taint: %w", err) } return nil }) if err != nil { - log.Warnf("%s: failed to remove taint %s on %s: %s", leader, t.String(), h, err.Error()) + leader.Log().Warnf("failed to remove taint %s on %s: %s", t.String(), h, err.Error()) } } diff --git a/phase/upgrade_workers.go b/phase/upgrade_workers.go index b5eda69b2..53c7b9f28 100644 --- a/phase/upgrade_workers.go +++ b/phase/upgrade_workers.go @@ -5,12 +5,12 @@ import ( "fmt" "math" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/k0sctl/pkg/node" "github.com/k0sproject/k0sctl/pkg/retry" "github.com/k0sproject/rig/v2/cmd" - log "github.com/sirupsen/logrus" ) // UpgradeWorkers upgrades workers in batches @@ -80,9 +80,9 @@ func (p *UpgradeWorkers) CleanUp() { _ = p.parallelDo(context.Background(), p.hosts, func(_ context.Context, h *cluster.Host) error { if len(h.Environment) > 0 { if svc, err := h.Sudo().Service(h.K0sServiceName()); err != nil { - log.Warnf("%s: failed to get service %s: %v", h, h.K0sServiceName(), err) + h.Log().Warnf("failed to get service %s: %v", h.K0sServiceName(), err) } else if err := svc.SetEnvironment(context.Background(), map[string]string{}); err != nil { - log.Warnf("%s: failed to clean up service environment: %s", h, err.Error()) + h.Log().Warnf("failed to clean up service environment: %s", err.Error()) } } _ = p.leader.UncordonNode(h) @@ -112,14 +112,14 @@ func (p *UpgradeWorkers) Run(ctx context.Context) error { func (p *UpgradeWorkers) cordonWorker(_ context.Context, h *cluster.Host) error { if p.NoDrain { - log.Debugf("%s: not cordoning because --no-drain given", h) + h.Log().Debugf("not cordoning because --no-drain given") return nil } if !p.IsWet() { p.DryMsg(h, "cordon node") return nil } - log.Debugf("%s: cordon", h) + h.Log().Debugf("cordon") if err := p.leader.CordonNode(h); err != nil { return fmt.Errorf("cordon node: %w", err) } @@ -134,12 +134,12 @@ func (p *UpgradeWorkers) uncordonWorker(_ context.Context, h *cluster.Host) erro } return nil } - log.Debugf("%s: uncordon", h) + h.Log().Debugf("uncordon") if err := p.leader.UncordonNode(h); err != nil { return fmt.Errorf("uncordon node: %w", err) } if t := p.Config.Spec.Options.EvictTaint; t.Enabled { - log.Debugf("%s: remove taint: %s", h, t.String()) + h.Log().Debugf("remove taint: %s", t.String()) if err := p.leader.RemoveTaint(h, t.String()); err != nil { return fmt.Errorf("remove taint: %w", err) } @@ -149,11 +149,11 @@ func (p *UpgradeWorkers) uncordonWorker(_ context.Context, h *cluster.Host) erro func (p *UpgradeWorkers) drainWorker(_ context.Context, h *cluster.Host) error { if p.NoDrain { - log.Debugf("%s: not draining because --no-drain given", h) + h.Log().Debugf("not draining because --no-drain given") return nil } if t := p.Config.Spec.Options.EvictTaint; t.Enabled { - log.Debugf("%s: add taint: %s", h, t.String()) + h.Log().Debugf("add taint: %s", t.String()) err := p.Wet(h, "add taint "+t.String(), func() error { if err := p.leader.AddTaint(h, t.String()); err != nil { return fmt.Errorf("add taint: %w", err) @@ -168,7 +168,7 @@ func (p *UpgradeWorkers) drainWorker(_ context.Context, h *cluster.Host) error { p.DryMsg(h, "drain node") return nil } - log.Debugf("%s: drain", h) + h.Log().Debugf("drain") if err := p.leader.DrainNode(h, p.Config.Spec.Options.Drain); err != nil { return fmt.Errorf("drain node: %w", err) } @@ -176,12 +176,12 @@ func (p *UpgradeWorkers) drainWorker(_ context.Context, h *cluster.Host) error { } func (p *UpgradeWorkers) start(_ context.Context, h *cluster.Host) error { - log.Infof("%s: starting upgrade", h) + h.Log().Infof("starting upgrade") return nil } func (p *UpgradeWorkers) finish(_ context.Context, h *cluster.Host) error { - log.Infof("%s: upgrade finished", h) + h.Log().Infof("upgrade finished") return nil } @@ -191,7 +191,7 @@ func (p *UpgradeWorkers) upgradeWorker(ctx context.Context, h *cluster.Host) err return fmt.Errorf("get service %s: %w", h.K0sServiceName(), svcErr) } - log.Debugf("%s: stop service", h) + h.Log().Debugf("stop service") err := p.Wet(h, "stop k0s service", func() error { if err := svc.Stop(ctx); err != nil { return err @@ -208,7 +208,7 @@ func (p *UpgradeWorkers) upgradeWorker(ctx context.Context, h *cluster.Host) err } if h.Metadata.K0sBinaryTempFile != "" { - log.Debugf("%s: update binary", h) + h.Log().Debugf("update binary") err = p.Wet(h, "replace k0s binary", func() error { return h.UpdateK0sBinary(h.Metadata.K0sBinaryTempFile, p.Config.Spec.K0s.Version) }) @@ -218,11 +218,11 @@ func (p *UpgradeWorkers) upgradeWorker(ctx context.Context, h *cluster.Host) err // Clear the temp file metadata after successful update to avoid stale paths. h.Metadata.K0sBinaryTempFile = "" } else { - log.Debugf("%s: binary already in-place at %s, skipping binary replacement", h, h.K0sInstallLocation()) + h.Log().Debugf("binary already in-place at %s, skipping binary replacement", h.K0sInstallLocation()) } if len(h.Environment) > 0 { - log.Infof("%s: updating service environment", h) + h.Log().Infof("updating service environment") err := p.Wet(h, "update service environment", func() error { return svc.SetEnvironment(ctx, h.Environment) }) @@ -256,15 +256,15 @@ func (p *UpgradeWorkers) upgradeWorker(ctx context.Context, h *cluster.Host) err } h.Metadata.K0sInstalled = true - log.Debugf("%s: restart service", h) + h.Log().Debugf("restart service") err = p.Wet(h, "restart k0s service", func() error { if err := svc.Start(ctx); err != nil { return err } if NoWait { - log.Debugf("%s: not waiting because --no-wait given", h) + h.Log().Debugf("not waiting because --no-wait given") } else { - log.Infof("%s: waiting for node to become ready again", h) + h.Log().Infof("waiting for node to become ready again") if err := retry.WithDefaultTimeout(ctx, node.KubeNodeReadyFunc(h)); err != nil { return fmt.Errorf("node did not become ready: %w", err) } diff --git a/phase/uploadfiles.go b/phase/uploadfiles.go index 05e57121e..9714be707 100644 --- a/phase/uploadfiles.go +++ b/phase/uploadfiles.go @@ -13,7 +13,7 @@ import ( "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/rig/v2/remotefs" - log "github.com/sirupsen/logrus" + log "github.com/k0sproject/k0sctl/internal/log" ) // UploadFiles implements a phase which upload files to hosts @@ -69,7 +69,7 @@ func (p *UploadFiles) uploadFiles(ctx context.Context, h *cluster.Host) error { } func (p *UploadFiles) ensureDir(h *cluster.Host, dir, perm, owner string) error { - log.Debugf("%s: ensuring directory %s", h, dir) + h.Log().Debugf("ensuring directory %s", dir) if !h.FS().FileExist(dir) { targetPerm := perm if targetPerm == "" { @@ -105,7 +105,7 @@ func (p *UploadFiles) ensureDir(h *cluster.Host, dir, perm, owner string) error } func (p *UploadFiles) uploadFile(h *cluster.Host, f *cluster.UploadFile) error { - log.Infof("%s: uploading %s", h, f) + h.Log().Infof("uploading %s", f) numfiles := len(f.Sources) for i, s := range f.Sources { @@ -116,7 +116,7 @@ func (p *UploadFiles) uploadFile(h *cluster.Host, f *cluster.UploadFile) error { src := path.Join(f.Base, s.Path) if numfiles > 1 { - log.Infof("%s: uploading file %s => %s (%d of %d)", h, src, dest, i+1, numfiles) + h.Log().Infof("uploading file %s => %s (%d of %d)", src, dest, i+1, numfiles) } owner := f.Owner() @@ -149,7 +149,7 @@ func (p *UploadFiles) uploadFile(h *cluster.Host, f *cluster.UploadFile) error { return err } } else { - log.Infof("%s: file already exists and hasn't been changed, skipping upload", h) + h.Log().Infof("file already exists and hasn't been changed, skipping upload") } if stat == nil { @@ -168,7 +168,7 @@ func (p *UploadFiles) uploadFile(h *cluster.Host, f *cluster.UploadFile) error { } func (p *UploadFiles) uploadData(h *cluster.Host, f *cluster.UploadFile) error { - log.Infof("%s: uploading inline data", h) + h.Log().Infof("uploading inline data") dest := f.DestinationFile if dest == "" { if f.DestinationDir != "" { @@ -209,7 +209,7 @@ func (p *UploadFiles) uploadData(h *cluster.Host, f *cluster.UploadFile) error { } func (p *UploadFiles) uploadURL(h *cluster.Host, f *cluster.UploadFile) error { - log.Infof("%s: downloading %s to host %s", h, f, f.DestinationFile) + h.Log().Infof("downloading %s to host %s", f, f.DestinationFile) owner := f.Owner() if err := p.ensureDir(h, path.Dir(f.DestinationFile), f.DirPermString, owner); err != nil { @@ -235,7 +235,7 @@ func (p *UploadFiles) uploadURL(h *cluster.Host, f *cluster.UploadFile) error { func (p *UploadFiles) applyFileMetadata(h *cluster.Host, dest, owner, perm string, timestamp *time.Time) error { if owner != "" { err := p.Wet(h, fmt.Sprintf("set owner for %s to %s", dest, owner), func() error { - log.Debugf("%s: setting owner %s for %s", h, owner, dest) + h.Log().Debugf("setting owner %s for %s", owner, dest) return h.Sudo().FS().Chown(dest, owner) }) if err != nil { @@ -245,7 +245,7 @@ func (p *UploadFiles) applyFileMetadata(h *cluster.Host, dest, owner, perm strin if perm != "" { err := p.Wet(h, fmt.Sprintf("set permissions for %s to %s", dest, perm), func() error { - log.Debugf("%s: setting permissions %s for %s", h, perm, dest) + h.Log().Debugf("setting permissions %s for %s", perm, dest) return chmodWithString(h, dest, perm) }) if err != nil { @@ -255,7 +255,7 @@ func (p *UploadFiles) applyFileMetadata(h *cluster.Host, dest, owner, perm strin if timestamp != nil { err := p.Wet(h, fmt.Sprintf("set timestamp for %s to %s", dest, timestamp.String()), func() error { - log.Debugf("%s: touching %s", h, dest) + h.Log().Debugf("touching %s", dest) return h.Sudo().FS().Touch(dest, *timestamp) }) if err != nil { diff --git a/phase/validate_etcd_members.go b/phase/validate_etcd_members.go index 8db214e2e..68c88ba90 100644 --- a/phase/validate_etcd_members.go +++ b/phase/validate_etcd_members.go @@ -5,9 +5,9 @@ import ( "fmt" "slices" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" - log "github.com/sirupsen/logrus" ) // ValidateEtcdMembers checks for existing etcd members with the same IP as a new controller @@ -34,17 +34,17 @@ func (p *ValidateEtcdMembers) Prepare(config *v1beta1.Cluster) error { // ShouldRun is true when there are new controllers and etcd func (p *ValidateEtcdMembers) ShouldRun() bool { if p.Config.Spec.K0sLeader().Metadata.K0sRunningVersion == nil { - log.Debugf("%s: leader has no k0s running, assuming a fresh cluster", p.Config.Spec.K0sLeader()) + p.Config.Spec.K0sLeader().Log().Debugf("leader has no k0s running, assuming a fresh cluster") return false } if p.Config.Spec.K0sLeader().Role == "single" { - log.Debugf("%s: leader is a single node, assuming no etcd", p.Config.Spec.K0sLeader()) + p.Config.Spec.K0sLeader().Log().Debugf("leader is a single node, assuming no etcd") return false } if s := p.Config.StorageType(); s != "etcd" { - log.Debugf("%s: storage type is %q, not k0s managed etcd", p.Config.Spec.K0sLeader(), s) + p.Config.Spec.K0sLeader().Log().Debugf("storage type is %q, not k0s managed etcd", s) } return len(p.hosts) > 0 @@ -65,10 +65,10 @@ func (p *ValidateEtcdMembers) validateControllerSwap() error { } for _, h := range p.hosts { - log.Debugf("%s: host is new, checking if etcd members list already contains %s", h, h.PrivateAddress) + h.Log().Debugf("host is new, checking if etcd members list already contains %s", h.PrivateAddress) if slices.Contains(p.Config.Metadata.EtcdMembers, h.PrivateAddress) { if Force { - log.Infof("%s: force used, running 'k0s etcd leave' for the host", h) + h.Log().Infof("force used, running 'k0s etcd leave' for the host") leader := p.Config.Spec.K0sLeader() leaveCommand := leader.Configurer.K0sCmdf("etcd leave --peer-address %s", h.PrivateAddress) err := p.Wet(h, fmt.Sprintf("remove host from etcd using %v", leaveCommand), func() error { @@ -81,7 +81,7 @@ func (p *ValidateEtcdMembers) validateControllerSwap() error { } return fmt.Errorf("controller %s is listed as an existing etcd member but k0s is not found installed on it, the host may have been replaced. check the host and use `k0s etcd leave --peer-address %s on a controller or re-run apply with --force", h, h.PrivateAddress) } - log.Debugf("%s: no match, assuming its safe to install", h) + h.Log().Debugf("no match, assuming its safe to install") } return nil diff --git a/phase/validate_facts.go b/phase/validate_facts.go index 63b1e664e..a599e44e8 100644 --- a/phase/validate_facts.go +++ b/phase/validate_facts.go @@ -4,8 +4,8 @@ import ( "context" "fmt" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" - log "github.com/sirupsen/logrus" ) // ValidateFacts performs remote OS detection diff --git a/phase/validate_hosts.go b/phase/validate_hosts.go index b5b968f34..dbee64081 100644 --- a/phase/validate_hosts.go +++ b/phase/validate_hosts.go @@ -5,15 +5,15 @@ import ( "fmt" "io/fs" "path" - "strings" "slices" + "strings" "sync" "time" "github.com/k0sproject/k0sctl/configurer" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) // ValidateHosts performs remote OS detection @@ -76,7 +76,7 @@ func (p *ValidateHosts) Run(ctx context.Context) error { func (p *ValidateHosts) warnK0sBinaryPath(_ context.Context, h *cluster.Host) error { if h.K0sBinaryPath != "" { - log.Warnf("%s: k0s binary path is set to %q, version checking for the host is disabled. The k0s version for other hosts is %s.", h, h.K0sBinaryPath, p.Config.Spec.K0s.Version) + h.Log().Warnf("k0s binary path is set to %q, version checking for the host is disabled. The k0s version for other hosts is %s.", h.K0sBinaryPath, p.Config.Spec.K0s.Version) } return nil @@ -134,7 +134,7 @@ func (p *ValidateHosts) validateOS(_ context.Context, h *cluster.Host) error { return fmt.Errorf("windows workers require k0s version %s", k0sWindowsWorkerSupportSince) } - log.Warnf("%s: windows worker node support is experimental", h) + h.Log().Warnf("windows worker node support is experimental") return nil } @@ -154,20 +154,20 @@ func (p *ValidateHosts) cleanUpOldK0sTmpFiles(_ context.Context, h *cluster.Host if !strings.HasPrefix(d.Name(), "k0s.tmp.") { return nil } - log.Debugf("%s: found k0s binary upload temporary file %s", h, entryPath) + h.Log().Debugf("found k0s binary upload temporary file %s", entryPath) info, err := d.Info() if err != nil { - log.Warnf("%s: failed to get info for %s: %v", h, entryPath, err) + h.Log().Warnf("failed to get info for %s: %v", entryPath, err) return nil } if time.Since(info.ModTime()) > cleanUpOlderThan { - log.Warnf("%s: cleaning up old k0s binary upload temporary file %s", h, entryPath) + h.Log().Warnf("cleaning up old k0s binary upload temporary file %s", entryPath) if err := h.Sudo().FS().Remove(entryPath); err != nil { - log.Warnf("%s: failed to delete %s: %v", h, entryPath, err) + h.Log().Warnf("failed to delete %s: %v", entryPath, err) } return nil } - log.Warnf("%s: found k0s binary upload temporary file %s that is newer than %s", h, entryPath, cleanUpOlderThan) + h.Log().Warnf("found k0s binary upload temporary file %s that is newer than %s", entryPath, cleanUpOlderThan) return nil }) if err != nil { @@ -210,7 +210,7 @@ func (p *ValidateHosts) validateClockSkew(ctx context.Context) error { for h, skew := range skews { deviation := (skew - median).Abs() if deviation > maxSkew { - log.Errorf("%s: clock skew of %.0f seconds exceeds the maximum of %.0f seconds", h, deviation.Seconds(), maxSkew.Seconds()) + h.Log().Errorf("clock skew of %.0f seconds exceeds the maximum of %.0f seconds", deviation.Seconds(), maxSkew.Seconds()) foundExceeding++ } } diff --git a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/host.go b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/host.go index 83db0fdbc..5a6ab486b 100644 --- a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/host.go +++ b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/host.go @@ -5,11 +5,13 @@ import ( "fmt" "io/fs" "log/slog" + "net" "net/url" gos "os" "path" "path/filepath" "slices" + "strconv" "strings" "time" @@ -17,37 +19,28 @@ import ( "github.com/jellydator/validation" "github.com/jellydator/validation/is" "github.com/k0sproject/k0sctl/configurer" + log "github.com/k0sproject/k0sctl/internal/log" k0s "github.com/k0sproject/k0sctl/pkg/k0s" "github.com/k0sproject/k0sctl/pkg/k0s/binprovider" rig "github.com/k0sproject/rig/v2" rigos "github.com/k0sproject/rig/v2/os" "github.com/k0sproject/rig/v2/remotefs" "github.com/k0sproject/version" - sloglogrus "github.com/samber/slog-logrus/v2" - log "github.com/sirupsen/logrus" ) var K0sForceFlagSince = version.MustParse("v1.27.4+k0s.0") var _ binprovider.Host = (*Host)(nil) -// rigLogger bridges rig v2's slog-based logging into k0sctl's logrus output. -// It wraps the logrus standard logger (the same singleton configured in cmd's -// logging setup), so any level and hook changes applied there are reflected -// automatically. rig v2 has no global logger setter; the logger is injected -// per client via rig.WithLogger at Connect time (see Host.Connect). -var rigLogger = slog.New(sloglogrus.Option{ - Level: slog.LevelDebug, - Logger: log.StandardLogger(), -}.NewLogrusHandler()) - -// Connect establishes the connection to the host, injecting k0sctl's logger so -// that rig's internal logging is routed into k0sctl's logrus output. +// Connect establishes the connection to the host, injecting k0sctl's base +// logger so that rig's internal logging shares k0sctl's output. The base +// logger is passed untagged on purpose: rig wraps it with its own host and +// protocol attributes, using the same attribute keys k0sctl uses. func (h *Host) Connect(ctx context.Context) error { if h.Client == nil { client, err := rig.NewClient( rig.WithConnectionFactory(&h.CompositeConfig), - rig.WithLogger(rigLogger), + rig.WithLogger(log.Base()), ) if err != nil { return fmt.Errorf("create rig client: %w", err) @@ -57,8 +50,24 @@ func (h *Host) Connect(ctx context.Context) error { return h.Client.Connect(ctx) } -// String returns a human-readable description of the host, safe before Connect. +// Log returns a logger scoped to the host. It is rebuilt on each call so the +// host attribute always reflects the host's current display name. +func (h *Host) Log() *log.Logger { + return log.With(slog.String(log.KeyHost, h.String())) +} + +// String returns a human-readable name for the host. It intentionally +// matches the name rig gives the underlying connection so that the host +// identity in log records is the same before and after connecting. func (h *Host) String() string { + switch { + case h.SSH != nil: + return net.JoinHostPort(h.SSH.Address, strconv.Itoa(h.SSH.Port)) + case h.WinRM != nil: + return net.JoinHostPort(h.WinRM.Address, strconv.Itoa(h.WinRM.Port)) + case bool(h.Localhost): + return "localhost" + } if h.Client != nil { return h.Client.String() } @@ -186,11 +195,11 @@ func (h *Host) SetDefaults() { _ = defaults.Set(&h.CompositeConfig) if h.InstallFlags.Get("--single") != "" && h.InstallFlags.GetValue("--single") != "false" && h.Role != "single" { - log.Debugf("%s: changed role from '%s' to 'single' because of --single installFlag", h, h.Role) + h.Log().Debugf("changed role from '%s' to 'single' because of --single installFlag", h.Role) h.Role = "single" } if h.InstallFlags.Get("--enable-worker") != "" && h.InstallFlags.GetValue("--enable-worker") != "false" && h.Role != "controller+worker" { - log.Debugf("%s: changed role from '%s' to 'controller+worker' because of --enable-worker installFlag", h, h.Role) + h.Log().Debugf("changed role from '%s' to 'controller+worker' because of --enable-worker installFlag", h.Role) h.Role = "controller+worker" } @@ -200,7 +209,7 @@ func (h *Host) SetDefaults() { if dd := h.InstallFlags.GetValue("--data-dir"); dd != "" { if h.DataDir != "" { - log.Debugf("%s: changed dataDir from '%s' to '%s' because of --data-dir installFlag", h, h.DataDir, dd) + h.Log().Debugf("changed dataDir from '%s' to '%s' because of --data-dir installFlag", h.DataDir, dd) } h.InstallFlags.Delete("--data-dir") h.DataDir = dd @@ -208,7 +217,7 @@ func (h *Host) SetDefaults() { if krd := h.InstallFlags.GetValue("--kubelet-root-dir"); krd != "" { if h.KubeletRootDir != "" { - log.Debugf("%s: changed kubeletRootDir from '%s' to '%s' because of --kubelet-root-dir installFlag", h, h.DataDir, krd) + h.Log().Debugf("changed kubeletRootDir from '%s' to '%s' because of --kubelet-root-dir installFlag", h.DataDir, krd) } h.InstallFlags.Delete("--kubelet-root-dir") h.KubeletRootDir = krd @@ -549,7 +558,7 @@ func (h *Host) K0sInstallFlags() (Flags, error) { } if flags.Include("--force") && h.Metadata.K0sBinaryVersion != nil && h.Metadata.K0sBinaryVersion.LessThan(K0sForceFlagSince) { - log.Warnf("%s: k0s version %s does not support the --force flag, ignoring it", h, h.Metadata.K0sBinaryVersion) + h.Log().Warnf("k0s version %s does not support the --force flag, ignoring it", h.Metadata.K0sBinaryVersion) flags.Delete("--force") } @@ -616,7 +625,7 @@ func (h *Host) InstallK0sBinary(path string) error { } dir := h.k0sBinaryPathDir() - log.Debugf("%s: k0s binary dir: %q", h, dir) + h.Log().Debugf("k0s binary dir: %q", dir) if err := h.Sudo().FS().MkdirAll(dir, fs.FileMode(0o755)); err != nil { return fmt.Errorf("create k0s binary dir: %w", err) } @@ -630,7 +639,7 @@ func (h *Host) InstallK0sBinary(path string) error { if h.FS().FileExist(path) { if err := h.Sudo().FS().Remove(path); err != nil { - log.Warnf("%s: failed to delete k0s binary tempfile: %s", h, err) + h.Log().Warnf("failed to delete k0s binary tempfile: %s", err) } } @@ -796,22 +805,22 @@ func (h *Host) NeedInetUtils() bool { func (h *Host) FileChanged(lpath, rpath string) bool { lstat, err := gos.Stat(lpath) if err != nil { - log.Debugf("%s: local stat failed: %s", h, err) + h.Log().Debugf("local stat failed: %s", err) return true } rstat, err := h.Sudo().FS().Stat(rpath) if err != nil { - log.Debugf("%s: remote stat failed: %s", h, err) + h.Log().Debugf("remote stat failed: %s", err) return true } if lstat.Size() != rstat.Size() { - log.Debugf("%s: file sizes for %s differ (%d vs %d)", h, lpath, lstat.Size(), rstat.Size()) + h.Log().Debugf("file sizes for %s differ (%d vs %d)", lpath, lstat.Size(), rstat.Size()) return true } if !lstat.ModTime().Equal(rstat.ModTime()) { - log.Debugf("%s: file modtimes for %s differ (%s vs %s)", h, lpath, lstat.ModTime(), rstat.ModTime()) + h.Log().Debugf("file modtimes for %s differ (%s vs %s)", lpath, lstat.ModTime(), rstat.ModTime()) return true } @@ -836,7 +845,7 @@ func (h *Host) ExpandTokens(input string, k0sVersion *version.Version) string { if arch, err := h.Arch(); err == nil { archToken = arch } else { - log.Warnf("%s: failed to resolve architecture for token expansion: %v", h, err) + h.Log().Warnf("failed to resolve architecture for token expansion: %v", err) } } builder := strings.Builder{} @@ -882,13 +891,13 @@ func (h *Host) ExpandTokens(input string, k0sVersion *version.Version) string { func (h *Host) FlagsChanged() bool { our, err := h.K0sInstallFlags() if err != nil { - log.Warnf("%s: could not get install flags: %s", h, err) + h.Log().Warnf("could not get install flags: %s", err) our = Flags{} } ex := our.GetValue("--kubelet-extra-args") ourExtra, err := NewFlags(ex) if err != nil { - log.Warnf("%s: could not parse local --kubelet-extra-args value %q: %s", h, ex, err) + h.Log().Warnf("could not parse local --kubelet-extra-args value %q: %s", ex, err) } var their Flags @@ -896,11 +905,11 @@ func (h *Host) FlagsChanged() bool { ex = their.GetValue("--kubelet-extra-args") theirExtra, err := NewFlags(ex) if err != nil { - log.Warnf("%s: could not parse remote --kubelet-extra-args value %q: %s", h, ex, err) + h.Log().Warnf("could not parse remote --kubelet-extra-args value %q: %s", ex, err) } if !ourExtra.Equals(theirExtra) { - log.Debugf("%s: installFlags --kubelet-extra-args seem to have changed: %+v vs %+v", h, theirExtra.Map(), ourExtra.Map()) + h.Log().Debugf("installFlags --kubelet-extra-args seem to have changed: %+v vs %+v", theirExtra.Map(), ourExtra.Map()) return true } @@ -911,11 +920,11 @@ func (h *Host) FlagsChanged() bool { } if our.Equals(their) { - log.Debugf("%s: installFlags have not changed", h) + h.Log().Debugf("installFlags have not changed") return false } - log.Debugf("%s: installFlags seem to have changed. existing: %+v new: %+v", h, their.Map(), our.Map()) + h.Log().Debugf("installFlags seem to have changed. existing: %+v new: %+v", their.Map(), our.Map()) return true } @@ -937,7 +946,7 @@ func (h *Host) RunHooks(ctx context.Context, action, stage string) error { return err } - log.Infof("%s: running %s %s hook: %q", h, stage, action, cmd) + h.Log().Infof("running %s %s hook: %q", stage, action, cmd) if err := h.Exec(cmd); err != nil { return fmt.Errorf("failed to execute hook %q for action %q stage %q on host %s: %w", cmd, action, stage, h.Address(), err) } diff --git a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/hosts.go b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/hosts.go index 541be950a..8cf7e0dd7 100644 --- a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/hosts.go +++ b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/hosts.go @@ -5,6 +5,8 @@ import ( "fmt" "strings" "sync" + + log "github.com/k0sproject/k0sctl/internal/log" ) // Hosts are destnation hosts @@ -114,7 +116,8 @@ func (hosts Hosts) Each(ctx context.Context, filters ...func(context.Context, *H if err := ctx.Err(); err != nil { return fmt.Errorf("error from context: %w", err) } - if err := filter(ctx, h); err != nil { + if err := filter(log.IntoContext(ctx, h.Log()), h); err != nil { + h.Log().With(log.KeyError, err.Error()).Error("phase failed") return err } } @@ -141,7 +144,8 @@ func (hosts Hosts) ParallelEach(ctx context.Context, filters ...func(context.Con mu.Unlock() return } - if err := filter(ctx, h); err != nil { + if err := filter(log.IntoContext(ctx, h.Log()), h); err != nil { + h.Log().With(log.KeyError, err.Error()).Error("phase failed") mu.Lock() errors = append(errors, fmt.Sprintf("%s: %s", h.String(), err.Error())) mu.Unlock() diff --git a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/k0s.go b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/k0s.go index b4e10d1d8..07874bdbf 100644 --- a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/k0s.go +++ b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/k0s.go @@ -12,10 +12,10 @@ import ( "github.com/creasty/defaults" "github.com/jellydator/validation" "github.com/k0sproject/dig" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/retry" "github.com/k0sproject/rig/v2/cmd" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" "gopkg.in/yaml.v2" ) diff --git a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/uploadfile.go b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/uploadfile.go index 1af95a920..3453ea2ed 100644 --- a/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/uploadfile.go +++ b/pkg/apis/k0sctl.k0sproject.io/v1beta1/cluster/uploadfile.go @@ -10,7 +10,7 @@ import ( "github.com/bmatcuk/doublestar/v4" "github.com/jellydator/validation" - log "github.com/sirupsen/logrus" + log "github.com/k0sproject/k0sctl/internal/log" ) type LocalFile struct { diff --git a/pkg/k0s/binprovider/existing.go b/pkg/k0s/binprovider/existing.go index fa335a3cb..674298b2c 100644 --- a/pkg/k0s/binprovider/existing.go +++ b/pkg/k0s/binprovider/existing.go @@ -3,8 +3,8 @@ package binprovider import ( "context" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/k0s" - log "github.com/sirupsen/logrus" ) // existing uses a k0s binary that is already present on the host. diff --git a/pkg/k0s/binprovider/helpers.go b/pkg/k0s/binprovider/helpers.go index 18bebe721..4442dce42 100644 --- a/pkg/k0s/binprovider/helpers.go +++ b/pkg/k0s/binprovider/helpers.go @@ -10,9 +10,9 @@ import ( "strings" "time" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/rig/v2/remotefs" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) // stagedFile is embedded by providers that place a temporary binary on the remote host. diff --git a/pkg/k0s/binprovider/local_file.go b/pkg/k0s/binprovider/local_file.go index 7a73019d2..9dc94f8e8 100644 --- a/pkg/k0s/binprovider/local_file.go +++ b/pkg/k0s/binprovider/local_file.go @@ -3,8 +3,8 @@ package binprovider import ( "context" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/k0s" - log "github.com/sirupsen/logrus" ) // localFile uploads a developer-supplied k0s binary from the local machine to the host. diff --git a/pkg/k0s/binprovider/local_upload.go b/pkg/k0s/binprovider/local_upload.go index d446d0051..f496871f6 100644 --- a/pkg/k0s/binprovider/local_upload.go +++ b/pkg/k0s/binprovider/local_upload.go @@ -14,9 +14,9 @@ import ( "time" "github.com/adrg/xdg" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/k0sproject/k0sctl/pkg/k0s" "github.com/k0sproject/version" - log "github.com/sirupsen/logrus" ) // localUpload downloads a k0s binary to a local cache and uploads it to the host. diff --git a/pkg/node/statusfunc.go b/pkg/node/statusfunc.go index d8038a42c..00c2da857 100644 --- a/pkg/node/statusfunc.go +++ b/pkg/node/statusfunc.go @@ -11,8 +11,6 @@ import ( "github.com/k0sproject/k0sctl/pkg/retry" "github.com/k0sproject/rig/v2/cmd" "github.com/k0sproject/rig/v2/protocol" - - log "github.com/sirupsen/logrus" ) // this file contains functions that return functions that can be used with pkg/retry to wait on certain @@ -104,10 +102,10 @@ func ScheduledEventsAfterFunc(h *cluster.Host, since time.Time) retryFunc { } for _, e := range events.Items { if e.EventTime.Before(since) { - log.Tracef("%s: skipping prior event for %s: %s < %s", h, e.InvolvedObject.Name, e.EventTime.Format(time.RFC3339), since.Format(time.RFC3339)) + h.Log().Tracef("skipping prior event for %s: %s < %s", e.InvolvedObject.Name, e.EventTime.Format(time.RFC3339), since.Format(time.RFC3339)) continue } - log.Debugf("%s: found a 'Scheduled' event occuring after %s", h, since) + h.Log().Debugf("found a 'Scheduled' event occuring after %s", since) return nil } return fmt.Errorf("didn't find any 'Scheduled' kube-system events after %s", since) diff --git a/pkg/retry/retry.go b/pkg/retry/retry.go index 0a9ae8c5e..dd11a1719 100644 --- a/pkg/retry/retry.go +++ b/pkg/retry/retry.go @@ -7,7 +7,7 @@ import ( "fmt" "time" - log "github.com/sirupsen/logrus" + log "github.com/k0sproject/k0sctl/internal/log" ) var ( @@ -19,6 +19,21 @@ var ( ErrAbort = errors.New("retrying aborted") ) +// logAttempt logs a retry attempt with structured attributes using the logger +// carried by the context, so the host being retried against is attached when +// the retry happens inside a per-host operation. To keep the default output +// calm during normal short waits, attempts only surface at info level once +// ~15 seconds have passed and then roughly twice a minute; the rest go to +// debug. +func logAttempt(ctx context.Context, attempt int, lastErr error) { + logger := log.FromContext(ctx).With(log.KeyAttempt, attempt, log.KeyError, lastErr.Error()) + if attempt >= 3 && attempt%6 == 3 { + logger.Info("retrying") + } else { + logger.Debug("retrying") + } +} + // Context retries f at constant Interval until it succeeds or the context is cancelled. func Context(ctx context.Context, f func(ctx context.Context) error) error { var lastErr error @@ -39,23 +54,23 @@ func Context(ctx context.Context, f func(ctx context.Context) error) error { for { select { case <-ctx.Done(): - log.Tracef("retry.Context: context cancelled after %d attempts", attempt) + log.FromContext(ctx).Tracef("retry.Context: context cancelled after %d attempts", attempt) return errors.Join(ctx.Err(), lastErr) case <-ticker.C: attempt++ if lastErr != nil { - log.Debugf("retrying, attempt %d - last error: %v", attempt, lastErr) + logAttempt(ctx, attempt, lastErr) } lastErr = f(ctx) if errors.Is(lastErr, ErrAbort) { - log.Tracef("retry.Context: aborted after %d attempts", attempt) + log.FromContext(ctx).Tracef("retry.Context: aborted after %d attempts", attempt) return lastErr } if lastErr == nil { - log.Tracef("retry.Context: succeeded after %d attempts", attempt) + log.FromContext(ctx).Tracef("retry.Context: succeeded after %d attempts", attempt) return nil } - log.Tracef("retry.Context: attempt %d failed: %s", attempt, lastErr) + log.FromContext(ctx).Tracef("retry.Context: attempt %d failed: %s", attempt, lastErr) } } } @@ -96,24 +111,24 @@ func Times(ctx context.Context, times int, f func(context.Context) error) error for { select { case <-ctx.Done(): - log.Tracef("retry.Times: context cancelled after %d attempts", i) + log.FromContext(ctx).Tracef("retry.Times: context cancelled after %d attempts", i) return errors.Join(ctx.Err(), lastErr) case <-ticker.C: if lastErr != nil { - log.Debugf("retrying: attempt %d of %d (previous error: %v)", i+1, times, lastErr) + logAttempt(ctx, i+1, lastErr) } lastErr = f(ctx) if errors.Is(lastErr, ErrAbort) { - log.Tracef("retry.Times: aborted after %d attempts", i) + log.FromContext(ctx).Tracef("retry.Times: aborted after %d attempts", i) return lastErr } if lastErr == nil { - log.Tracef("retry.Times: succeeded on attempt %d", i) + log.FromContext(ctx).Tracef("retry.Times: succeeded on attempt %d", i) return nil } i++ if i >= times { - log.Tracef("retry.Times: exceeded %d attempts", times) + log.FromContext(ctx).Tracef("retry.Times: exceeded %d attempts", times) return fmt.Errorf("retry limit exceeded after %d attempts: %w", times, lastErr) } } diff --git a/pkg/retry/retry_test.go b/pkg/retry/retry_test.go index 8ebda940c..cdf87e5aa 100644 --- a/pkg/retry/retry_test.go +++ b/pkg/retry/retry_test.go @@ -3,9 +3,13 @@ package retry import ( "context" "errors" + "fmt" + "log/slog" + "sync" "testing" "time" + log "github.com/k0sproject/k0sctl/internal/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -168,3 +172,210 @@ func TestWithDefaultTimeout(t *testing.T) { assert.Error(t, err) //nolint:testifylint assert.GreaterOrEqual(t, elapsed.Milliseconds(), int64(5)) } + +// retryLogRecord is a flattened view of a captured slog.Record, pulling out +// the attrs logAttempt attaches so tests can assert on them without +// depending on any particular rendering. +type retryLogRecord struct { + level slog.Level + message string + attempt int64 + hasAttempt bool + errText string + host string +} + +// capturingHandler is a minimal slog.Handler that records every record it +// receives, merging in attrs attached via WithAttrs the way a real handler +// would, so tests can inspect what retry logged without parsing text output. +type capturingHandler struct { + mu *sync.Mutex + records *[]retryLogRecord + attrs []slog.Attr +} + +func newCapturingHandler() *capturingHandler { + return &capturingHandler{mu: &sync.Mutex{}, records: &[]retryLogRecord{}} +} + +func (h *capturingHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (h *capturingHandler) Handle(_ context.Context, r slog.Record) error { + rec := retryLogRecord{level: r.Level, message: r.Message} + apply := func(a slog.Attr) { + switch a.Key { + case "attempt": + rec.attempt = a.Value.Int64() + rec.hasAttempt = true + case log.KeyError: + rec.errText = a.Value.String() + case log.KeyHost: + rec.host = a.Value.String() + } + } + for _, a := range h.attrs { + apply(a) + } + r.Attrs(func(a slog.Attr) bool { + apply(a) + return true + }) + + h.mu.Lock() + defer h.mu.Unlock() + *h.records = append(*h.records, rec) + return nil +} + +func (h *capturingHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + next := *h + next.attrs = append(append([]slog.Attr{}, h.attrs...), attrs...) + return &next +} + +func (h *capturingHandler) WithGroup(_ string) slog.Handler { return h } + +func (h *capturingHandler) Records() []retryLogRecord { + h.mu.Lock() + defer h.mu.Unlock() + out := make([]retryLogRecord, len(*h.records)) + copy(out, *h.records) + return out +} + +// retryingRecords filters out the Tracef bookkeeping records emitted by +// Context/Times so tests only see the ones logAttempt produced. +func retryingRecords(recs []retryLogRecord) []retryLogRecord { + var out []retryLogRecord + for _, r := range recs { + if r.message == "retrying" { + out = append(out, r) + } + } + return out +} + +func installCapturingHandler(t *testing.T) *capturingHandler { + t.Helper() + orig := log.Base() + t.Cleanup(func() { log.SetLogger(orig) }) + + h := newCapturingHandler() + log.SetLogger(slog.New(h)) + return h +} + +func TestLogAttemptRoutesThroughContextLogger(t *testing.T) { + h := installCapturingHandler(t) + + scoped := log.With(log.KeyHost, "node-a") + ctx := log.IntoContext(context.Background(), scoped) + + logAttempt(ctx, 1, errors.New("boom")) + logAttempt(ctx, 3, errors.New("boom again")) + + recs := h.Records() + require.Len(t, recs, 2) + + assert.Equal(t, slog.LevelDebug, recs[0].level, "attempt 1 should log at debug") + assert.Equal(t, "retrying", recs[0].message) + assert.True(t, recs[0].hasAttempt) + assert.Equal(t, int64(1), recs[0].attempt) + assert.Equal(t, "node-a", recs[0].host) + assert.Equal(t, "boom", recs[0].errText) + + assert.Equal(t, slog.LevelInfo, recs[1].level, "attempt 3 should log at info") + assert.Equal(t, int64(3), recs[1].attempt) + assert.Equal(t, "boom again", recs[1].errText) +} + +func TestLogAttemptFallsBackToBaseLoggerWithoutContextLogger(t *testing.T) { + h := installCapturingHandler(t) + + logAttempt(context.Background(), 1, errors.New("boom")) + + recs := h.Records() + require.Len(t, recs, 1) + assert.Empty(t, recs[0].host, "no host should be attached without a scoped context logger") +} + +func TestLogAttemptLevelPolicy(t *testing.T) { + orig := log.Base() + t.Cleanup(func() { log.SetLogger(orig) }) + + tests := []struct { + attempt int + want slog.Level + }{ + {1, slog.LevelDebug}, + {2, slog.LevelDebug}, + {3, slog.LevelInfo}, + {4, slog.LevelDebug}, + {8, slog.LevelDebug}, + {9, slog.LevelInfo}, + {10, slog.LevelDebug}, + {15, slog.LevelInfo}, + {16, slog.LevelDebug}, + } + for _, tt := range tests { + t.Run(fmt.Sprintf("attempt=%d", tt.attempt), func(t *testing.T) { + h := newCapturingHandler() + log.SetLogger(slog.New(h)) + + logAttempt(context.Background(), tt.attempt, errors.New("fail")) + + recs := h.Records() + require.Len(t, recs, 1) + assert.Equal(t, tt.want, recs[0].level, "logAttempt(attempt=%d) level", tt.attempt) + }) + } +} + +func TestRetryTimesLogsAttemptsThroughLogAttempt(t *testing.T) { + h := installCapturingHandler(t) + + ctx := t.Context() + err := Times(ctx, 4, func(_ context.Context) error { + return errors.New("still failing") + }) + require.Error(t, err) + + recs := retryingRecords(h.Records()) + require.Len(t, recs, 3, "expected one retrying log per retry tick before the attempt limit was hit") + + wantAttempts := []int64{2, 3, 4} + wantLevels := []slog.Level{slog.LevelDebug, slog.LevelInfo, slog.LevelDebug} + for i, rec := range recs { + assert.Equal(t, wantAttempts[i], rec.attempt, "record %d attempt", i) + assert.Equal(t, wantLevels[i], rec.level, "record %d level", i) + assert.Equal(t, "still failing", rec.errText, "record %d error text", i) + } +} + +func TestRetryContextLogsAttemptsThroughLogAttempt(t *testing.T) { + h := installCapturingHandler(t) + + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + + var calls int + err := Context(ctx, func(_ context.Context) error { + calls++ + if calls == 4 { + cancel() + } + return errors.New("still failing") + }) + require.Error(t, err) + + recs := retryingRecords(h.Records()) + require.Len(t, recs, 3, "expected one retrying log per retry tick before cancellation") + + wantAttempts := []int64{1, 2, 3} + wantLevels := []slog.Level{slog.LevelDebug, slog.LevelDebug, slog.LevelInfo} + for i, rec := range recs { + assert.Equal(t, wantAttempts[i], rec.attempt, "record %d attempt", i) + assert.Equal(t, wantLevels[i], rec.level, "record %d level", i) + assert.Equal(t, "still failing", rec.errText, "record %d error text", i) + } +}