Logging for peer migrations

Signed-off-by: Jimmy Moore <[email protected]>

cmd/drafter-peer/main.go

@@ -24,6 +24,7 @@ import (
 	"github.com/loopholelabs/drafter/pkg/runner"
 	"github.com/loopholelabs/drafter/pkg/snapshotter"
 	"github.com/loopholelabs/goroutine-manager/pkg/manager"
+	"github.com/loopholelabs/logging"
 	"github.com/loopholelabs/silo/pkg/storage/migrator"
 )
 
@@ -280,6 +281,9 @@ func main() {
 		writers = []io.Writer{conn}
 	}
 
+	// FIXME: Allow tweak from cmdline
+	ourlog := logging.New(logging.Zerolog, "drafter", os.Stderr)
+
 	p, err := peer.StartPeer[struct{}, ipc.AgentServerRemote[struct{}]](
 		goroutineManager.Context(),
 		context.Background(), // Never give up on rescue operations
@@ -303,6 +307,7 @@ func main() {
 
 		packager.StateName,
 		packager.MemoryName,
+		ourlog,
 	)
 
 	defer func() {

go.mod

@@ -44,6 +44,8 @@ require (
 	github.com/josharian/native v1.1.0 // indirect
 	github.com/klauspost/cpuid/v2 v2.2.9 // indirect
 	github.com/lib/pq v1.10.9 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/mdlayher/genetlink v1.3.2 // indirect
 	github.com/mdlayher/netlink v1.7.2 // indirect
 	github.com/mdlayher/socket v0.5.1 // indirect
@@ -54,6 +56,7 @@ require (
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/redis/go-redis/v9 v9.7.0 // indirect
 	github.com/rs/xid v1.6.0 // indirect
+	github.com/rs/zerolog v1.33.0 // indirect
 	github.com/xdg-go/pbkdf2 v1.0.0 // indirect
 	github.com/xdg-go/scram v1.1.2 // indirect
 	github.com/xdg-go/stringprep v1.0.4 // indirect

go.sum

@@ -114,6 +114,8 @@ github.com/magiconair/properties v1.8.7 h1:IeQXZAiQcpL9mgcAe1Nu6cX9LLw6ExEHKjN0V
 github.com/magiconair/properties v1.8.7/go.mod h1:Dhd985XPs7jluiymwWYZ0G4Z61jb3vdS329zhj2hYo0=
 github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
 github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY=
 github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-sqlite3 v1.14.22 h1:2gZY6PC6kBnID23Tichd1K+Z0oS6nE/XwU+Vz/5o4kU=
@@ -168,6 +170,7 @@ github.com/power-devops/perfstat v0.0.0-20240221224432-82ca36839d55 h1:o4JXh1EVt
 github.com/power-devops/perfstat v0.0.0-20240221224432-82ca36839d55/go.mod h1:OmDBASR4679mdNQnz2pUhc2G8CO2JrUAVFDRBDP/hJE=
 github.com/redis/go-redis/v9 v9.7.0 h1:HhLSs+B6O021gwzl+locl0zEDnyNkxMtf/Z3NNBMa9E=
 github.com/redis/go-redis/v9 v9.7.0/go.mod h1:f6zhXITC7JUJIlPEiBOTXxJgPLdZcA93GewI7inzyWw=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
 github.com/rs/xid v1.6.0 h1:fV591PaemRlL6JfRxGDEPl69wICngIQ3shQtzfy2gxU=
 github.com/rs/xid v1.6.0/go.mod h1:7XoLgs4eV+QndskICGsho+ADou8ySMSjJKDIan90Nz0=
 github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8=
@@ -270,8 +273,11 @@ golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/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.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.2.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.10.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.29.0 h1:TPYlXGxvx1MGTn2GiZDhnjPA9wZzZeGKHHmKhHYvgaU=
 golang.org/x/sys v0.29.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=

pkg/common/migrations.go

@@ -189,8 +189,13 @@ func MigrateFromFS(log types.Logger, met metrics.SiloMetrics, vmpath string,
 		}
 	}
 
+	var slog types.Logger
+	if log != nil {
+		slog = log.SubLogger("silo")
+	}
+
 	// Create a silo deviceGroup from all the schemas
-	dg, err := devicegroup.NewFromSchema(siloDeviceSchemas, log, met)
+	dg, err := devicegroup.NewFromSchema(siloDeviceSchemas, slog, met)
 	if err != nil {
 		return nil, err
 	}
@@ -241,7 +246,13 @@ func MigrateFromPipe(log types.Logger, met metrics.SiloMetrics, vmpath string,
 		}
 		close(ready)
 	}
-	dg, err := devicegroup.NewFromProtocol(ctx, pro, schemaTweak, events, icdh, log, met)
+
+	var slog types.Logger
+	if log != nil {
+		slog = log.SubLogger("silo")
+	}
+
+	dg, err := devicegroup.NewFromProtocol(ctx, pro, schemaTweak, events, icdh, slog, met)
 	if err != nil {
 		return nil, err
 	}

pkg/peer/migrated_peer.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
-	"fmt"
 	"os"
 	"path"
 	"sync"
@@ -15,13 +14,14 @@ import (
 	"github.com/loopholelabs/drafter/pkg/packager"
 	"github.com/loopholelabs/drafter/pkg/runner"
 	"github.com/loopholelabs/drafter/pkg/snapshotter"
+	"github.com/loopholelabs/logging/types"
 	"github.com/loopholelabs/silo/pkg/storage/devicegroup"
 )
 
 type MigratedPeer[L ipc.AgentServerLocal, R ipc.AgentServerRemote[G], G any] struct {
 	cancelCtx context.CancelFunc
 
-	//Wait func() error
+	log types.Logger
 
 	dgLock     sync.Mutex
 	dg         *devicegroup.DeviceGroup
@@ -35,8 +35,13 @@ type MigratedPeer[L ipc.AgentServerLocal, R ipc.AgentServerRemote[G], G any] str
 }
 
 func (migratedPeer *MigratedPeer[L, R, G]) Close() error {
+	if migratedPeer.log != nil {
+		migratedPeer.log.Debug().Msg("migratedPeer.Close")
+	}
 	if migratedPeer.alreadyClosed {
-		fmt.Printf("FIXME: MigratedPeer.Close called multiple times\n")
+		if migratedPeer.log != nil {
+			migratedPeer.log.Trace().Msg("FIXME: MigratedPeer.Close called multiple times")
+		}
 		return nil
 	}
 	migratedPeer.alreadyClosed = true
@@ -52,8 +57,13 @@ func (migratedPeer *MigratedPeer[L, R, G]) Close() error {
 }
 
 func (migratedPeer *MigratedPeer[L, R, G]) Wait() error {
+	if migratedPeer.log != nil {
+		migratedPeer.log.Debug().Msg("migratedPeer.Wait")
+	}
 	if migratedPeer.alreadyWaited {
-		fmt.Printf("FIXME: MigratedPeer.Wait called multiple times\n")
+		if migratedPeer.log != nil {
+			migratedPeer.log.Trace().Msg("FIXME: MigratedPeer.Wait called multiple times")
+		}
 		return nil
 	}
 	migratedPeer.alreadyWaited = true
@@ -68,7 +78,14 @@ func (migratedPeer *MigratedPeer[L, R, G]) Wait() error {
 	if migratedPeer.dgIncoming && migratedPeer.dg != nil {
 		migratedPeer.dgIncoming = false
 		migratedPeer.dgLock.Unlock()
-		return migratedPeer.dg.WaitForCompletion()
+		if migratedPeer.log != nil {
+			migratedPeer.log.Trace().Msg("waiting for device migrations to complete")
+		}
+		err := migratedPeer.dg.WaitForCompletion()
+		if migratedPeer.log != nil {
+			migratedPeer.log.Trace().Err(err).Msg("device migrations completed")
+		}
+		return err
 	}
 	migratedPeer.dgLock.Unlock()
 
@@ -103,9 +120,14 @@ func (migratedPeer *MigratedPeer[L, R, G]) Resume(
 	agentServerHooks ipc.AgentServerAcceptHooks[R, G],
 
 	snapshotLoadConfiguration runner.SnapshotLoadConfiguration,
-) (resumedPeer *ResumedPeer[L, R, G], errs error) {
-	resumedPeer = &ResumedPeer[L, R, G]{
-		dg: migratedPeer.dg,
+) (*ResumedPeer[L, R, G], error) {
+	resumedPeer := &ResumedPeer[L, R, G]{
+		dg:  migratedPeer.dg,
+		log: migratedPeer.log,
+	}
+
+	if migratedPeer.log != nil {
+		migratedPeer.log.Trace().Msg("resuming vm")
 	}
 
 	// Read from the config device
@@ -124,6 +146,10 @@ func (migratedPeer *MigratedPeer[L, R, G]) Resume(
 	}
 	configFileData = configFileData[:firstZero]
 
+	if migratedPeer.log != nil {
+		migratedPeer.log.Trace().Str("config", string(configFileData)).Msg("resuming config")
+	}
+
 	var packageConfig snapshotter.PackageConfiguration
 	if err := json.Unmarshal(configFileData, &packageConfig); err != nil {
 		return nil, errors.Join(ErrCouldNotDecodeConfigFile, err)
@@ -142,9 +168,16 @@ func (migratedPeer *MigratedPeer[L, R, G]) Resume(
 		snapshotLoadConfiguration,
 	)
 	if err != nil {
+		if migratedPeer.log != nil {
+			migratedPeer.log.Warn().Err(err).Msg("could not resume runner")
+		}
 		return nil, errors.Join(ErrCouldNotResumeRunner, err)
 	}
 	resumedPeer.Remote = resumedPeer.resumedRunner.Remote
 
+	if migratedPeer.log != nil {
+		migratedPeer.log.Info().Msg("resumed vm")
+	}
+
 	return resumedPeer, nil
 }