Sharing logs via slog

go.mod

@@ -7,6 +7,7 @@ toolchain go1.21.0
 require (
 	github.com/Netflix/go-expect v0.0.0-20220104043353-73e0943537d2
 	github.com/creack/pty v1.1.21
+	github.com/samber/slog-multi v1.0.2
 	github.com/u-root/gobusybox/src v0.0.0-20231228173702-b69f654846aa
 	github.com/u-root/u-root v0.12.1-0.20240114161452-ab3534910ced
 	github.com/u-root/uio v0.0.0-20230305220412-3e8cd9d6bf63
@@ -29,6 +30,7 @@ require (
 	github.com/mdlayher/packet v1.1.2 // indirect
 	github.com/mdlayher/socket v0.5.0 // indirect
 	github.com/pierrec/lz4/v4 v4.1.14 // indirect
+	github.com/samber/lo v1.38.1 // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
 	github.com/stretchr/testify v1.7.1 // indirect
 	github.com/ulikunitz/xz v0.5.11 // indirect

go.sum

@@ -42,6 +42,10 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/rekby/gpt v0.0.0-20200219180433-a930afbc6edc h1:goZGTwEEn8mWLcY012VouWZWkJ8GrXm9tS3VORMxT90=
 github.com/rekby/gpt v0.0.0-20200219180433-a930afbc6edc/go.mod h1:scrOqOnnHVKCHENvFw8k9ajCb88uqLQDA4BvuJNJ2ew=
+github.com/samber/lo v1.38.1 h1:j2XEAqXKb09Am4ebOg31SpvzUTTs6EN3VfgeLUhPdXM=
+github.com/samber/lo v1.38.1/go.mod h1:+m/ZKRl6ClXCE2Lgf3MsQlWfh4bn1bz6CXEOxnEXnEA=
+github.com/samber/slog-multi v1.0.2 h1:6BVH9uHGAsiGkbbtQgAOQJMpKgV8unMrHhhJaw+X1EQ=
+github.com/samber/slog-multi v1.0.2/go.mod h1:uLAvHpGqbYgX4FSL0p1ZwoLuveIAJvBECtE07XmYvFo=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
 github.com/stretchr/objx v0.1.0 h1:4G4v2dO3VZwixGIRoQ5Lfboy6nUhCyYzaqnIAPPhYs4=

gotest.go

@@ -14,8 +14,8 @@ import (
 	"time"
 
 	"github.com/hugelgupf/vmtest/internal/json2test"
-	"github.com/hugelgupf/vmtest/internal/testevent"
 	"github.com/hugelgupf/vmtest/qemu"
+	"github.com/hugelgupf/vmtest/qemu/qslog"
 	"github.com/hugelgupf/vmtest/testtmp"
 	"github.com/u-root/gobusybox/src/pkg/golang"
 	"github.com/u-root/u-root/pkg/uroot"
@@ -224,12 +224,12 @@ func RunGoTestsInVM(t testing.TB, pkgs []string, opts ...GoTestOpt) {
 		}
 	}
 
-	errors, err := qemu.ReadEventFile[testevent.ErrorEvent](filepath.Join(sharedDir, "errors.json"))
+	errors, err := qslog.ReadEventFile(filepath.Join(sharedDir, "errors.json"))
 	if err != nil {
 		t.Errorf("Reading test events: %v", err)
 	}
-	for _, e := range errors {
-		t.Errorf("Binary %s experienced error: %s", e.Binary, e.Error)
+	for _, r := range errors {
+		t.Errorf("Test failed: %s", r)
 	}
 
 	tc := json2test.NewTestCollector()

qemu/qslog/slog.go

@@ -0,0 +1,91 @@
+// Package qslog implements an event channel for slog JSON data.
+package qslog
+
+import (
+	"fmt"
+	"log/slog"
+	"strings"
+	"time"
+
+	"github.com/hugelgupf/vmtest/qemu"
+)
+
+// Record is an slog record as transmitted via the JSON handler.
+type Record struct {
+	Time  time.Time
+	Msg   string
+	Level slog.Level
+	Attrs map[string]any
+}
+
+// String formats a record just like slog's default handler would (or as close
+// as possible).
+func (s Record) String() string {
+	var b strings.Builder
+	b.WriteString(s.Time.Format(time.RFC3339))
+	b.WriteString(" ")
+	b.WriteString(s.Level.String())
+	b.WriteString(" ")
+	b.WriteString(s.Msg)
+	b.WriteString(" ")
+	writeAttrs(&b, "", s.Attrs)
+	return b.String()
+}
+
+func writeAttrs(b *strings.Builder, prefix string, attrs map[string]any) {
+	for key, value := range attrs {
+		switch v := value.(type) {
+		case map[string]interface{}:
+			var np string
+			if prefix == "" {
+				np = key
+			} else {
+				np = prefix + "." + key
+			}
+			writeAttrs(b, np, v)
+
+		default:
+			if prefix != "" {
+				b.WriteString(prefix)
+				b.WriteString(".")
+			}
+			b.WriteString(key)
+			b.WriteString("=")
+			b.WriteString(fmt.Sprintf("%v", v))
+			b.WriteString(" ")
+		}
+	}
+}
+
+// RecordFrom converts an arbitrary JSON-decoded slog record.
+func RecordFrom(r map[string]any) Record {
+	var nr Record
+	if st, ok := r["time"].(string); ok {
+		t, _ := time.Parse(time.RFC3339Nano, st)
+		nr.Time = t
+		delete(r, "time")
+	}
+	if msg, ok := r["msg"].(string); ok {
+		nr.Msg = msg
+		delete(r, "msg")
+	}
+	if level, ok := r["level"].(string); ok {
+		_ = nr.Level.UnmarshalText([]byte(level))
+		delete(r, "level")
+	}
+	nr.Attrs = r
+	return nr
+}
+
+// ReadEventFile reads a vmtest event channel file full of slog records.
+func ReadEventFile(path string) ([]Record, error) {
+	errors, err := qemu.ReadEventFile[map[string]any](path)
+	if err != nil {
+		return nil, err
+	}
+	var records []Record
+	for _, r := range errors {
+		records = append(records, RecordFrom(r))
+	}
+	return records, nil
+}

vminit/gouinit/main_linux.go

@@ -11,6 +11,7 @@ import (
 	"fmt"
 	"io"
 	"log"
+	"log/slog"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -19,7 +20,7 @@ import (
 
 	"github.com/hugelgupf/vmtest/guest"
 	"github.com/hugelgupf/vmtest/internal/json2test"
-	"github.com/hugelgupf/vmtest/internal/testevent"
+	slogmulti "github.com/samber/slog-multi"
 	"golang.org/x/sys/unix"
 )
 
@@ -72,33 +73,39 @@ func AppendFile(srcFile, targetFile string) error {
 }
 
 // runTest mounts a vfat or 9pfs volume and runs the tests within.
-func runTest() error {
+func runTest() {
 	flag.Parse()
 
 	// If these fail, the host will be missing the "Done" event from
 	// testEvents, or possibly even the errors.json file and fail.
 	mp, err := guest.Mount9PDir("/gotestdata", "gotests")
 	if err != nil {
-		return err
+		log.Printf("Could not mount gotests data: %v", err)
+		return
 	}
 	defer func() { _ = mp.Unmount(0) }()
 
-	testEvents, err := guest.EventChannel[testevent.ErrorEvent]("/gotestdata/errors.json")
+	testEvents, err := guest.EventChannel[any]("/gotestdata/errors.json")
 	if err != nil {
-		return err
+		log.Printf("Could not open event channel: %v", err)
+		return
 	}
-	defer testEvents.Close()
-
-	if err := run(testEvents); err != nil {
-		_ = testEvents.Emit(testevent.ErrorEvent{
-			Error: fmt.Sprintf("running tests failed: %v", err),
-		})
-		return err
+	defer func() {
+		if err := testEvents.Close(); err != nil {
+			log.Printf("Event channel closing failed: %v", err)
+		}
+	}()
+
+	logger := slog.New(slogmulti.Fanout(
+		slog.Default().Handler(),
+		slog.NewJSONHandler(testEvents, nil),
+	))
+	if err := run(logger); err != nil {
+		logger.Error("running tests failed", "err", err)
 	}
-	return nil
 }
 
-func run(testEvents *guest.Emitter[testevent.ErrorEvent]) error {
+func run(logger *slog.Logger) error {
 	cleanup, err := guest.MountSharedDir()
 	if err != nil {
 		return err
@@ -128,9 +135,11 @@ func run(testEvents *guest.Emitter[testevent.ErrorEvent]) error {
 		ctx, cancel := context.WithTimeout(context.Background(), *individualTestTimeout+500*time.Millisecond)
 		defer cancel()
 
+		plog := logger.With("binary", path)
+
 		r, w, err := os.Pipe()
 		if err != nil {
-			log.Printf("Failed to get pipe: %v", err)
+			plog.Error("failed to get pipe", "err", err)
 			return
 		}
 
@@ -154,11 +163,7 @@ func run(testEvents *guest.Emitter[testevent.ErrorEvent]) error {
 		// relative directory.
 		cmd.Dir = filepath.Dir(path)
 		if err := cmd.Start(); err != nil {
-			_ = testEvents.Emit(testevent.ErrorEvent{
-				Binary: path,
-				Error:  fmt.Sprintf("failed to start: %v", err),
-			})
-			log.Printf("Failed to start %q: %v", path, err)
+			plog.Error("failed to start", "err", err)
 			return
 		}
 
@@ -169,41 +174,25 @@ func run(testEvents *guest.Emitter[testevent.ErrorEvent]) error {
 		j.Stdin = r
 		j.Stdout, cmd.Stderr = goTestEvents, os.Stderr
 		if err := j.Start(); err != nil {
-			_ = testEvents.Emit(testevent.ErrorEvent{
-				Binary: path,
-				Error:  fmt.Sprintf("failed to start test2json: %v", err),
-			})
-			log.Printf("Failed to start test2json: %v", err)
+			plog.Error("failed to start test2json", "err", err)
 			return
 		}
 
 		if err := cmd.Wait(); err != nil {
-			_ = testEvents.Emit(testevent.ErrorEvent{
-				Binary: path,
-				Error:  fmt.Sprintf("test exited with non-zero status: %v", err),
-			})
-			log.Printf("Error: test %q exited with non-zero status: %v", pkgName, err)
+			plog.Error("test exited with non-zero status", "err", err)
 		}
 
 		// Close the pipe so test2json will quit.
 		if err := w.Close(); err != nil {
-			log.Printf("Failed to close pipe: %v", err)
+			plog.Error("failed to close pipe", "err", err)
 		}
 		if err := j.Wait(); err != nil {
-			_ = testEvents.Emit(testevent.ErrorEvent{
-				Binary: path,
-				Error:  fmt.Sprintf("test2json exited with non-zero status: %v", err),
-			})
-			log.Printf("Failed to stop test2json: %v", err)
+			plog.Error("test2json exited with non-zero status", "err", err)
 		}
 
 		if len(*coverProfile) > 0 {
 			if err := AppendFile(coverFile, *coverProfile); err != nil {
-				_ = testEvents.Emit(testevent.ErrorEvent{
-					Binary: path,
-					Error:  fmt.Sprintf("could not append to coverage file: %v", err),
-				})
-				log.Printf("Could not append to cover file: %v", err)
+				plog.Error("could not append to coverage file", "err", err)
 			}
 		}
 	})
@@ -212,9 +201,7 @@ func run(testEvents *guest.Emitter[testevent.ErrorEvent]) error {
 func main() {
 	flag.Parse()
 
-	if err := runTest(); err != nil {
-		log.Printf("Tests failed: %v", err)
-	}
+	runTest()
 
 	if err := unix.Reboot(unix.LINUX_REBOOT_CMD_POWER_OFF); err != nil {
 		log.Fatalf("Failed to reboot: %v", err)