From 7492a39768035abafa55be738649a8dd035a89bd Mon Sep 17 00:00:00 2001 From: Sergey Matveev Date: Fri, 30 Jul 2021 16:55:21 +0300 Subject: [PATCH] Recursive serialized logs capability --- buildlog.go | 300 ++++++++++++++++++++++++++++++++++++++++++++++ doc/cmds.texi | 9 +- doc/faq.texi | 6 +- doc/features.texi | 6 + doc/index.texi | 1 + doc/logs.texi | 67 +++++++++++ doc/news.texi | 10 ++ main.go | 7 +- run.go | 63 +++++++++- usage.go | 6 +- 10 files changed, 453 insertions(+), 22 deletions(-) create mode 100644 buildlog.go create mode 100644 doc/logs.texi diff --git a/buildlog.go b/buildlog.go new file mode 100644 index 0000000..3403e4d --- /dev/null +++ b/buildlog.go @@ -0,0 +1,300 @@ +/* +goredo -- djb's redo implementation on pure Go +Copyright (C) 2020-2021 Sergey Matveev + +This program is free software: you can redistribute it and/or modify +it under the terms of the GNU General Public License as published by +the Free Software Foundation, version 3 of the License. + +This program is distributed in the hope that it will be useful, +but WITHOUT ANY WARRANTY; without even the implied warranty of +MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +GNU General Public License for more details. + +You should have received a copy of the GNU General Public License +along with this program. If not, see . +*/ + +package main + +import ( + "bufio" + "errors" + "flag" + "fmt" + "io" + "os" + "path" + "path/filepath" + "sort" + "strconv" + "strings" + "time" + + "go.cypherpunks.ru/recfile" + "go.cypherpunks.ru/tai64n/v2" +) + +const HumanTimeFmt = "2006-01-02 15:04:05.000000000 Z07:00" + +type BuildLogJob struct { + dir string + tgt string + started time.Time + exitCode int + rec map[string][]string +} + +type ByStarted []*BuildLogJob + +func (a ByStarted) Len() int { return len(a) } + +func (a ByStarted) Swap(i, j int) { a[i], a[j] = a[j], a[i] } + +func (a ByStarted) Less(i, j int) bool { + // actually that code performs reverse order + if a[i].exitCode > a[j].exitCode { + // bad return code has higher priority + return true + } + return a[i].started.After(a[j].started) +} + +var ( + flagBuildLogRecursive *bool + flagBuildLogCommands *bool + buildLogSeen map[string]struct{} +) + +func init() { + if CmdName() != CmdNameRedoLog { + return + } + flagBuildLogRecursive = flag.Bool("r", false, "Show logs recursively") + flagBuildLogCommands = flag.Bool("c", false, "Show how target was invoked") + buildLogSeen = make(map[string]struct{}) +} + +func parseBuildLogRec(dir, tgt string) (map[string][]string, error) { + fd, err := os.Open(path.Join(dir, RedoDir, tgt+LogSuffix+DepSuffix)) + if err != nil { + return nil, err + } + r := recfile.NewReader(bufio.NewReader(fd)) + rec, err := r.NextMapWithSlice() + fd.Close() + return rec, err +} + +func depthPrefix(depth int) string { + if depth == 0 { + return " " + } + return " " + colourize(CDebug, strings.Repeat("> ", depth)) +} + +func showBuildLogSub(sub *BuildLogJob, depth int) error { + abs, err := filepath.Abs(path.Join(sub.dir, sub.tgt)) + if err != nil { + return err + } + if _, ok := buildLogSeen[abs]; ok { + return nil + } + buildLogSeen[abs] = struct{}{} + dp := depthPrefix(depth) + fmt.Printf( + "%s%s%s\n", + sub.rec["Started"][0], dp, + colourize(CRedo, "redo "+sub.tgt), + ) + if err := showBuildLog(sub.dir, sub.tgt, sub.rec, depth+1); err != nil { + return err + } + durationSec, durationNsec, err := durationToInts(sub.rec["Duration"][0]) + if err != nil { + return err + } + if sub.exitCode > 0 { + fmt.Printf( + "%s%s%s (code: %d) (%d.%ds)\n\n", + sub.rec["Finished"][0], dp, + colourize(CErr, "err "+sub.tgt), + sub.exitCode, durationSec, durationNsec, + ) + } else { + fmt.Printf( + "%s%s%s (%d.%ds)\n\n", + sub.rec["Finished"][0], dp, + colourize(CRedo, "done "+sub.tgt), + durationSec, durationNsec, + ) + } + return nil +} + +func durationToInts(d string) (int64, int64, error) { + duration, err := strconv.ParseInt(d, 10, 64) + if err != nil { + return 0, 0, err + } + return duration / 1e9, (duration % 1e9) / 1000, nil +} + +func showBuildLogCmd(m map[string][]string, depth int) error { + started, err := tai64n.Decode(m["Started"][0]) + if err != nil { + return err + } + dp := depthPrefix(depth) + fmt.Printf( + "%s%s%s $ %s\n", + m["Started"][0], dp, m["Cwd"][0], strings.Join(m["Cmd"], " "), + ) + if len(m["ExitCode"]) > 0 { + fmt.Printf("%s%sExit code: %s\n", m["Started"][0], dp, m["ExitCode"][0]) + } + finished, err := tai64n.Decode(m["Finished"][0]) + if err != nil { + return err + } + durationSec, durationNsec, err := durationToInts(m["Duration"][0]) + if err != nil { + return err + } + fmt.Printf( + "%s%sStarted:\t%s\n%s%sFinished:\t%s\n%s%sDuration:\t%d.%ds\n\n", + m["Started"][0], dp, started.Format(HumanTimeFmt), + m["Started"][0], dp, finished.Format(HumanTimeFmt), + m["Started"][0], dp, durationSec, durationNsec, + ) + return nil +} + +func showBuildLog(dir, tgt string, buildLogRec map[string][]string, depth int) error { + var err error + dirNormalized, tgtNormalized := cwdAndTgt(path.Join(dir, tgt)) + if *flagBuildLogCommands || *flagBuildLogRecursive { + buildLogRec, err = parseBuildLogRec(dirNormalized, tgtNormalized) + if err != nil { + return err + } + } + if *flagBuildLogCommands { + if err = showBuildLogCmd(buildLogRec, depth); err != nil { + return err + } + } + fd, err := os.Open(path.Join(dirNormalized, RedoDir, tgtNormalized+LogSuffix)) + if err != nil { + return err + } + if !*flagBuildLogRecursive { + w := bufio.NewWriter(os.Stdout) + _, err = io.Copy(w, bufio.NewReader(fd)) + fd.Close() + if err != nil { + w.Flush() + return err + } + return w.Flush() + } + defer fd.Close() + fdDep, err := os.Open(path.Join(dirNormalized, RedoDir, tgtNormalized+DepSuffix)) + if err != nil { + return err + } + depInfo, err := depRead(fdDep) + fdDep.Close() + if err != nil { + return err + } + subs := make([]*BuildLogJob, 0, len(depInfo.ifchanges)) + for _, dep := range depInfo.ifchanges { + subDir, subTgt := cwdAndTgt(path.Join(dirNormalized, dep["Target"])) + if subDir == dirNormalized && subTgt == tgtNormalized { + continue + } + rec, err := parseBuildLogRec(subDir, subTgt) + if err != nil { + if os.IsNotExist(err) { + continue + } + return err + } + if rec["Build"][0] != buildLogRec["Build"][0] { + continue + } + started, err := tai64n.Decode(rec["Started"][0]) + if err != nil { + return err + } + var exitCode int + if len(rec["ExitCode"]) > 0 { + exitCode, err = strconv.Atoi(rec["ExitCode"][0]) + if err != nil { + return err + } + } + subs = append(subs, &BuildLogJob{ + dir: dirNormalized, + tgt: dep["Target"], + started: started, + exitCode: exitCode, + rec: rec, + }) + } + sort.Sort(ByStarted(subs)) + scanner := bufio.NewScanner(fd) + var text string + var sep int + var t time.Time + var sub *BuildLogJob + if len(subs) > 0 { + sub = subs[len(subs)-1] + } + dp := depthPrefix(depth) + for { + if !scanner.Scan() { + if err = scanner.Err(); err != nil { + return err + } + break + } + text = scanner.Text() + if text[0] != '@' { + return errors.New("unexpected non-TAI64Ned string") + } + sep = strings.IndexByte(text, byte(' ')) + if sep == -1 { + sep = len(text) + } + t, err = tai64n.Decode(text[1:sep]) + if err != nil { + return err + } + for sub != nil && t.After(sub.started) { + if err = showBuildLogSub(sub, depth); err != nil { + return err + } + subs = subs[:len(subs)-1] + if len(subs) > 0 { + sub = subs[len(subs)-1] + } else { + sub = nil + } + } + if depth == 0 { + fmt.Println(text) + } else { + fmt.Printf("%s%s%s\n", text[:sep], dp, text[sep+1:]) + } + } + for i := len(subs); i > 0; i-- { + sub = subs[i-1] + if err = showBuildLogSub(sub, depth); err != nil { + return err + } + } + return nil +} diff --git a/doc/cmds.texi b/doc/cmds.texi index 4c39609..144b118 100644 --- a/doc/cmds.texi +++ b/doc/cmds.texi @@ -31,14 +31,7 @@ With @option{-j} option you can enable parallel builds, probably with an infinite number of workers (@code{=0}). Also you can set @env{$REDO_JOBS} to automatically apply that setting globally. -With @option{-k} (@env{$REDO_LOGS=1}) option you can capture job's -@code{stderr} on the disk and read it later with @command{redo-log} -command. Log's lines have @url{http://cr.yp.to/libtai/tai64.html, -TAI64N} timestamp. You can decode it with @command{tai64nlocal} utility -from @url{http://cr.yp.to/daemontools.html, daemontools}, or similar -one: @code{go get go.cypherpunks.ru/tai64n/cmd/tai64nlocal}. -@option{-s} (@env{$REDO_SILENT=1}) omits @code{stderr} printing at -all, but you can still capture it with @option{-k}. +Read about @ref{Logs, log storage capabilities}. @option{-log-pid} (@env{$REDO_LOG_PID=1}) can be used to prefix job's @code{stderr} with the PID, that could be useful during parallel builds. diff --git a/doc/faq.texi b/doc/faq.texi index 50a3cdb..7039e2a 100644 --- a/doc/faq.texi +++ b/doc/faq.texi @@ -19,10 +19,8 @@ them do not apply. @item If you really wish to produce an empty target file, just touch @file{$3} @end itemize -DJB's proposal with both @file{stdout} and @file{$3} gives that ability -to control your desired behaviour. Those who do not capture -@file{stdout} -- failed. Those who create an empty file if no -@file{stdout} was written -- failed. +Those who create an empty file if no @file{stdout} was written -- failed +implementation. redo is a tool to help people. Literally all targets can be safely @code{redo-stamp < $3}-ed, reducing false positive out-of-dates. Of diff --git a/doc/features.texi b/doc/features.texi index 3ba5483..c1eb41b 100644 --- a/doc/features.texi +++ b/doc/features.texi @@ -13,6 +13,12 @@ implementations. @item check that generated target was not modified "externally" outside the redo, preventing its overwriting, but continuing the build @end itemize +@item recursive, indented and serialized logs display ability, with + priority to the depth and bad return codes, like in @command{apenwarr/redo}, + thanks to @url{https://apenwarr.ca/log/20181106, apenwarr's article} +@item all environment variables, working directory, command line + arguments, start/finish times, duration, participated PIDs, return + codes can be saved for later investigation @item targets, dependency information and their directories are explicitly synced (can be disabled, should work faster) @item file's change is detected by comparing its size, @code{ctime} (if diff --git a/doc/index.texi b/doc/index.texi index 2a81af4..8b88014 100644 --- a/doc/index.texi +++ b/doc/index.texi @@ -49,6 +49,7 @@ maillist. Announcements also go to this mailing list. @include notes.texi @include rules.texi @include cmds.texi +@include logs.texi @include news.texi @include install.texi @include faq.texi diff --git a/doc/logs.texi b/doc/logs.texi new file mode 100644 index 0000000..b68b88e --- /dev/null +++ b/doc/logs.texi @@ -0,0 +1,67 @@ +@node Logs +@unnumbered Logs + +@code{stderr} of the running targets can be kept on the disk by +specifying @option{-k} option (or by setting @env{$REDO_LOGS=1} +environment variable) to @command{redo}. You can simultaneously +use also @option{-s} option (@env{$REDO_SILENT=1} environment variable) +to silence @code{stderr} output, but still keeping it on the disk for +possible further debug investigation. @strong{Only} the latest build is +kept, previous one is overwritten. + +@example +$ redo -xx -k -s build-the-whole-huge-project +@end example + +Logs are stored in corresponding @file{.redo/tgt.log} file. Each line of +it is prefixed with @url{http://cr.yp.to/libtai/tai64.html, TAI64N} +timestamp, that you can decode with @command{tai64nlocal} utility from +@url{http://cr.yp.to/daemontools.html, daemontools}, or similar one: +@code{go get go.cypherpunks.ru/tai64n/cmd/tai64nlocal}. + +When @option{-k} is in use, all environment variables, working +directory, command line arguments, start/finish times, duration, +participated PIDs, return codes are also saved in corresponding +@file{.redo/tgt.log.reg} file. + +You can view any target's output with @command{redo-log} command +(possibly piping to @command{tai64nlocal}). @option{-c} option also +shows how exactly it was started, when started/finished and how long did +it take. + +@option{-r} option enables recursive serialized indented output. When +you run @command{redo} in parallel, then all @code{stderr} (if no +@option{-s}ilence was enabled) is printed as it appears, mixing output +from all commands, that is hard to read and investigate. Serialized +@command{redo-log} output rearranges output. I will take example from +original apenwarr's idea @url{https://apenwarr.ca/log/20181106, +article}. Serialized output will look like this: + +@verbatim +$ redo-log -r A +A: ...A stuff... +A: redo-ifchange J +J: > redo J +J: > ...J stuff... +J: > redo-ifchange X Y +X: > > redo X +X: > > ...X stuff... +X: > > done X +J: > > redo Y +Y: > > ...Y stuff... +Z: > > > redo Z +Z: > > > ...Z stuff... +Z: > > > done Z +Y: > > ...more Y stuff... +Y: > > done Y +J: > ...more J stuff... +J: > done J +A: ...more A stuff... +@end verbatim + +It will output depth first logs. It can rearrange some "events" (redo +invocations): failed targets will be at the very end, because they are +the most interesting ones for the human. + +Pay attention that recursive output is more CPU hungry. Single target +output is literally copying of @file{.redo/tgt.log} file to @code{stdout}. diff --git a/doc/news.texi b/doc/news.texi index 3574f79..ceffac8 100644 --- a/doc/news.texi +++ b/doc/news.texi @@ -14,6 +14,16 @@ @item @option{-logs} option is renamed to @option{-k} @item @option{-silent} option is renamed to @option{-s} @end itemize +@item + When @code{stderr} logs are kept, all environment variables, working + directory, command line arguments, start/finish times, duration, + participated PIDs, return codes are saved in corresponding + @file{.redo/tgt.log.rec} file. Some of them can be viewed with + @option{-c} option to @command{redo-log}. +@item + @command{redo-log}'s @option{-r} option allows recursive, indented + viewing of the whole redo commands invocations for the given target + in serialized way. @end itemize @anchor{Release 1_8_0} diff --git a/main.go b/main.go index 0bb9357..3001571 100644 --- a/main.go +++ b/main.go @@ -337,12 +337,7 @@ CmdSwitch: log.Fatalln("single target expected") } d, t := cwdAndTgt(tgts[0]) - var fd *os.File - fd, err = os.Open(path.Join(d, RedoDir, t+LogSuffix)) - if err != nil { - break - } - _, err = io.Copy(os.Stdout, fd) + err = showBuildLog(d, t, nil, 0) case CmdNameRedoWhichdo: if len(tgts) != 1 { log.Fatalln("single target expected") diff --git a/run.go b/run.go index 59e134e..fe78a87 100644 --- a/run.go +++ b/run.go @@ -29,6 +29,7 @@ import ( "os/exec" "path" "path/filepath" + "strconv" "strings" "sync" "syscall" @@ -418,6 +419,8 @@ func runScript(tgtOrig string, errs chan error, traced bool) error { FdStatus.Write([]byte{StatusRun}) } + var finished time.Time + var exitErr *exec.ExitError started := time.Now() runErr.Started = &started fdStdout, err = os.OpenFile(stdoutPath, os.O_RDWR, os.FileMode(0666)) @@ -440,12 +443,58 @@ func runScript(tgtOrig string, errs chan error, traced bool) error { defer func() { jsRelease(shCtx, jsToken) - lockRelease() fdDep.Close() fdStdout.Close() if fdStderr != nil { fdStderr.Close() + logRecPath := path.Join(redoDir, tgt+LogSuffix+DepSuffix) + if fdStderr, err = os.OpenFile( + logRecPath, + os.O_WRONLY|os.O_CREATE, + os.FileMode(0666), + ); err == nil { + fdStderr.Truncate(0) + fields := []recfile.Field{ + {Name: "Build", Value: BuildUUID}, + {Name: "PID", Value: strconv.Itoa(cmd.Process.Pid)}, + {Name: "PPID", Value: strconv.Itoa(os.Getpid())}, + {Name: "Cwd", Value: cwd}, + } + ts := new(tai64n.TAI64N) + ts.FromTime(started) + fields = append(fields, + recfile.Field{Name: "Started", Value: tai64n.Encode(ts[:])}, + ) + ts.FromTime(finished) + fields = append(fields, + recfile.Field{Name: "Finished", Value: tai64n.Encode(ts[:])}) + fields = append(fields, recfile.Field{ + Name: "Duration", + Value: strconv.FormatInt(finished.Sub(started).Nanoseconds(), 10), + }) + fields = append(fields, recfile.Field{Name: "Cmd", Value: cmdName}) + for _, arg := range args { + fields = append(fields, recfile.Field{Name: "Cmd", Value: arg}) + } + for _, e := range cmd.Env { + fields = append(fields, recfile.Field{Name: "Env", Value: e}) + } + if exitErr != nil { + fields = append(fields, recfile.Field{ + Name: "ExitCode", + Value: strconv.Itoa(exitErr.ProcessState.ExitCode()), + }) + } + w := bufio.NewWriter(fdStderr) + _, err = recfile.NewWriter(w).WriteFields(fields...) + w.Flush() + fdStderr.Close() + if err != nil { + os.Remove(logRecPath) + } + } } + lockRelease() os.Remove(fdDep.Name()) os.Remove(fdStdout.Name()) os.Remove(tmpPath) @@ -504,9 +553,19 @@ func runScript(tgtOrig string, errs chan error, traced bool) error { // Wait for job completion <-stderrTerm err = cmd.Wait() - finished := time.Now() + finished = time.Now() runErr.Finished = &finished if err != nil { + // Try to commit .rec anyway + if !NoSync { + fdDep.Sync() + } + os.Rename(fdDep.Name(), path.Join(redoDir, tgt+DepSuffix)) + if !NoSync { + err = syncDir(redoDir) + } + + exitErr = err.(*exec.ExitError) runErr.Err = err errs <- runErr return diff --git a/usage.go b/usage.go index 58b182b..59f2e90 100644 --- a/usage.go +++ b/usage.go @@ -67,11 +67,13 @@ Always build current target. Unusable outside .do.` Remove either all goredo's related temporary files, or kept stderr logs, or everything (including .redo directories) related.` case CmdNameRedoLog: - d = `Usage: redo-log target [ | tai64nlocal ] + d = `Usage: redo-log [-c] [-r] target [ | tai64nlocal ] Display kept target's stderr with TAI64N timestamped lines. Only the last build is kept. You must enable stderr keeping with either -logs, -or REDO_LOGS=1.` +or REDO_LOGS=1. -c option show the exact command invoked, start and +finish time. -r option recursively and linearly show also all deeper +redo calls and their logs.` case CmdNameRedoDot: d = `Usage: redo-dot target [...] -- 2.44.0