--- /dev/null
+/*
+goredo -- djb's redo implementation on pure Go
+Copyright (C) 2020-2021 Sergey Matveev <stargrave@stargrave.org>
+
+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 <http://www.gnu.org/licenses/>.
+*/
+
+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
+}
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.
@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
@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
@include notes.texi
@include rules.texi
@include cmds.texi
+@include logs.texi
@include news.texi
@include install.texi
@include faq.texi
--- /dev/null
+@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}.
@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}
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")
"os/exec"
"path"
"path/filepath"
+ "strconv"
"strings"
"sync"
"syscall"
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))
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)
// 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
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 [...]