diff --git a/go.mod b/go.mod index e6ebc11..a03674e 100644 --- a/go.mod +++ b/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-20231224233253-2944a440b6b6 github.com/u-root/u-root v0.11.1-0.20230807200058-f87ad7ccb594 github.com/u-root/uio v0.0.0-20230305220412-3e8cd9d6bf63 @@ -30,6 +31,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 diff --git a/go.sum b/go.sum index 01d9ef0..e4a929e 100644 --- a/go.sum +++ b/go.sum @@ -62,6 +62,10 @@ github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZN github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA= 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= diff --git a/gotest.go b/gotest.go index f2de215..d0b3520 100644 --- a/gotest.go +++ b/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() diff --git a/qemu/qslog/slog.go b/qemu/qslog/slog.go new file mode 100644 index 0000000..40a984e --- /dev/null +++ b/qemu/qslog/slog.go @@ -0,0 +1,90 @@ +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 +} diff --git a/vminit/gouinit/main_linux.go b/vminit/gouinit/main_linux.go index 8057fb5..537da1a 100644 --- a/vminit/gouinit/main_linux.go +++ b/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,41 @@ 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 } - return nil + return } -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 +137,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 +165,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 +176,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 +203,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)