Implements per-test logging to the current working directory

container.go

@@ -15,6 +15,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 
 	"code.dumpstack.io/tools/out-of-tree/config"
@@ -113,17 +114,26 @@ func listContainerImages() (diis []containerImageInfo, err error) {
 
 type container struct {
 	name string
+
 	timeout time.Duration
+
 	Volumes struct {
 		LibModules string
 		UsrSrc     string
 		Boot       string
 	}
+
 	// Additional arguments
 	Args []string
+
+	Log zerolog.Logger
 }
 
 func NewContainer(name string, timeout time.Duration) (c container, err error) {
+	c.Log = log.With().
+		Str("container", name).
+		Logger()
+
 	c.name = name
 	c.timeout = timeout
 
@@ -153,7 +163,7 @@ func (c container) Build(imagePath string) (output string, err error) {
 
 	cmd := exec.Command(containerRuntime, args...)
 
-	flog := log.With().
+	flog := c.Log.With().
 		Str("command", fmt.Sprintf("%v", cmd)).
 		Logger()
 
@@ -182,8 +192,7 @@ func (c container) Build(imagePath string) (output string, err error) {
 }
 
 func (c container) Run(workdir string, command string) (output string, err error) {
-	flog := log.With().
+	flog := c.Log.With().
-		Str("container", c.name).
 		Str("workdir", workdir).
 		Str("command", command).
 		Logger()
@@ -212,7 +221,7 @@ func (c container) Run(workdir string, command string) (output string, err error
 
 	cmd := exec.Command(containerRuntime, args...)
 
-	log.Debug().Msgf("%v", cmd)
+	flog.Debug().Msgf("%v", cmd)
 
 	stdout, err := cmd.StdoutPipe()
 	if err != nil {

debug.go

@@ -178,7 +178,7 @@ func (cmd *DebugCmd) Run(g *Globals) (err error) {
 			return
 		}
 	} else {
-		buildDir, outFile, output, err = build(tmp, ka, ki, g.Config.Docker.Timeout.Duration)
+		buildDir, outFile, output, err = build(log.Logger, tmp, ka, ki, g.Config.Docker.Timeout.Duration)
 		if err != nil {
 			log.Print(err, output)
 			return

main.go

@@ -94,6 +94,10 @@ func (lw *LevelWriter) WriteLevel(l zerolog.Level, p []byte) (n int, err error)
 
 var tempDirBase string
 
+var consoleWriter, fileWriter LevelWriter
+
+var loglevel zerolog.Level
+
 func main() {
 	rand.Seed(time.Now().UnixNano())
 
@@ -110,7 +114,6 @@ func main() {
 		},
 	)
 
-	var loglevel zerolog.Level
 	switch cli.LogLevel {
 	case "trace":
 		loglevel = zerolog.TraceLevel
@@ -132,19 +135,23 @@ func main() {
 	tempDirBase = usr.HomeDir + "/.out-of-tree/tmp/"
 	os.MkdirAll(tempDirBase, os.ModePerm)
 
-	log.Logger = log.Output(zerolog.MultiLevelWriter(
+	consoleWriter = LevelWriter{Writer: zerolog.NewConsoleWriter(
-		&LevelWriter{Writer: zerolog.NewConsoleWriter(
 		func(w *zerolog.ConsoleWriter) {
 			w.Out = os.Stderr
 		},
 	),
 		Level: loglevel,
-		},
+	}
-		&LevelWriter{Writer: &lumberjack.Logger{
+
+	fileWriter = LevelWriter{Writer: &lumberjack.Logger{
 		Filename: usr.HomeDir + "/.out-of-tree/logs/out-of-tree.log",
 	},
 		Level: zerolog.TraceLevel,
-		},
+	}
+
+	log.Logger = log.Output(zerolog.MultiLevelWriter(
+		&consoleWriter,
+		&fileWriter,
 	))
 
 	log.Trace().Msg("start out-of-tree")

pew.go

@@ -117,7 +117,7 @@ func (cmd *PewCmd) Run(g *Globals) (err error) {
 	if cmd.Tag == "" {
 		cmd.Tag = fmt.Sprintf("%d", time.Now().Unix())
 	}
-	log.Info().Str("tag", cmd.Tag).Msg("log")
+	log.Info().Str("tag", cmd.Tag).Msg("")
 
 	err = cmd.performCI(ka)
 	if err != nil {
@@ -227,8 +227,9 @@ func applyPatches(src string, ka config.Artifact) (err error) {
 	return
 }
 
-func build(tmp string, ka config.Artifact, ki config.KernelInfo,
+func build(flog zerolog.Logger, tmp string, ka config.Artifact,
-	dockerTimeout time.Duration) (outdir, outpath, output string, err error) {
+	ki config.KernelInfo, dockerTimeout time.Duration) (
+	outdir, outpath, output string, err error) {
 
 	target := fmt.Sprintf("%d_%s", rand.Int(), ki.KernelRelease)
 
@@ -262,6 +263,7 @@ func build(tmp string, ka config.Artifact, ki config.KernelInfo,
 	if ki.ContainerName != "" {
 		var c container
 		c, err = NewContainer(ki.ContainerName, dockerTimeout)
+		c.Log = flog
 		if err != nil {
 			log.Fatal().Err(err).Msg("container creation failure")
 		}
@@ -375,24 +377,19 @@ func copyFile(sourcePath, destinationPath string) (err error) {
 func dumpResult(q *qemu.System, ka config.Artifact, ki config.KernelInfo,
 	res *phasesResult, dist, tag, binary string, db *sql.DB) {
 
-	// TODO merge (problem is it's not 100% same) with log.go:logLogEntry
-
-	distroInfo := fmt.Sprintf("%s-%s {%s}", ki.DistroType,
-		ki.DistroRelease, ki.KernelRelease)
-
 	colored := ""
 	switch ka.Type {
 	case config.KernelExploit:
-		colored = aurora.Sprintf("[*] %40s: %s %s", distroInfo,
+		colored = aurora.Sprintf("%s %s",
 			genOkFail("BUILD", res.Build.Ok),
 			genOkFail("LPE", res.Test.Ok))
 	case config.KernelModule:
-		colored = aurora.Sprintf("[*] %40s: %s %s %s", distroInfo,
+		colored = aurora.Sprintf("%s %s %s",
 			genOkFail("BUILD", res.Build.Ok),
 			genOkFail("INSMOD", res.Run.Ok),
 			genOkFail("TEST", res.Test.Ok))
 	case config.Script:
-		colored = aurora.Sprintf("[*] %40s: %s", distroInfo,
+		colored = aurora.Sprintf("%s",
 			genOkFail("", res.Test.Ok))
 	}
 
@@ -404,14 +401,14 @@ func dumpResult(q *qemu.System, ka config.Artifact, ki config.KernelInfo,
 	}
 
 	if additional != "" {
-		fmt.Println(colored, additional)
+		q.Log.Info().Msgf("%v %v", colored, additional)
 	} else {
-		fmt.Println(colored)
+		q.Log.Info().Msgf("%v", colored)
 	}
 
 	err := addToLog(db, q, ka, ki, res, tag)
 	if err != nil {
-		log.Warn().Err(err).Msgf("[db] addToLog (%v)", ka)
+		q.Log.Warn().Err(err).Msgf("[db] addToLog (%v)", ka)
 	}
 
 	if binary == "" && dist != pathDevNull {
@@ -549,7 +546,38 @@ func (cmd PewCmd) testArtifact(swg *sizedwaitgroup.SizedWaitGroup,
 
 	defer swg.Done()
 
-	slog := log.With().
+	logdir := "logs/" + cmd.Tag
+	err := os.MkdirAll(logdir, os.ModePerm)
+	if err != nil {
+		log.Error().Err(err).Msgf("mkdir %s", logdir)
+		return
+	}
+
+	logfile := fmt.Sprintf("logs/%s/%s-%s-%s.log",
+		cmd.Tag,
+		ki.DistroType.String(),
+		ki.DistroRelease,
+		ki.KernelRelease,
+	)
+	f, err := os.Create(logfile)
+	if err != nil {
+		log.Error().Err(err).Msgf("create %s", logfile)
+		return
+	}
+	defer f.Close()
+
+	slog := zerolog.New(zerolog.MultiLevelWriter(
+		&consoleWriter,
+		&fileWriter,
+		&zerolog.ConsoleWriter{Out: f},
+	))
+
+	switch loglevel {
+	case zerolog.TraceLevel, zerolog.DebugLevel:
+		slog = slog.With().Caller().Logger()
+	}
+
+	slog = slog.With().Timestamp().
 		Str("distro_type", ki.DistroType.String()).
 		Str("distro_release", ki.DistroRelease).
 		Str("kernel", ki.KernelRelease).
@@ -563,6 +591,8 @@ func (cmd PewCmd) testArtifact(swg *sizedwaitgroup.SizedWaitGroup,
 		slog.Error().Err(err).Msg("qemu init")
 		return
 	}
+	q.Log = slog
+
 	q.Timeout = cmd.QemuTimeout
 
 	if ka.Qemu.Timeout.Duration != 0 {
@@ -615,7 +645,7 @@ func (cmd PewCmd) testArtifact(swg *sizedwaitgroup.SizedWaitGroup,
 		// TODO: build should return structure
 		start := time.Now()
 		result.BuildDir, result.BuildArtifact, result.Build.Output, err =
-			build(tmp, ka, ki, cmd.DockerTimeout)
+			build(slog, tmp, ka, ki, cmd.DockerTimeout)
 		slog.Debug().Str("duration", time.Now().Sub(start).String()).
 			Msg("build done")
 		if err != nil {
@@ -631,7 +661,10 @@ func (cmd PewCmd) testArtifact(swg *sizedwaitgroup.SizedWaitGroup,
 	if cmd.Test == "" {
 		cmd.Test = result.BuildArtifact + "_test"
 		if !exists(cmd.Test) {
+			slog.Debug().Msgf("%s does not exist", cmd.Test)
 			cmd.Test = tmp + "/source/" + "test.sh"
+		} else {
+			slog.Debug().Msgf("%s exist", cmd.Test)
 		}
 	}
 
@@ -667,7 +700,7 @@ func (cmd PewCmd) testArtifact(swg *sizedwaitgroup.SizedWaitGroup,
 	start := time.Now()
 	copyArtifactAndTest(slog, q, ka, &result, remoteTest)
 	slog.Debug().Str("duration", time.Now().Sub(start).String()).
-		Msg("test completed")
+		Msgf("test completed (success: %v)", result.Test.Ok)
 }
 
 func shuffleKernels(a []config.KernelInfo) []config.KernelInfo {
@@ -723,10 +756,8 @@ func (cmd PewCmd) performCI(ka config.Artifact) (err error) {
 
 func exists(path string) bool {
 	if _, err := os.Stat(path); err != nil {
-		log.Debug().Msgf("%s does not exist", path)
 		return false
 	}
-	log.Debug().Msgf("%s exist", path)
 	return true
 }
 

preload.go

@@ -111,7 +111,7 @@ func buildPreload(workPath, tmp string, ki config.KernelInfo,
 		dockerTimeout = ka.Docker.Timeout.Duration
 	}
 
-	_, artifact, _, err = build(tmp, ka, ki, dockerTimeout)
+	_, artifact, _, err = build(log.Logger, tmp, ka, ki, dockerTimeout)
 	return
 }
 

qemu/qemu-kernel.go

@@ -87,13 +87,13 @@ type System struct {
 	// accessible after qemu is closed
 	exitErr error
 
-	log zerolog.Logger
+	Log zerolog.Logger
 }
 
 // NewSystem constructor
 func NewSystem(arch arch, kernel Kernel, drivePath string) (q *System, err error) {
 	q = &System{}
-	q.log = log.With().
+	q.Log = log.With().
 		Str("kernel", kernel.KernelPath).
 		Logger()
 
@@ -183,7 +183,7 @@ func (q *System) panicWatcher() {
 		time.Sleep(time.Second)
 		if strings.Contains(q.Stdout, "Kernel panic") {
 			q.KernelPanic = true
-			q.log.Debug().Msg("kernel panic")
+			q.Log.Debug().Msg("kernel panic")
 			time.Sleep(time.Second)
 			// There is no reason to stay alive after kernel panic
 			q.Stop()
@@ -261,7 +261,7 @@ func (q *System) Start() (err error) {
 	rand.Seed(time.Now().UnixNano()) // Are you sure?
 
 	q.cmd = exec.Command(q.Executable(), q.Args()...)
-	q.log.Debug().Msgf("%v", q.cmd)
+	q.Log.Debug().Msgf("%v", q.cmd)
 
 	if q.pipe.stdin, err = q.cmd.StdinPipe(); err != nil {
 		return
@@ -285,7 +285,7 @@ func (q *System) Start() (err error) {
 		for scanner.Scan() {
 			m := scanner.Text()
 			q.Stdout += m + "\n"
-			q.log.Trace().Str("stdout", m).Msg("")
+			q.Log.Trace().Str("stdout", m).Msg("qemu")
 		}
 	}()
 
@@ -294,7 +294,7 @@ func (q *System) Start() (err error) {
 		for scanner.Scan() {
 			m := scanner.Text()
 			q.Stderr += m + "\n"
-			q.log.Trace().Str("stderr", m).Msg("")
+			q.Log.Trace().Str("stderr", m).Msg("qemu")
 		}
 	}()
 
@@ -361,13 +361,11 @@ func (q System) ssh(user string) (client *ssh.Client, err error) {
 
 // Command executes shell commands on qemu system
 func (q System) Command(user, cmd string) (output string, err error) {
-	flog := log.With().
+	q.Log.With().Str("kernel", q.kernel.KernelPath).
-		Str("kernel", q.kernel.KernelPath).
 		Str("user", user).
-		Str("cmd", cmd).
+		Str("cmd", cmd)
-		Logger()
 
-	flog.Debug().Msg("qemu command")
+	q.Log.Debug().Msg("qemu command")
 
 	client, err := q.ssh(user)
 	if err != nil {
@@ -400,7 +398,7 @@ func (q System) Command(user, cmd string) (output string, err error) {
 		for scanner.Scan() {
 			m := scanner.Text()
 			output += m + "\n"
-			flog.Trace().Str("stdout", m).Msg("")
+			q.Log.Trace().Str("stdout", m).Msg("qemu command")
 		}
 		output = strings.TrimSuffix(output, "\n")
 	}()
@@ -411,7 +409,7 @@ func (q System) Command(user, cmd string) (output string, err error) {
 			m := scanner.Text()
 			output += m + "\n"
 			// Note: it prints stderr as stdout
-			flog.Trace().Str("stdout", m).Msg("")
+			q.Log.Trace().Str("stdout", m).Msg("qemu command")
 		}
 		output = strings.TrimSuffix(output, "\n")
 	}()
@@ -452,7 +450,7 @@ func (q System) scp(user, localPath, remotePath string, recursive bool) (err err
 	if recursive {
 		cmd := exec.Command("ssh", "-V")
 
-		log.Debug().Msgf("%v", cmd)
+		q.Log.Debug().Msgf("%v", cmd)
 
 		var output []byte
 		output, err = cmd.CombinedOutput()
@@ -461,7 +459,7 @@ func (q System) scp(user, localPath, remotePath string, recursive bool) (err err
 		}
 		sshVersion := string(output)
 
-		log.Debug().Str("ssh version", sshVersion).Msg("")
+		q.Log.Debug().Str("ssh version", sshVersion).Msg("qemu scp")
 
 		if strings.Contains(sshVersion, "OpenSSH_9") {
 			// This release switches scp from using the
@@ -481,7 +479,7 @@ func (q System) scp(user, localPath, remotePath string, recursive bool) (err err
 	args = append(args, localPath, user+"@"+addr+":"+remotePath)
 
 	cmd := exec.Command("scp", args...)
-	log.Debug().Msgf("%v", cmd)
+	q.Log.Debug().Msgf("%v", cmd)
 
 	output, err := cmd.CombinedOutput()
 	if err != nil || string(output) != "" {
@@ -498,9 +496,9 @@ func (q System) scpWithRetry(user, localPath, remotePath string, recursive bool)
 			break
 		}
 
-		q.log.Warn().Err(err).Msg("scp: failed")
+		q.Log.Warn().Err(err).Msg("scp: failed")
 		time.Sleep(q.SCP.RetryTimeout)
-		q.log.Warn().Msgf("scp: %d retries left", retries)
+		q.Log.Warn().Msgf("scp: %d retries left", retries)
 	}
 	return
 }