From 87c40da6cc5d9ae62d20984ba5d3762da734a49e Mon Sep 17 00:00:00 2001 From: Andrey Smirnov Date: Tue, 7 Nov 2023 16:33:18 +0400 Subject: [PATCH] fix: proper logging in machined on startup Move `setupLogging` inside the controller, so that logger is set up correctly before Talos starts printing first messages. This fixes an inconsistency that first messages are printed using "default" logger, while after that the proper logger is set up, and format of the messages matches kernel log. Also move `waitForUSBDelay` into the sequencer after `udevd` was started (this is when blockdevices including USB ones are discovered). Signed-off-by: Andrey Smirnov --- .../runtime/v1alpha1/v1alpha1_controller.go | 91 +++++++++---------- .../runtime/v1alpha1/v1alpha1_sequencer.go | 9 +- .../v1alpha1/v1alpha1_sequencer_tasks.go | 54 +++++------ 3 files changed, 72 insertions(+), 82 deletions(-) diff --git a/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_controller.go b/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_controller.go index 7f61b99474..f021647310 100644 --- a/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_controller.go +++ b/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_controller.go @@ -8,22 +8,24 @@ import ( "context" "errors" "fmt" + "io" "log" "os" "os/signal" - "strconv" - "strings" "syscall" "time" + "github.com/siderolabs/go-kmsg" "golang.org/x/sync/errgroup" "github.com/siderolabs/talos/internal/app/machined/pkg/runtime" "github.com/siderolabs/talos/internal/app/machined/pkg/runtime/logging" "github.com/siderolabs/talos/internal/app/machined/pkg/runtime/v1alpha1/acpi" "github.com/siderolabs/talos/internal/app/machined/pkg/runtime/v1alpha2" + krnl "github.com/siderolabs/talos/pkg/kernel" "github.com/siderolabs/talos/pkg/machinery/api/common" "github.com/siderolabs/talos/pkg/machinery/api/machine" + "github.com/siderolabs/talos/pkg/machinery/kernel" ) // Controller represents the controller responsible for managing the execution @@ -38,14 +40,6 @@ type Controller struct { // NewController intializes and returns a controller. func NewController() (*Controller, error) { - // Wait for USB storage in the case that the install disk is supplied over - // USB. If we don't wait, there is the chance that we will fail to detect the - // install disk. - err := waitForUSBDelay() - if err != nil { - return nil, err - } - s, err := NewState() if err != nil { return nil, err @@ -67,9 +61,47 @@ func NewController() (*Controller, error) { return nil, err } + if err := ctlr.setupLogging(); err != nil { + return nil, err + } + return ctlr, nil } +func (c *Controller) setupLogging() error { + machinedLog, err := c.r.Logging().ServiceLog("machined").Writer() + if err != nil { + return err + } + + if c.r.State().Platform().Mode() == runtime.ModeContainer { + // send all the logs to machinedLog as well, but skip /dev/kmsg logging + log.SetOutput(io.MultiWriter(log.Writer(), machinedLog)) + log.SetPrefix("[talos] ") + + return nil + } + + // disable ratelimiting for kmsg, otherwise logs might be not visible. + // this should be set via kernel arg, but in case it's not set, try to force it. + if err = krnl.WriteParam(&kernel.Param{ + Key: "proc.sys.kernel.printk_devkmsg", + Value: "on\n", + }); err != nil { + var serr syscall.Errno + + if !(errors.As(err, &serr) && serr == syscall.EINVAL) { // ignore EINVAL which is returned when kernel arg is set + log.Printf("failed setting kernel.printk_devkmsg: %s, error ignored", err) + } + } + + if err = kmsg.SetupLogger(nil, "[talos]", machinedLog); err != nil { + return fmt.Errorf("failed to setup logging: %w", err) + } + + return nil +} + // Run executes all phases known to the controller in serial. `Controller` // aborts immediately if any phase fails. func (c *Controller) Run(ctx context.Context, seq runtime.Sequence, data interface{}, setters ...runtime.LockOption) error { @@ -385,42 +417,3 @@ func (c *Controller) phases(seq runtime.Sequence, data interface{}) ([]runtime.P return phases, nil } - -func waitForUSBDelay() (err error) { - wait := true - - file := "/sys/module/usb_storage/parameters/delay_use" - - _, err = os.Stat(file) - if err != nil { - if os.IsNotExist(err) { - wait = false - } else { - return err - } - } - - if wait { - var b []byte - - b, err = os.ReadFile(file) - if err != nil { - return err - } - - val := strings.TrimSuffix(string(b), "\n") - - var i int - - i, err = strconv.Atoi(val) - if err != nil { - return err - } - - log.Printf("waiting %d second(s) for USB storage", i) - - time.Sleep(time.Duration(i) * time.Second) - } - - return nil -} diff --git a/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer.go b/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer.go index 87a85c086c..545ee4abe5 100644 --- a/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer.go +++ b/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer.go @@ -70,9 +70,6 @@ func (*Sequencer) Initialize(r runtime.Runtime) []runtime.Phase { switch r.State().Platform().Mode() { //nolint:exhaustive case runtime.ModeContainer: phases = phases.Append( - "logger", - SetupLogger, - ).Append( "systemRequirements", SetupSystemDirectory, ).Append( @@ -89,9 +86,6 @@ func (*Sequencer) Initialize(r runtime.Runtime) []runtime.Phase { ) default: phases = phases.Append( - "logger", - SetupLogger, - ).Append( "systemRequirements", EnforceKSPPRequirements, SetupSystemDirectory, @@ -111,6 +105,9 @@ func (*Sequencer) Initialize(r runtime.Runtime) []runtime.Phase { "earlyServices", StartUdevd, StartMachined, + ).Append( + "usb", + WaitForUSB, ).Append( "meta", ReloadMeta, diff --git a/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer_tasks.go b/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer_tasks.go index a233f45fe4..70c45a5c05 100644 --- a/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer_tasks.go +++ b/internal/app/machined/pkg/runtime/v1alpha1/v1alpha1_sequencer_tasks.go @@ -16,6 +16,7 @@ import ( "os" "path/filepath" "slices" + "strconv" "strings" "syscall" "time" @@ -35,7 +36,6 @@ import ( "github.com/siderolabs/go-blockdevice/blockdevice/util" "github.com/siderolabs/go-cmd/pkg/cmd" "github.com/siderolabs/go-cmd/pkg/cmd/proc" - "github.com/siderolabs/go-kmsg" "github.com/siderolabs/go-pointer" "github.com/siderolabs/go-procfs/procfs" "github.com/siderolabs/go-retry/retry" @@ -63,7 +63,6 @@ import ( "github.com/siderolabs/talos/internal/pkg/secureboot/tpm2" "github.com/siderolabs/talos/pkg/conditions" "github.com/siderolabs/talos/pkg/images" - krnl "github.com/siderolabs/talos/pkg/kernel" "github.com/siderolabs/talos/pkg/kernel/kspp" "github.com/siderolabs/talos/pkg/kubernetes" machineapi "github.com/siderolabs/talos/pkg/machinery/api/machine" @@ -71,7 +70,6 @@ import ( "github.com/siderolabs/talos/pkg/machinery/config/machine" "github.com/siderolabs/talos/pkg/machinery/config/types/v1alpha1" "github.com/siderolabs/talos/pkg/machinery/constants" - "github.com/siderolabs/talos/pkg/machinery/kernel" metamachinery "github.com/siderolabs/talos/pkg/machinery/meta" resourcefiles "github.com/siderolabs/talos/pkg/machinery/resources/files" "github.com/siderolabs/talos/pkg/machinery/resources/k8s" @@ -81,41 +79,43 @@ import ( "github.com/siderolabs/talos/pkg/version" ) -// SetupLogger represents the SetupLogger task. -func SetupLogger(runtime.Sequence, any) (runtime.TaskExecutionFunc, string) { - return func(ctx context.Context, logger *log.Logger, r runtime.Runtime) (err error) { - machinedLog, err := r.Logging().ServiceLog("machined").Writer() +// WaitForUSB represents the WaitForUSB task. +func WaitForUSB(runtime.Sequence, any) (runtime.TaskExecutionFunc, string) { + return func(ctx context.Context, logger *log.Logger, r runtime.Runtime) error { + // Wait for USB storage in the case that the install disk is supplied over + // USB. If we don't wait, there is the chance that we will fail to detect the + // install disk. + file := "/sys/module/usb_storage/parameters/delay_use" + + _, err := os.Stat(file) if err != nil { + if os.IsNotExist(err) { + return nil + } + return err } - if r.State().Platform().Mode() == runtime.ModeContainer { - // send all the logs to machinedLog as well, but skip /dev/kmsg logging - log.SetOutput(io.MultiWriter(log.Writer(), machinedLog)) - log.SetPrefix("[talos] ") - - return nil + b, err := os.ReadFile(file) + if err != nil { + return err } - // disable ratelimiting for kmsg, otherwise logs might be not visible. - // this should be set via kernel arg, but in case it's not set, try to force it. - if err = krnl.WriteParam(&kernel.Param{ - Key: "proc.sys.kernel.printk_devkmsg", - Value: "on\n", - }); err != nil { - var serr syscall.Errno + val := strings.TrimSuffix(string(b), "\n") - if !(errors.As(err, &serr) && serr == syscall.EINVAL) { // ignore EINVAL which is returned when kernel arg is set - log.Printf("failed setting kernel.printk_devkmsg: %s, error ignored", err) - } - } + var i int - if err = kmsg.SetupLogger(nil, "[talos]", machinedLog); err != nil { - return fmt.Errorf("failed to setup logging: %w", err) + i, err = strconv.Atoi(val) + if err != nil { + return err } + logger.Printf("waiting %d second(s) for USB storage", i) + + time.Sleep(time.Duration(i) * time.Second) + return nil - }, "setupLogger" + }, "waitForUSB" } // EnforceKSPPRequirements represents the EnforceKSPPRequirements task.