Fix spegel logging and startup sequence

Signed-off-by: Brad Davidson <brad.davidson@rancher.com>

go.mod

@@ -95,7 +95,6 @@ require (
 	github.com/flannel-io/flannel v0.27.0
 	github.com/fsnotify/fsnotify v1.7.0
 	github.com/go-logr/logr v1.4.2
-	github.com/go-logr/stdr v1.2.3-0.20220714215716-96bad1d688c5
 	github.com/go-test/deep v1.0.7
 	github.com/google/cadvisor v0.52.1
 	github.com/google/go-containerregistry v0.20.2
@@ -264,6 +263,7 @@ require (
 	github.com/go-errors/errors v1.4.2 // indirect
 	github.com/go-ini/ini v1.67.0 // indirect
 	github.com/go-jose/go-jose/v4 v4.0.5 // indirect
+	github.com/go-logr/stdr v1.2.3-0.20220714215716-96bad1d688c5 // indirect
 	github.com/go-openapi/jsonpointer v0.21.1 // indirect
 	github.com/go-openapi/jsonreference v0.21.0 // indirect
 	github.com/go-openapi/swag v0.23.1 // indirect

pkg/agent/run.go

@@ -106,12 +106,16 @@ func run(ctx context.Context, cfg cmds.Agent, proxy proxy.Proxy) error {
 	nodeConfig.AgentConfig.EnableIPv4 = enableIPv4
 	nodeConfig.AgentConfig.EnableIPv6 = enableIPv6
 
+	if err := executor.Bootstrap(ctx, nodeConfig, cfg); err != nil {
+		return err
+	}
+
 	if nodeConfig.EmbeddedRegistry {
 		if nodeConfig.Docker || nodeConfig.ContainerRuntimeEndpoint != "" {
 			return errors.New("embedded registry mirror requires embedded containerd")
 		}
 
-		if err := spegel.DefaultRegistry.Start(ctx, nodeConfig); err != nil {
+		if err := spegel.DefaultRegistry.Start(ctx, nodeConfig, executor.CRIReadyChan()); err != nil {
 			return pkgerrors.WithMessage(err, "failed to start embedded registry")
 		}
 	}
@@ -132,10 +136,6 @@ func run(ctx context.Context, cfg cmds.Agent, proxy proxy.Proxy) error {
 		return err
 	}
 
-	if err := executor.Bootstrap(ctx, nodeConfig, cfg); err != nil {
-		return err
-	}
-
 	if !nodeConfig.NoFlannel {
 		if (nodeConfig.FlannelExternalIP) && (len(nodeConfig.AgentConfig.NodeExternalIPs) == 0) {
 			logrus.Warnf("Server has flannel-external-ip flag set but this node does not set node-external-ip. Flannel will use internal address when connecting to this node.")

pkg/spegel/spegel.go

@@ -5,7 +5,6 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
-	"log"
 	"net"
 	"net/http"
 	"net/url"
@@ -19,13 +18,12 @@ import (
 	"github.com/k3s-io/k3s/pkg/clientaccess"
 	"github.com/k3s-io/k3s/pkg/daemons/config"
 	"github.com/k3s-io/k3s/pkg/server/auth"
+	"github.com/k3s-io/k3s/pkg/util/logger"
 	"github.com/k3s-io/k3s/pkg/version"
 	"github.com/rancher/dynamiclistener/cert"
 	"k8s.io/apimachinery/pkg/util/wait"
-	"k8s.io/utils/ptr"
 
 	"github.com/go-logr/logr"
-	"github.com/go-logr/stdr"
 	"github.com/gorilla/mux"
 	leveldb "github.com/ipfs/go-ds-leveldb"
 	ipfslog "github.com/ipfs/go-log/v2"
@@ -108,7 +106,7 @@ func init() {
 }
 
 // Start starts the embedded p2p router, and binds the registry API to an existing HTTP router.
-func (c *Config) Start(ctx context.Context, nodeConfig *config.Node) error {
+func (c *Config) Start(ctx context.Context, nodeConfig *config.Node, criReadyChan <-chan struct{}) error {
 	localAddr := net.JoinHostPort(c.InternalAddress, c.RegistryPort)
 	// distribute images for all configured mirrors. there doesn't need to be a
 	// configured endpoint, just having a key for the registry will do.
@@ -135,12 +133,10 @@ func (c *Config) Start(ctx context.Context, nodeConfig *config.Node) error {
 		c.ExternalAddress, c.RegistryPort, registries)
 
 	// set up the various logging logging frameworks
+	ctx = logr.NewContext(ctx, logger.NewLogrusSink(nil).AsLogr().WithName("spegel"))
 	level := ipfslog.LevelInfo
 	if logrus.IsLevelEnabled(logrus.DebugLevel) {
 		level = ipfslog.LevelDebug
-		stdlog := log.New(logrus.StandardLogger().Writer(), "spegel ", log.LstdFlags)
-		logger := stdr.NewWithOptions(stdlog, stdr.Options{Verbosity: ptr.To(7)})
-		ctx = logr.NewContext(ctx, logger)
 	}
 	ipfslog.SetAllLoggers(level)
 
@@ -232,7 +228,10 @@ func (c *Config) Start(ctx context.Context, nodeConfig *config.Node) error {
 	}
 
 	// Track images available in containerd and publish via p2p router
-	go state.Track(ctx, ociClient, router, resolveLatestTag)
+	go func() {
+		<-criReadyChan
+		state.Track(ctx, ociClient, router, resolveLatestTag)
+	}()
 
 	mRouter, err := c.Router(ctx, nodeConfig)
 	if err != nil {

pkg/util/logger/logger.go

@@ -0,0 +1,86 @@
+package logger
+
+import (
+	"fmt"
+
+	"github.com/go-logr/logr"
+	"github.com/sirupsen/logrus"
+)
+
+// implicit interface check
+var _ logr.LogSink = &logrusSink{}
+
+// mapLevel maps logr log verbosities to logrus log levels
+// logr does not have "log levels", but Info prints at verbosity 0
+// while logrus's LevelInfo is unit32(4). This means:
+// * panic/fatal/warn are unused,
+// * 0 is info
+// * 1 is debug
+// * >=2 are trace
+func mapLevel(level int) logrus.Level {
+	if level >= 2 {
+		return logrus.TraceLevel
+	}
+	return logrus.Level(level + 4)
+}
+
+// mapKV maps a list of keys and values to logrus Fields
+func mapKV(kvs []any) logrus.Fields {
+	fields := logrus.Fields{}
+	for i := 0; i < len(kvs); i += 2 {
+		k := kvs[i].(string)
+		if len(kvs) > i+1 {
+			fields[k] = kvs[i+1]
+		} else {
+			fields[k] = ""
+		}
+	}
+	return fields
+}
+
+// LogrusSink wraps logrus the Logger/Entry types for use as a logr LogSink.
+type logrusSink struct {
+	e  *logrus.Entry
+	ri logr.RuntimeInfo
+}
+
+func NewLogrusSink(l *logrus.Logger) *logrusSink {
+	if l == nil {
+		l = logrus.StandardLogger()
+	}
+	return &logrusSink{e: logrus.NewEntry(l)}
+}
+
+func (ls *logrusSink) AsLogr() logr.Logger {
+	return logr.New(ls)
+}
+
+func (ls *logrusSink) Init(ri logr.RuntimeInfo) {
+	ls.ri = ri
+}
+
+func (ls *logrusSink) Enabled(level int) bool {
+	return ls.e.Logger.IsLevelEnabled(mapLevel(level))
+}
+
+func (ls *logrusSink) Info(level int, msg string, kvs ...any) {
+	ls.e.WithFields(mapKV(kvs)).Log(mapLevel(level), msg)
+}
+
+func (ls *logrusSink) Error(err error, msg string, kvs ...any) {
+	ls.e.WithError(err).WithFields(mapKV(kvs)).Error(msg)
+}
+
+func (ls *logrusSink) WithValues(kvs ...any) logr.LogSink {
+	return &logrusSink{
+		e:  ls.e.WithFields(mapKV(kvs)),
+		ri: ls.ri,
+	}
+}
+
+func (ls *logrusSink) WithName(name string) logr.LogSink {
+	if base, ok := ls.e.Data["logger"]; ok {
+		name = fmt.Sprintf("%s/%s", base, name)
+	}
+	return ls.WithValues("logger", name)
+}