run.go

   1 /*
   2 goredo -- djb's redo implementation on pure Go
   3 Copyright (C) 2020-2023 Sergey Matveev <stargrave@stargrave.org>
   4
   5 This program is free software: you can redistribute it and/or modify
   6 it under the terms of the GNU General Public License as published by
   7 the Free Software Foundation, version 3 of the License.
   8
   9 This program is distributed in the hope that it will be useful,
  10 but WITHOUT ANY WARRANTY; without even the implied warranty of
  11 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  12 GNU General Public License for more details.
  13
  14 You should have received a copy of the GNU General Public License
  15 along with this program.  If not, see <http://www.gnu.org/licenses/>.
  16 */
  17
  18 // Targets runner
  19
  20 package main
  21
  22 import (
  23         "bufio"
  24         "crypto/rand"
  25         "encoding/hex"
  26         "errors"
  27         "flag"
  28         "fmt"
  29         "io"
  30         "io/fs"
  31         "log"
  32         "os"
  33         "os/exec"
  34         "path"
  35         "strconv"
  36         "strings"
  37         "sync"
  38         "syscall"
  39         "time"
  40
  41         "go.cypherpunks.ru/recfile"
  42         "go.cypherpunks.ru/tai64n/v2"
  43         "golang.org/x/sys/unix"
  44 )
  45
  46 const (
  47         EnvDepFd        = "REDO_DEP_FD"
  48         EnvDirPrefix    = "REDO_DIRPREFIX"
  49         EnvDepCwd       = "REDO_DEP_CWD"
  50         EnvBuildUUID    = "REDO_BUILD_UUID"
  51         EnvStderrPrefix = "REDO_STDERR_PREFIX"
  52         EnvTrace        = "REDO_TRACE"
  53         EnvStderrKeep   = "REDO_LOGS"
  54         EnvStderrSilent = "REDO_SILENT"
  55         EnvNoSync       = "REDO_NO_SYNC"
  56         EnvStopIfMod    = "REDO_STOP_IF_MODIFIED"
  57
  58         RedoDir      = ".redo"
  59         LockSuffix   = ".lock"
  60         DepSuffix    = ".rec"
  61         TmpPrefix    = ".redo."
  62         LogSuffix    = ".log"
  63         LogRecSuffix = ".log-rec"
  64 )
  65
  66 var (
  67         NoSync       = false
  68         StderrKeep   = false
  69         StderrSilent = false
  70         StderrPrefix string
  71         StopIfMod    = false
  72         Jobs         sync.WaitGroup
  73
  74         flagTrace          *bool
  75         flagTraceAll       *bool
  76         flagStderrKeep     *bool
  77         flagStderrSilent   *bool
  78         flagForcedIfchange *bool
  79
  80         TracedAll bool
  81
  82         RunningProcs  = map[int]*os.Process{}
  83         RunningProcsM sync.Mutex
  84
  85         Err1WasTouched = errors.New("$1 was explicitly touched")
  86 )
  87
  88 func init() {
  89         cmdName := CmdName()
  90         if !(cmdName == CmdNameRedo || cmdName == CmdNameRedoIfchange) {
  91                 return
  92         }
  93         flagTrace = flag.Bool("x", false, "trace (sh -x) current targets")
  94         flagTraceAll = flag.Bool("xx", false,
  95                 fmt.Sprintf("trace (sh -x) all targets (%s=1)", EnvTrace))
  96         flagStderrKeep = flag.Bool("k", false,
  97                 fmt.Sprintf("keep job's stderr (%s=1)", EnvStderrKeep))
  98         flagStderrSilent = flag.Bool("s", false,
  99                 fmt.Sprintf("silent, do not print job's stderr (%s=1)", EnvStderrSilent))
 100         flagForcedIfchange = flag.Bool("f", false, "forced redo-ifchange")
 101 }
 102
 103 type RunError struct {
 104         Tgt      *Tgt
 105         DoFile   string
 106         Started  *time.Time
 107         Finished *time.Time
 108         Err      error
 109 }
 110
 111 func (e *RunError) Name() string {
 112         var name string
 113         if e.DoFile == "" {
 114                 name = e.Tgt.rel
 115         } else {
 116                 name = fmt.Sprintf("%s (%s)", e.Tgt, e.DoFile)
 117         }
 118         if e.Finished == nil {
 119                 return name
 120         }
 121         return fmt.Sprintf("%s (%.3fs)", name, e.Finished.Sub(*e.Started).Seconds())
 122 }
 123
 124 func (e RunError) Error() string {
 125         return fmt.Sprintf("%s: %s", e.Name(), e.Err)
 126 }
 127
 128 func mkdirs(pth string) error {
 129         if FileExists(pth) {
 130                 return nil
 131         }
 132         return os.MkdirAll(pth, os.FileMode(0777))
 133 }
 134
 135 func isModified(dep *Dep, tgt *Tgt) (
 136         modified bool, ourInode *Inode, hshPrev Hash, err error,
 137 ) {
 138         if dep == nil {
 139                 return
 140         }
 141         for _, ifchange := range dep.ifchanges {
 142                 if ifchange.tgt.a != tgt.a {
 143                         continue
 144                 }
 145                 ourInode, err = inodeFromFileByPath(tgt.a)
 146                 if err != nil {
 147                         if os.IsNotExist(err) {
 148                                 err = nil
 149                                 return
 150                         }
 151                         err = ErrLine(err)
 152                         return
 153                 }
 154                 hshPrev = dep.hash
 155                 modified = !ourInode.Equals(dep.inode)
 156                 break
 157         }
 158         return
 159 }
 160
 161 func syncDir(dir string) error {
 162         fd, err := os.Open(dir)
 163         if err != nil {
 164                 return err
 165         }
 166         err = fd.Sync()
 167         fd.Close()
 168         return err
 169 }
 170
 171 func runScript(tgt *Tgt, errs chan error, forced, traced bool) error {
 172         redoDir := path.Join(tgt.h, RedoDir)
 173         if err := mkdirs(redoDir); err != nil {
 174                 return TgtError{tgt, ErrLine(err)}
 175         }
 176
 177         shCtx := fmt.Sprintf("sh: %s: cwd:%s", tgt, tgt.h)
 178         jsToken := jsAcquire(shCtx)
 179         jsNeedsRelease := true
 180         defer func() {
 181                 if jsNeedsRelease {
 182                         jsRelease(shCtx, jsToken)
 183                 }
 184         }()
 185
 186         // Acquire lock
 187         fdLock, err := os.OpenFile(
 188                 path.Join(redoDir, tgt.t+LockSuffix),
 189                 os.O_WRONLY|os.O_TRUNC|os.O_CREATE,
 190                 os.FileMode(0666),
 191         )
 192         if err != nil {
 193                 return TgtError{tgt, ErrLine(err)}
 194         }
 195         flock := unix.Flock_t{
 196                 Type:   unix.F_WRLCK,
 197                 Whence: io.SeekStart,
 198         }
 199         lockRelease := func() {
 200                 tracef(CLock, "LOCK_UN: %s", fdLock.Name())
 201                 flock.Type = unix.F_UNLCK
 202                 if err := unix.FcntlFlock(fdLock.Fd(), unix.F_SETLK, &flock); err != nil {
 203                         log.Fatalln(err, fdLock.Name())
 204                 }
 205                 fdLock.Close()
 206         }
 207         tracef(CLock, "LOCK_NB: %s", fdLock.Name())
 208
 209         // Waiting for job completion, already taken by someone else
 210         if err = unix.FcntlFlock(fdLock.Fd(), unix.F_SETLK, &flock); err != nil {
 211                 if uintptr(err.(syscall.Errno)) != uintptr(unix.EAGAIN) {
 212                         fdLock.Close()
 213                         return TgtError{tgt, ErrLine(err)}
 214                 }
 215                 Jobs.Add(1)
 216                 if err = unix.FcntlFlock(fdLock.Fd(), unix.F_GETLK, &flock); err != nil {
 217                         log.Fatalln(err, fdLock.Name())
 218                 }
 219                 tracef(CDebug, "waiting: %s (pid=%d)", tgt, flock.Pid)
 220                 if FdStatus != nil {
 221                         if _, err = FdStatus.Write([]byte{StatusWait}); err != nil {
 222                                 log.Fatal(err)
 223                         }
 224                 }
 225                 go func() {
 226                         defer Jobs.Done()
 227                         tracef(CLock, "LOCK_EX: %s", fdLock.Name())
 228                 LockAgain:
 229                         if err := unix.FcntlFlock(fdLock.Fd(), unix.F_SETLKW, &flock); err != nil {
 230                                 if errors.Is(err, unix.EDEADLK) {
 231                                         time.Sleep(10 * time.Millisecond)
 232                                         goto LockAgain
 233                                 }
 234                                 log.Fatalln(err, fdLock.Name())
 235                         }
 236                         lockRelease()
 237                         tracef(CDebug, "waiting done: %s", tgt)
 238                         if FdStatus != nil {
 239                                 if _, err = FdStatus.Write([]byte{StatusWaited}); err != nil {
 240                                         log.Fatal(err)
 241                                 }
 242                         }
 243                         build, err := depReadBuild(tgt.Dep())
 244                         if err == nil {
 245                                 if build != BuildUUID {
 246                                         err = errors.New("was not built: build differs")
 247                                 }
 248                         } else {
 249                                 if errors.Is(err, fs.ErrNotExist) {
 250                                         err = errors.New("was not built: no .rec")
 251                                 }
 252                         }
 253                         if err != nil {
 254                                 err = TgtError{tgt, err}
 255                         }
 256                         errs <- err
 257                 }()
 258                 return nil
 259         }
 260
 261         // It scans the whole .rec file while searching for the single target,
 262         // but that one is always located at the very end
 263         dep, err := depRead(tgt)
 264         if err != nil {
 265                 if errors.Is(err, fs.ErrNotExist) {
 266                         err = nil
 267                 } else {
 268                         lockRelease()
 269                         return TgtError{tgt, ErrLine(err)}
 270                 }
 271         }
 272
 273         // Check if it was already built in parallel
 274         if !forced && dep != nil && dep.build == BuildUUID {
 275                 lockRelease()
 276                 errs <- nil
 277                 return nil
 278         }
 279
 280         // Check if target is not modified externally
 281         modified, inodePrev, hshPrev, err := isModified(dep, tgt)
 282         if err != nil {
 283                 lockRelease()
 284                 return TgtError{tgt, ErrLine(err)}
 285         }
 286         if modified {
 287                 lockRelease()
 288                 if StopIfMod {
 289                         return fmt.Errorf("%s externally modified", tgt)
 290                 }
 291                 tracef(CWarn, "%s externally modified: not redoing", tgt)
 292                 go func() {
 293                         errs <- nil
 294                 }()
 295                 return nil
 296         }
 297         dep = nil
 298
 299         // Start preparing .rec
 300         fdDep, err := tempfile(redoDir, tgt.t+DepSuffix)
 301         if err != nil {
 302                 lockRelease()
 303                 return TgtError{tgt, ErrLine(err)}
 304         }
 305         fdDepOpened := true
 306         fdDepExists := true
 307         cleanup := func() {
 308                 lockRelease()
 309                 if fdDepOpened {
 310                         fdDep.Close()
 311                 }
 312                 if fdDepExists {
 313                         os.Remove(fdDep.Name())
 314                 }
 315         }
 316         if _, err = recfile.NewWriter(fdDep).WriteFields(
 317                 recfile.Field{Name: "Build", Value: BuildUUID},
 318         ); err != nil {
 319                 cleanup()
 320                 return TgtError{tgt, ErrLine(err)}
 321         }
 322
 323         var cwd string
 324         var dirPrefix string
 325         var doFile *Tgt
 326         basename := tgt.t
 327         runErr := RunError{Tgt: tgt}
 328         // Determine basename and DIRPREFIX
 329         {
 330                 doFileRelPath, upLevels, err := findDo(fdDep, tgt.h, tgt.t)
 331                 if err != nil {
 332                         cleanup()
 333                         return TgtError{tgt, ErrLine(err)}
 334                 }
 335                 if doFileRelPath == "" {
 336                         cleanup()
 337                         return TgtError{tgt, errors.New("no .do found")}
 338                 }
 339                 // ents := strings.Split(strings.TrimSuffix(tgt.h, "/"), "/")
 340                 ents := strings.Split(tgt.h, "/")
 341                 ents = ents[len(ents)-upLevels:]
 342                 dirPrefix = path.Join(ents...)
 343                 ups := make([]string, 0, upLevels+2)
 344                 ups = append(ups, tgt.h)
 345                 for i := 0; i < upLevels; i++ {
 346                         ups = append(ups, "..")
 347                 }
 348                 ups = append(ups, doFileRelPath)
 349                 cwd = path.Clean(path.Join(ups[:len(ups)-1]...))
 350                 doFile = NewTgt(path.Join(ups...))
 351                 if strings.HasPrefix(doFile.t, "default.") {
 352                         basename = basename[:len(basename)-(len(doFile.t)-len("default.")-len(".do"))-1]
 353                         runErr.DoFile = doFile.rel
 354                 }
 355         }
 356
 357         if err = depWrite(fdDep, tgt.h, doFile, ""); err != nil {
 358                 cleanup()
 359                 return TgtError{tgt, ErrLine(err)}
 360         }
 361         fdDep.Close()
 362         fdDepOpened = false
 363         tracef(CWait, "%s", runErr.Name())
 364
 365         // Prepare command line
 366         var cmdName string
 367         var args []string
 368         if err = unix.Access(doFile.rel, unix.X_OK); err == nil {
 369                 cmdName = doFile.t
 370                 args = make([]string, 0, 3)
 371         } else {
 372                 cmdName = "/bin/sh"
 373                 if traced || TracedAll {
 374                         args = append(args, "-ex")
 375                 } else {
 376                         args = append(args, "-e")
 377                 }
 378                 args = append(args, doFile.t)
 379         }
 380
 381         // Temporary file for stdout
 382         fdStdout, err := tempfile(tgt.h, tgt.t)
 383         if err != nil {
 384                 cleanup()
 385                 return TgtError{tgt, ErrLine(err)}
 386         }
 387         fdStdout.Close()
 388         tmpPath := fdStdout.Name() + ".3" // and for $3
 389         tmpPathRel := mustRel(cwd, tmpPath)
 390         args = append(
 391                 args,
 392                 path.Join(dirPrefix, tgt.t),
 393                 path.Join(dirPrefix, basename),
 394                 tmpPathRel,
 395         )
 396         shCtx = fmt.Sprintf(
 397                 "sh: %s: %s %s cwd:%s dirprefix:%s",
 398                 tgt, cmdName, args, cwd, dirPrefix,
 399         )
 400
 401         cmd := exec.Command(cmdName, args...)
 402         cmd.Dir = cwd
 403         // cmd.Stdin reads from /dev/null by default
 404         cmd.Env = append(os.Environ(), fmt.Sprintf("%s=%d", EnvLevel, Level+1))
 405         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", EnvDirPrefix, dirPrefix))
 406         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", EnvBuildUUID, BuildUUID))
 407
 408         childStderrPrefixRaw := make([]byte, 8)
 409         if _, err = io.ReadFull(rand.Reader, childStderrPrefixRaw); err != nil {
 410                 panic(err)
 411         }
 412         childStderrPrefix := hex.EncodeToString(childStderrPrefixRaw)
 413         cmd.Env = append(cmd.Env, fmt.Sprintf(
 414                 "%s=%s", EnvStderrPrefix, childStderrPrefix,
 415         ))
 416
 417         fdNum := 0
 418         cmd.ExtraFiles = append(cmd.ExtraFiles, FdOODTgts)
 419         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvOODTgtsFd, 3+fdNum))
 420         fdNum++
 421         cmd.ExtraFiles = append(cmd.ExtraFiles, FdOODTgtsLock)
 422         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvOODTgtsLockFd, 3+fdNum))
 423         fdNum++
 424
 425         if FdStatus == nil {
 426                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=NO", EnvStatusFd))
 427         } else {
 428                 cmd.ExtraFiles = append(cmd.ExtraFiles, FdStatus)
 429                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvStatusFd, 3+fdNum))
 430                 fdNum++
 431         }
 432
 433         // Preparing stderr
 434         var fdStderr *os.File
 435         if StderrKeep {
 436                 fdStderr, err = os.OpenFile(
 437                         path.Join(redoDir, tgt.t+LogSuffix),
 438                         os.O_WRONLY|os.O_CREATE|os.O_TRUNC,
 439                         os.FileMode(0666),
 440                 )
 441                 if err != nil {
 442                         cleanup()
 443                         return TgtError{tgt, ErrLine(err)}
 444                 }
 445         }
 446         tracef(CDebug, "%s", shCtx)
 447
 448         jsNeedsRelease = false
 449         Jobs.Add(1)
 450         go func() {
 451                 if JSR == nil {
 452                         // infinite jobs
 453                         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=NO", EnvJobs))
 454                 } else {
 455                         cmd.ExtraFiles = append(cmd.ExtraFiles, JSR)
 456                         cmd.ExtraFiles = append(cmd.ExtraFiles, JSW)
 457                         makeFlags := fmt.Sprintf(
 458                                 "%s %s%d,%d", MakeFlags, MakeJSArg, 3+fdNum+0, 3+fdNum+1,
 459                         )
 460                         makeFlags = strings.Trim(makeFlags, " ")
 461                         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", MakeFlagsName, makeFlags))
 462                         fdNum += 2
 463                         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvJSToken, jsToken))
 464                 }
 465
 466                 if FdStatus != nil {
 467                         if _, err = FdStatus.Write([]byte{StatusRun}); err != nil {
 468                                 log.Fatal(err)
 469                         }
 470                 }
 471
 472                 defer jsRelease(shCtx, jsToken)
 473
 474                 var finished time.Time
 475                 var exitErr *exec.ExitError
 476                 started := time.Now()
 477                 runErr.Started = &started
 478                 fdStdout, err = os.OpenFile(fdStdout.Name(), os.O_RDWR, os.FileMode(0666))
 479                 if err != nil {
 480                         if fdStderr != nil {
 481                                 fdStderr.Close()
 482                         }
 483                         runErr.Err = err
 484                         errs <- runErr
 485                         return
 486                 }
 487                 cmd.Stdout = fdStdout
 488                 fdDep, err = os.OpenFile(fdDep.Name(), os.O_WRONLY|os.O_APPEND, os.FileMode(0666))
 489                 if err != nil {
 490                         if fdStderr != nil {
 491                                 fdStderr.Close()
 492                         }
 493                         fdStdout.Close()
 494                         runErr.Err = err
 495                         errs <- runErr
 496                         return
 497                 }
 498                 fdDepOpened = true
 499                 cmd.ExtraFiles = append(cmd.ExtraFiles, fdDep)
 500                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvDepFd, 3+fdNum))
 501                 fdNum++
 502                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", EnvDepCwd, cwd))
 503
 504                 defer func() {
 505                         if fdDepOpened {
 506                                 fdDep.Close()
 507                         }
 508                         fdStdout.Close()
 509                         if fdStderr != nil {
 510                                 fdStderr.Close()
 511                                 logRecPath := path.Join(redoDir, tgt.t+LogRecSuffix)
 512                                 if fdStderr, err = os.OpenFile(
 513                                         logRecPath,
 514                                         os.O_WRONLY|os.O_CREATE|os.O_TRUNC,
 515                                         os.FileMode(0666),
 516                                 ); err == nil {
 517                                         fields := []recfile.Field{
 518                                                 {Name: "Build", Value: BuildUUID},
 519                                                 {Name: "PPID", Value: strconv.Itoa(os.Getpid())},
 520                                                 {Name: "Cwd", Value: cwd},
 521                                         }
 522                                         if cmd.Process != nil {
 523                                                 fields = append(fields, recfile.Field{
 524                                                         Name: "PID", Value: strconv.Itoa(cmd.Process.Pid),
 525                                                 })
 526                                         }
 527                                         ts := new(tai64n.TAI64N)
 528                                         ts.FromTime(started)
 529                                         fields = append(fields,
 530                                                 recfile.Field{Name: "Started", Value: tai64n.Encode(ts[:])},
 531                                         )
 532                                         ts.FromTime(finished)
 533                                         fields = append(fields,
 534                                                 recfile.Field{Name: "Finished", Value: tai64n.Encode(ts[:])})
 535                                         fields = append(fields, recfile.Field{
 536                                                 Name:  "Duration",
 537                                                 Value: strconv.FormatInt(finished.Sub(started).Nanoseconds(), 10),
 538                                         })
 539                                         fields = append(fields, recfile.Field{Name: "Cmd", Value: cmdName})
 540                                         for _, arg := range args {
 541                                                 fields = append(fields, recfile.Field{Name: "Arg", Value: arg})
 542                                         }
 543                                         for _, env := range cmd.Env {
 544                                                 fields = append(fields, recfile.Field{Name: "Env", Value: env})
 545                                         }
 546                                         if exitErr != nil {
 547                                                 fields = append(fields, recfile.Field{
 548                                                         Name:  "ExitCode",
 549                                                         Value: strconv.Itoa(exitErr.ProcessState.ExitCode()),
 550                                                 })
 551                                         }
 552
 553                                         w := bufio.NewWriter(fdStderr)
 554                                         {
 555                                                 var ifchanges []string
 556                                                 ifchanges, err = depReadOnlyIfchanges(tgt.Dep())
 557                                                 if err != nil {
 558                                                         err = ErrLine(err)
 559                                                         goto Err
 560                                                 }
 561                                                 for _, ifchange := range ifchanges {
 562                                                         fields = append(fields, recfile.Field{
 563                                                                 Name:  "Ifchange",
 564                                                                 Value: ifchange,
 565                                                         })
 566                                                 }
 567                                         }
 568                                         _, err = recfile.NewWriter(w).WriteFields(fields...)
 569                                         if err != nil {
 570                                                 err = ErrLine(err)
 571                                                 goto Err
 572                                         }
 573                                         err = ErrLine(w.Flush())
 574                                 Err:
 575                                         if err != nil {
 576                                                 log.Print(err)
 577                                                 os.Remove(logRecPath)
 578                                         }
 579                                         fdStderr.Close()
 580                                 } else {
 581                                         log.Println("can not open", logRecPath, ":", err)
 582                                 }
 583                         }
 584                         lockRelease()
 585                         if fdDepExists {
 586                                 os.Remove(fdDep.Name())
 587                         }
 588                         os.Remove(fdStdout.Name())
 589                         os.Remove(tmpPath)
 590                         if FdStatus != nil {
 591                                 if _, err = FdStatus.Write([]byte{StatusDone}); err != nil {
 592                                         log.Fatal(err)
 593                                 }
 594                         }
 595                         Jobs.Done()
 596                 }()
 597                 stderr, err := cmd.StderrPipe()
 598                 if err != nil {
 599                         runErr.Err = err
 600                         errs <- runErr
 601                         return
 602                 }
 603                 started = time.Now()
 604                 err = cmd.Start()
 605                 if err != nil {
 606                         runErr.Err = err
 607                         errs <- runErr
 608                         return
 609                 }
 610                 RunningProcsM.Lock()
 611                 RunningProcs[cmd.Process.Pid] = cmd.Process
 612                 RunningProcsM.Unlock()
 613                 pid := fmt.Sprintf("[%d]", cmd.Process.Pid)
 614                 tracef(CDebug, "%s runs %s", tgt, pid)
 615
 616                 stderrTerm := make(chan struct{})
 617                 go func() {
 618                         scanner := bufio.NewScanner(stderr)
 619                         var line string
 620                         ts := new(tai64n.TAI64N)
 621                         for scanner.Scan() {
 622                                 line = scanner.Text()
 623                                 if strings.HasPrefix(line, childStderrPrefix) {
 624                                         line = line[len(childStderrPrefix):]
 625                                         os.Stderr.WriteString(StderrPrefix + line + "\n")
 626                                         continue
 627                                 }
 628                                 if fdStderr != nil {
 629                                         ts.FromTime(time.Now())
 630                                         LogMutex.Lock()
 631                                         fmt.Fprintln(fdStderr, tai64n.Encode(ts[:]), line)
 632                                         LogMutex.Unlock()
 633                                 }
 634                                 if StderrSilent {
 635                                         continue
 636                                 }
 637                                 if MyPid == 0 {
 638                                         tracef(CNone, "%s", line)
 639                                 } else {
 640                                         tracef(CNone, "%s %s", pid, line)
 641                                 }
 642                         }
 643                         close(stderrTerm)
 644                 }()
 645
 646                 // Wait for job completion
 647                 <-stderrTerm
 648                 err = cmd.Wait()
 649                 RunningProcsM.Lock()
 650                 delete(RunningProcs, cmd.Process.Pid)
 651                 RunningProcsM.Unlock()
 652                 finished = time.Now()
 653                 runErr.Finished = &finished
 654                 if err != nil {
 655                         exitErr = err.(*exec.ExitError)
 656                         runErr.Err = err
 657                         errs <- runErr
 658                         return
 659                 }
 660
 661                 // Was $1 touched?
 662                 if inode, err := inodeFromFileByPath(tgt.a); err == nil {
 663                         if inodePrev == nil {
 664                                 runErr.Err = Err1WasTouched
 665                                 errs <- runErr
 666                                 return
 667                         }
 668                         if !inode.Equals(inodePrev) {
 669                                 runErr.Err = Err1WasTouched
 670                                 errs <- runErr
 671                                 return
 672                         }
 673                 }
 674
 675                 // Does it produce both stdout and tmp?
 676                 fiStdout, err := os.Stat(fdStdout.Name())
 677                 if err != nil {
 678                         runErr.Err = ErrLine(err)
 679                         errs <- runErr
 680                         return
 681                 }
 682                 tmpExists := false
 683                 _, err = os.Stat(tmpPath)
 684                 if err == nil {
 685                         if fiStdout.Size() > 0 {
 686                                 runErr.Err = errors.New("created both tmp and stdout")
 687                                 errs <- runErr
 688                                 return
 689                         }
 690                         tmpExists = true
 691                 } else if !errors.Is(err, fs.ErrNotExist) {
 692                         runErr.Err = ErrLine(err)
 693                         errs <- runErr
 694                         return
 695                 }
 696
 697                 // Determine what file we must process at last
 698                 var fd *os.File
 699                 if tmpExists {
 700                         fd, err = os.Open(tmpPath)
 701                         if err != nil {
 702                                 err = ErrLine(err)
 703                                 goto Finish
 704                         }
 705                         defer fd.Close()
 706                 } else if fiStdout.Size() > 0 {
 707                         fd = fdStdout
 708                 }
 709
 710                 // Do we need to ifcreate it, or ifchange with renaming?
 711                 if fd == nil {
 712                         os.Remove(tgt.a)
 713                         err = ifcreate(fdDep, tgt.t)
 714                         if err != nil {
 715                                 err = ErrLine(err)
 716                                 goto Finish
 717                         }
 718                 } else {
 719                         var hsh Hash
 720                         if hshPrev != "" {
 721                                 _, err = fd.Seek(0, io.SeekStart)
 722                                 if err != nil {
 723                                         err = ErrLine(err)
 724                                         goto Finish
 725                                 }
 726                                 hsh, err = fileHash(fd)
 727                                 if err != nil {
 728                                         err = ErrLine(err)
 729                                         goto Finish
 730                                 }
 731                                 if hsh == hshPrev {
 732                                         tracef(CDebug, "%s has same hash, not renaming", tgt)
 733                                         err = ErrLine(os.Remove(fd.Name()))
 734                                         if err != nil {
 735                                                 goto Finish
 736                                         }
 737                                         err = ErrLine(os.Chtimes(tgt.a, finished, finished))
 738                                         if err != nil {
 739                                                 goto Finish
 740                                         }
 741                                         if !NoSync {
 742                                                 err = ErrLine(syncDir(tgt.h))
 743                                                 if err != nil {
 744                                                         goto Finish
 745                                                 }
 746                                         }
 747                                         err = ErrLine(depWrite(fdDep, tgt.h, tgt, hsh))
 748                                         if err != nil {
 749                                                 goto Finish
 750                                         }
 751                                         goto RecCommit
 752                                 }
 753                         }
 754                         if !NoSync {
 755                                 err = ErrLine(fd.Sync())
 756                                 if err != nil {
 757                                         goto Finish
 758                                 }
 759                         }
 760                         err = ErrLine(os.Rename(fd.Name(), tgt.a))
 761                         if err != nil {
 762                                 goto Finish
 763                         }
 764                         if !NoSync {
 765                                 err = ErrLine(syncDir(tgt.h))
 766                                 if err != nil {
 767                                         goto Finish
 768                                 }
 769                         }
 770                         err = ErrLine(depWrite(fdDep, tgt.h, tgt, hsh))
 771                         if err != nil {
 772                                 goto Finish
 773                         }
 774                 }
 775
 776         RecCommit:
 777                 // Commit .rec
 778                 if !NoSync {
 779                         err = ErrLine(fdDep.Sync())
 780                         if err != nil {
 781                                 goto Finish
 782                         }
 783                 }
 784                 err = ErrLine(os.Rename(fdDep.Name(), tgt.Dep()))
 785                 if err != nil {
 786                         goto Finish
 787                 }
 788                 fdDepExists = false
 789                 if !NoSync {
 790                         err = ErrLine(syncDir(redoDir))
 791                         if err != nil {
 792                                 goto Finish
 793                         }
 794                 }
 795                 fdDep.Close()
 796                 fdDepOpened = false
 797
 798                 // Post-commit .rec sanitizing
 799                 dep, err = depRead(tgt)
 800                 if err == nil {
 801                         ifchangeSeen := make(map[string]struct{}, len(dep.ifchanges))
 802                         for _, ifchange := range dep.ifchanges {
 803                                 ifchangeSeen[ifchange.tgt.a] = struct{}{}
 804                         }
 805                         for _, ifcreate := range dep.ifcreates {
 806                                 if _, exists := ifchangeSeen[ifcreate.a]; exists {
 807                                         tracef(CWarn, "simultaneous ifcreate and ifchange records: %s", tgt)
 808                                 }
 809                         }
 810                 } else if errors.Is(err, fs.ErrNotExist) {
 811                         err = nil
 812                 } else {
 813                         err = ErrLine(err)
 814                         goto Finish
 815                 }
 816
 817         Finish:
 818                 runErr.Err = err
 819                 errs <- runErr
 820         }()
 821         return nil
 822 }
 823
 824 func isOkRun(err error) bool {
 825         if err == nil {
 826                 return true
 827         }
 828         var runErr RunError
 829         if errors.As(err, &runErr) && runErr.Err == nil {
 830                 tracef(CRedo, "%s", runErr.Name())
 831                 return true
 832         }
 833         tracef(CErr, "%s", err)
 834         return false
 835 }