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 <andrey.smirnov@siderolabs.com>
siderolabs · Nov 7, 2023 · 87c40da · 87c40da
1 parent a54da5f
commit 87c40da
Show file tree

Hide file tree

Showing 3 changed files with 72 additions and 82 deletions.
diff --git 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
@@ -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
@@ -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,15 +63,13 @@ 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"
 	"github.com/siderolabs/talos/pkg/machinery/config/config"
 	"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.