Several fixes

- Set global debug log
 - Set caller in the log if debug
 - Fatal if cannot get target image
 - clean up slices from cos-layoout.env
 - Add generic log with more context info
 - dump runtime to log on start
 - Set proper default paths if overlay is empty (fixes recovery)
 - Fix ErrAlreadyMounted to not trigger failures

Signed-off-by: Itxaka <itxaka@spectrocloud.com>

Earthfile

@@ -76,7 +76,7 @@ build-dracut:
     RUN rm -Rf /usr/lib/dracut/modules.d/30cos-immutable-rootfs/
     RUN rm /etc/dracut.conf.d/02-cos-immutable-rootfs.conf
     RUN kernel=$(ls /lib/modules | head -n1) && \
-        dracut -v -f "/boot/initrd-${kernel}" "${kernel}" && \
+        dracut -f "/boot/initrd-${kernel}" "${kernel}" && \
         ln -sf "initrd-${kernel}" /boot/initrd
     ARG INITRD=$(readlink -f /boot/initrd)
     SAVE ARTIFACT $INITRD Initrd AS LOCAL build/initrd-$VERSION

internal/cmd/commands.go

@@ -30,12 +30,13 @@ Sends a generic event payload with the configuration found in the scanned direct
 			},
 		},
 		Action: func(c *cli.Context) (err error) {
-			logLevel := zerolog.InfoLevel
+			debug := len(utils.ReadCMDLineArg("rd.immucore.debug")) > 0
-			debug := utils.ReadCMDLineArg("rd.immucore.debug")
+			log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).With().Logger()
-			if len(debug) > 0 {
+			zerolog.SetGlobalLevel(zerolog.InfoLevel)
-				logLevel = zerolog.DebugLevel
+			if debug {
+				log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).With().Caller().Logger()
+				zerolog.SetGlobalLevel(zerolog.DebugLevel)
 			}
-			log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).With().Logger().Level(logLevel)
 
 			// If we boot from CD, we do nothing
 			cdBoot, err := utils.BootedFromCD()
@@ -50,6 +51,9 @@ Sends a generic event payload with the configuration found in the scanned direct
 			}
 
 			img := utils.ReadCMDLineArg("cos-img/filename=")
+			if len(img) == 0 {
+				log.Logger.Fatal().Msg("Could not get the image name from cmdline (i.e. cos-img/filename=/cOS/active.img)")
+			}
 			log.Debug().Strs("TargetImage", img).Msg("Target image")
 			g := herd.DAG()
 			s := &mount.State{

internal/utils/common.go

@@ -104,3 +104,17 @@ func CreateIfNotExists(path string) error {
 
 	return nil
 }
+
+// CleanupSlice will clean a slice of strings of empty items
+// Typos can be made on writing the cos-layout.env file and that could introduce empty items
+// In the lists that we need to go over, which causes bad stuff
+func CleanupSlice(slice []string) []string {
+	var cleanSlice []string
+	for _, item := range slice {
+		if strings.Trim(item, " ") == "" {
+			continue
+		}
+		cleanSlice = append(cleanSlice, item)
+	}
+	return cleanSlice
+}

pkg/mount/fs.go

@@ -111,7 +111,6 @@ func mountWithBaseOverlay(mountpoint, root, base string) mountOperation {
 
 	tmpFstab := internalUtils.MountToFstab(tmpMount)
 	tmpFstab.File = internalUtils.CleanSysrootForFstab(rootMount)
-
 	// TODO: update fstab with x-systemd info
 	// https://github.com/kairos-io/packages/blob/94aa3bef3d1330cb6c6905ae164f5004b6a58b8c/packages/system/dracut/immutable-rootfs/30cos-immutable-rootfs/cos-mount-layout.sh#L170
 	return mountOperation{

pkg/mount/mount.go

@@ -106,7 +106,7 @@ func (s *State) RunStageOp(stage string) func(context.Context) error {
 }
 
 func (s *State) MountOP(what, where, t string, options []string, timeout time.Duration) func(context.Context) error {
-	log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).With().Logger()
+	log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).With().Str("what", what).Str("where", where).Str("type", t).Strs("options", options).Logger()
 
 	return func(c context.Context) error {
 		cc := time.After(timeout)
@@ -115,7 +115,7 @@ func (s *State) MountOP(what, where, t string, options []string, timeout time.Du
 			default:
 				err := internalUtils.CreateIfNotExists(where)
 				if err != nil {
-					log.Logger.Debug().Str("what", what).Str("where", where).Str("type", t).Strs("options", options).Err(err).Msg("Creating dir")
+					log.Logger.Err(err).Msg("Creating dir")
 					continue
 				}
 				time.Sleep(1 * time.Second)
@@ -146,11 +146,11 @@ func (s *State) MountOP(what, where, t string, options []string, timeout time.Du
 				return nil
 			case <-c.Done():
 				e := fmt.Errorf("context canceled")
-				log.Logger.Debug().Str("what", what).Str("where", where).Str("type", t).Strs("options", options).Err(e).Msg("mount canceled")
+				log.Logger.Err(e).Msg("mount canceled")
 				return e
 			case <-cc:
 				e := fmt.Errorf("timeout exhausted")
-				log.Logger.Debug().Str("what", what).Str("where", where).Str("type", t).Strs("options", options).Err(e).Msg("Mount timeout")
+				log.Logger.Err(e).Msg("Mount timeout")
 				return e
 			}
 		}
@@ -176,10 +176,12 @@ func (s *State) Register(g *herd.Graph) error {
 
 	runtime, err := state.NewRuntime()
 	if err != nil {
-		s.Logger.Debug().Err(err).Msg("")
+		s.Logger.Debug().Err(err).Msg("runtime")
 		return err
 	}
 
+	s.Logger.Debug().Interface("runtime", runtime).Msg("Current runtime")
+
 	// TODO: add hooks, fstab (might have missed some), systemd compat
 	// TODO: We should also set tmpfs here (not -related)
 
@@ -197,6 +199,7 @@ func (s *State) Register(g *herd.Graph) error {
 						log.Logger.Debug().Str("targetImage", s.TargetImage).Str("path", s.Rootdir).Str("TargetLabel", s.TargetLabel).Msg("Not mounting loop, already mounted")
 						return nil
 					}
+					// TODO: squashfs recovery image?
 					cmd := fmt.Sprintf("losetup --show -f %s", s.path("/run/initramfs/cos-state", s.TargetImage))
 					_, err := utils.SH(cmd)
 					if err != nil {
@@ -283,15 +286,15 @@ func (s *State) Register(g *herd.Graph) error {
 				return err
 			}
 			// populate from env here
-			s.OverlayDirs = strings.Split(env["RW_PATHS"], " ")
+			s.OverlayDirs = internalUtils.CleanupSlice(strings.Split(env["RW_PATHS"], " "))
-			// If empty, then set defaults
+			// Append default RW_Paths if Dirs are empty
 			if len(s.OverlayDirs) == 0 {
 				s.OverlayDirs = constants.DefaultRWPaths()
 			}
 			// Remove any duplicates
 			s.OverlayDirs = internalUtils.UniqueSlice(s.OverlayDirs)
 
-			s.BindMounts = strings.Split(env["PERSISTENT_STATE_PATHS"], " ")
+			s.BindMounts = internalUtils.CleanupSlice(strings.Split(env["PERSISTENT_STATE_PATHS"], " "))
 			// Remove any duplicates
 			s.BindMounts = internalUtils.UniqueSlice(s.BindMounts)
 
@@ -333,13 +336,17 @@ func (s *State) Register(g *herd.Graph) error {
 					if err != nil {
 						return err
 					}
-					s.fstabs = append(s.fstabs, &op.FstabEntry)
 					err2 := op.run()
-					// Don't return error if it's an already mounted error
+					// No error, add fstab
-					log.Logger.Err(err2).Send()
+					if err2 == nil {
+						s.fstabs = append(s.fstabs, &op.FstabEntry)
+						return nil
+					}
+					// Error but its already mounted error, dont add fstab but dont return error
 					if err2 != nil && errors.Is(err2, constants.ErrAlreadyMounted) {
 						return nil
 					}
+
 					return err2
 				},
 			),
@@ -360,6 +367,7 @@ func (s *State) Register(g *herd.Graph) error {
 		herd.WithCallback(
 			func(ctx context.Context) error {
 				var multierr *multierror.Error
+				s.Logger.Debug().Strs("dirs", s.OverlayDirs).Msg("Mounting overlays")
 				for _, p := range s.OverlayDirs {
 					op := mountWithBaseOverlay(p, s.Rootdir, "/run/overlay")
 					err := op.run()
@@ -423,11 +431,9 @@ func (s *State) Register(g *herd.Graph) error {
 		herd.WithCallback(
 			func(ctx context.Context) error {
 				var err *multierror.Error
+				s.Logger.Debug().Strs("mounts", s.BindMounts).Msg("Mounting binds")
+
 				for _, p := range s.BindMounts {
-					// Ignore empty values that can get there by having extra spaces in the cos-layout file
-					if p == "" {
-						continue
-					}
 					op := mountBind(p, s.Rootdir, s.StateDir)
 					err2 := op.run()
 					if err2 == nil {

pkg/mount/operation.go

@@ -18,22 +18,23 @@ type mountOperation struct {
 }
 
 func (m mountOperation) run() error {
-	log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).With().Logger()
+	log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).With().Str("what", m.MountOption.Source).Str("where", m.Target).Str("type", m.MountOption.Type).Strs("options", m.MountOption.Options).Logger()
 	if m.PrepareCallback != nil {
 		if err := m.PrepareCallback(); err != nil {
-			log.Logger.Err(err).Str("what", m.MountOption.Source).Str("where", m.Target).Str("type", m.MountOption.Type).Strs("options", m.MountOption.Options).Msg("executing mount callback")
+			log.Logger.Err(err).Msg("executing mount callback")
 			return err
 		}
 	}
 	//TODO: not only check if mounted but also if the type,options and source are the same?
 	mounted, err := mountinfo.Mounted(m.Target)
 	if err != nil {
-		log.Logger.Err(err).Str("what", m.MountOption.Source).Str("where", m.Target).Str("type", m.MountOption.Type).Strs("options", m.MountOption.Options).Msg("checking mount status")
+		log.Logger.Err(err).Msg("checking mount status")
 		return err
 	}
 	if mounted {
-		log.Logger.Debug().Str("what", m.MountOption.Source).Str("where", m.Target).Str("type", m.MountOption.Type).Strs("options", m.MountOption.Options).Msg("Already mounted")
+		log.Logger.Debug().Msg("Already mounted")
 		return constants.ErrAlreadyMounted
 	}
+	log.Logger.Debug().Msg("Mounted")
 	return mount.All([]mount.Mount{m.MountOption}, m.Target)
 }