Skip to content

Commit

Permalink
Sharing logs via slog.
Browse files Browse the repository at this point in the history
Signed-off-by: Chris Koch <[email protected]>
  • Loading branch information
hugelgupf committed Jan 15, 2024
1 parent 44ec9e8 commit 7733b32
Show file tree
Hide file tree
Showing 5 changed files with 133 additions and 48 deletions.
2 changes: 2 additions & 0 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down
4 changes: 4 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand Down
8 changes: 4 additions & 4 deletions gotest.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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()
Expand Down
90 changes: 90 additions & 0 deletions qemu/qslog/slog.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,90 @@
package qslog

Check failure on line 1 in qemu/qslog/slog.go

View workflow job for this annotation

GitHub Actions / lint

package-comments: should have a package comment (revive)

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

Check warning on line 42 in qemu/qslog/slog.go

View check run for this annotation

Codecov / codecov/patch

qemu/qslog/slog.go#L37-L42

Added lines #L37 - L42 were not covered by tests
}
writeAttrs(b, np, v)

Check warning on line 44 in qemu/qslog/slog.go

View check run for this annotation

Codecov / codecov/patch

qemu/qslog/slog.go#L44

Added line #L44 was not covered by tests

default:
if prefix != "" {
b.WriteString(prefix)
b.WriteString(".")

Check warning on line 49 in qemu/qslog/slog.go

View check run for this annotation

Codecov / codecov/patch

qemu/qslog/slog.go#L48-L49

Added lines #L48 - L49 were not covered by tests
}
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))

Check failure on line 72 in qemu/qslog/slog.go

View workflow job for this annotation

GitHub Actions / lint

Error return value of `nr.Level.UnmarshalText` is not checked (errcheck)
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

Check warning on line 83 in qemu/qslog/slog.go

View check run for this annotation

Codecov / codecov/patch

qemu/qslog/slog.go#L83

Added line #L83 was not covered by tests
}
var records []Record
for _, r := range errors {
records = append(records, RecordFrom(r))
}
return records, nil
}
77 changes: 33 additions & 44 deletions vminit/gouinit/main_linux.go
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import (
"fmt"
"io"
"log"
"log/slog"
"os"
"os/exec"
"path/filepath"
Expand All @@ -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"
)

Expand Down Expand Up @@ -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

Check failure on line 107 in vminit/gouinit/main_linux.go

View workflow job for this annotation

GitHub Actions / lint

S1023: redundant `return` statement (gosimple)
}

func run(testEvents *guest.Emitter[testevent.ErrorEvent]) error {
func run(logger *slog.Logger) error {
cleanup, err := guest.MountSharedDir()
if err != nil {
return err
Expand Down Expand Up @@ -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
}

Expand All @@ -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
}

Expand All @@ -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)
}
}
})
Expand All @@ -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)
Expand Down

0 comments on commit 7733b32

Please sign in to comment.