From 4f80122039758812987b2656ef28b667b0a48b8f Mon Sep 17 00:00:00 2001 From: Mikhail Klementev Date: Tue, 2 May 2023 11:10:57 +0000 Subject: [PATCH] Implements per-test logging to the current working directory --- container.go | 19 +++++++++---- debug.go | 2 +- main.go | 33 +++++++++++++--------- pew.go | 69 ++++++++++++++++++++++++++++++++------------- preload.go | 2 +- qemu/qemu-kernel.go | 34 +++++++++++----------- 6 files changed, 102 insertions(+), 57 deletions(-) diff --git a/container.go b/container.go index 2a3585a..87917c1 100644 --- a/container.go +++ b/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" @@ -112,18 +113,27 @@ func listContainerImages() (diis []containerImageInfo, err error) { } type container struct { - name string + 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(). - Str("container", c.name). + flog := c.Log.With(). 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 { diff --git a/debug.go b/debug.go index 439efc1..0961601 100644 --- a/debug.go +++ b/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 diff --git a/main.go b/main.go index 6f621d8..7106c85 100644 --- a/main.go +++ b/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) + consoleWriter = LevelWriter{Writer: zerolog.NewConsoleWriter( + func(w *zerolog.ConsoleWriter) { + w.Out = os.Stderr + }, + ), + Level: loglevel, + } + + 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( - &LevelWriter{Writer: zerolog.NewConsoleWriter( - func(w *zerolog.ConsoleWriter) { - w.Out = os.Stderr - }, - ), - Level: loglevel, - }, - &LevelWriter{Writer: &lumberjack.Logger{ - Filename: usr.HomeDir + "/.out-of-tree/logs/out-of-tree.log", - }, - Level: zerolog.TraceLevel, - }, + &consoleWriter, + &fileWriter, )) log.Trace().Msg("start out-of-tree") diff --git a/pew.go b/pew.go index de5c3cf..ab4158b 100644 --- a/pew.go +++ b/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, - dockerTimeout time.Duration) (outdir, outpath, output string, err error) { +func build(flog zerolog.Logger, tmp string, ka config.Artifact, + 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 } diff --git a/preload.go b/preload.go index 7a28f35..2b6e5e5 100644 --- a/preload.go +++ b/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 } diff --git a/qemu/qemu-kernel.go b/qemu/qemu-kernel.go index aade5e0..ade8d9c 100644 --- a/qemu/qemu-kernel.go +++ b/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(). - Str("kernel", q.kernel.KernelPath). + q.Log.With().Str("kernel", q.kernel.KernelPath). Str("user", user). - Str("cmd", cmd). - Logger() + Str("cmd", cmd) - 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 }