]> Cypherpunks.ru repositories - goredo.git/blob - run.go
Recursive serialized logs capability
[goredo.git] / run.go
1 /*
2 goredo -- djb's redo implementation on pure Go
3 Copyright (C) 2020-2021 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         "errors"
25         "flag"
26         "fmt"
27         "io"
28         "os"
29         "os/exec"
30         "path"
31         "path/filepath"
32         "strconv"
33         "strings"
34         "sync"
35         "syscall"
36         "time"
37
38         "go.cypherpunks.ru/recfile"
39         "go.cypherpunks.ru/tai64n/v2"
40         "golang.org/x/sys/unix"
41 )
42
43 const (
44         EnvDepFd        = "REDO_DEP_FD"
45         EnvDirPrefix    = "REDO_DIRPREFIX"
46         EnvDepCwd       = "REDO_DEP_CWD"
47         EnvBuildUUID    = "REDO_BUILD_UUID"
48         EnvStderrPrefix = "REDO_STDERR_PREFIX"
49         EnvTrace        = "REDO_TRACE"
50         EnvStderrKeep   = "REDO_LOGS"
51         EnvStderrSilent = "REDO_SILENT"
52         EnvNoSync       = "REDO_NO_SYNC"
53
54         RedoDir    = ".redo"
55         LockSuffix = ".lock"
56         DepSuffix  = ".rec"
57         TmpPrefix  = ".redo."
58         LogSuffix  = ".log"
59 )
60
61 var (
62         NoSync       bool = false
63         StderrKeep   bool = false
64         StderrSilent bool = false
65         StderrPrefix string
66         Jobs         sync.WaitGroup
67
68         flagTrace        *bool
69         flagTraceAll     *bool
70         flagStderrKeep   *bool
71         flagStderrSilent *bool
72
73         TracedAll bool
74 )
75
76 func init() {
77         cmdName := CmdName()
78         if !(cmdName == CmdNameRedo || cmdName == CmdNameRedoIfchange) {
79                 return
80         }
81         flagTrace = flag.Bool("x", false, "trace (sh -x) current targets")
82         flagTraceAll = flag.Bool("xx", false,
83                 fmt.Sprintf("trace (sh -x) all targets (%s=1)", EnvTrace))
84         flagStderrKeep = flag.Bool("k", false,
85                 fmt.Sprintf("keep job's stderr (%s=1)", EnvStderrKeep))
86         flagStderrSilent = flag.Bool("s", false,
87                 fmt.Sprintf("silent, do not print job's stderr (%s=1)", EnvStderrSilent))
88 }
89
90 type RunErr struct {
91         Tgt      string
92         DoFile   string
93         Started  *time.Time
94         Finished *time.Time
95         Err      error
96 }
97
98 func (e *RunErr) Name() string {
99         var name string
100         if e.DoFile == "" {
101                 name = e.Tgt
102         } else {
103                 name = fmt.Sprintf("%s (%s)", e.Tgt, e.DoFile)
104         }
105         if e.Finished == nil {
106                 return name
107         }
108         return fmt.Sprintf("%s (%.3fs)", name, e.Finished.Sub(*e.Started).Seconds())
109 }
110
111 func (e RunErr) Error() string {
112         return fmt.Sprintf("%s: %s", e.Name(), e.Err)
113 }
114
115 func mkdirs(pth string) error {
116         if _, err := os.Stat(pth); err == nil {
117                 return nil
118         }
119         return os.MkdirAll(pth, os.FileMode(0777))
120 }
121
122 func isModified(cwd, redoDir, tgt string) (bool, *Inode, error) {
123         fdDep, err := os.Open(path.Join(redoDir, tgt+DepSuffix))
124         if err != nil {
125                 if os.IsNotExist(err) {
126                         return false, nil, nil
127                 }
128                 return false, nil, err
129         }
130         defer fdDep.Close()
131         r := recfile.NewReader(fdDep)
132         var ourInode *Inode
133         for {
134                 m, err := r.NextMap()
135                 if err != nil {
136                         if err == io.EOF {
137                                 break
138                         }
139                         return false, nil, err
140                 }
141                 if m["Target"] != tgt {
142                         continue
143                 }
144                 fd, err := os.Open(path.Join(cwd, tgt))
145                 if err != nil {
146                         if os.IsNotExist(err) {
147                                 return false, nil, nil
148                         }
149                         return false, nil, err
150                 }
151                 ourInode, err = inodeFromFile(fd)
152                 fd.Close()
153                 if err != nil {
154                         return false, nil, err
155                 }
156                 theirInode, err := inodeFromRec(m)
157                 if err != nil {
158                         return false, nil, err
159                 }
160                 if !ourInode.Equals(theirInode) {
161                         return true, ourInode, nil
162                 }
163                 break
164         }
165         return false, ourInode, nil
166 }
167
168 func syncDir(dir string) error {
169         fd, err := os.Open(dir)
170         if err != nil {
171                 return err
172         }
173         err = fd.Sync()
174         fd.Close()
175         return err
176 }
177
178 func runScript(tgtOrig string, errs chan error, traced bool) error {
179         cwd, tgt := cwdAndTgt(tgtOrig)
180         redoDir := path.Join(cwd, RedoDir)
181         if err := mkdirs(redoDir); err != nil {
182                 return TgtErr{tgtOrig, err}
183         }
184
185         // Acquire lock
186         fdLock, err := os.OpenFile(
187                 path.Join(redoDir, tgt+LockSuffix),
188                 os.O_WRONLY|os.O_TRUNC|os.O_CREATE,
189                 os.FileMode(0666),
190         )
191         if err != nil {
192                 return TgtErr{tgtOrig, err}
193         }
194         lockRelease := func() {
195                 trace(CLock, "LOCK_UN: %s", fdLock.Name())
196                 unix.Flock(int(fdLock.Fd()), unix.LOCK_UN)
197                 fdLock.Close()
198         }
199         trace(CLock, "LOCK_NB: %s", fdLock.Name())
200
201         // Waiting for job completion, already taken by someone else
202         if err = unix.Flock(int(fdLock.Fd()), unix.LOCK_EX|unix.LOCK_NB); err != nil {
203                 if uintptr(err.(syscall.Errno)) != uintptr(unix.EWOULDBLOCK) {
204                         fdLock.Close()
205                         return TgtErr{tgtOrig, err}
206                 }
207                 Jobs.Add(1)
208                 trace(CDebug, "waiting: %s", tgtOrig)
209                 if FdStatus != nil {
210                         FdStatus.Write([]byte{StatusWait})
211                 }
212                 go func() {
213                         defer Jobs.Done()
214                         trace(CLock, "LOCK_EX: %s", fdLock.Name())
215                         unix.Flock(int(fdLock.Fd()), unix.LOCK_EX)
216                         lockRelease()
217                         trace(CDebug, "waiting done: %s", tgtOrig)
218                         if FdStatus != nil {
219                                 FdStatus.Write([]byte{StatusWaited})
220                         }
221                         var depInfo *DepInfo
222                         fdDep, err := os.Open(path.Join(redoDir, tgt+DepSuffix))
223                         if err != nil {
224                                 if os.IsNotExist(err) {
225                                         err = errors.New("was not built: no .rec")
226                                 }
227                                 goto Finish
228                         }
229                         defer fdDep.Close()
230                         depInfo, err = depRead(fdDep)
231                         if err != nil {
232                                 goto Finish
233                         }
234                         if depInfo.build != BuildUUID {
235                                 err = errors.New("was not built: build differs")
236                         }
237                 Finish:
238                         if err != nil {
239                                 err = TgtErr{tgtOrig, err}
240                         }
241                         errs <- err
242                 }()
243                 return nil
244         }
245
246         // Check if target is not modified externally
247         modified, inodePrev, err := isModified(cwd, redoDir, tgt)
248         if err != nil {
249                 lockRelease()
250                 return TgtErr{tgtOrig, err}
251         }
252         if modified {
253                 trace(CWarn, "%s externally modified: not redoing", tgtOrig)
254                 lockRelease()
255                 go func() {
256                         errs <- nil
257                 }()
258                 return nil
259         }
260
261         // Start preparing .rec
262         fdDep, err := tempfile(redoDir, tgt+DepSuffix)
263         if err != nil {
264                 lockRelease()
265                 return TgtErr{tgtOrig, err}
266         }
267         fdDepPath := fdDep.Name()
268         cleanup := func() {
269                 lockRelease()
270                 fdDep.Close()
271                 os.Remove(fdDep.Name())
272         }
273         if _, err = recfile.NewWriter(fdDep).WriteFields(
274                 recfile.Field{Name: "Build", Value: BuildUUID},
275         ); err != nil {
276                 cleanup()
277                 return TgtErr{tgtOrig, err}
278         }
279
280         // Find .do
281         doFile, upLevels, err := findDo(fdDep, cwd, tgt)
282         if err != nil {
283                 cleanup()
284                 return TgtErr{tgtOrig, err}
285         }
286         if doFile == "" {
287                 cleanup()
288                 return TgtErr{tgtOrig, errors.New("no .do found")}
289         }
290
291         // Determine basename and DIRPREFIX
292         doFileRelPath := doFile
293         ents := strings.Split(cwd, "/")
294         ents = ents[len(ents)-upLevels:]
295         dirPrefix := path.Join(ents...)
296         cwdOrig := cwd
297         for i := 0; i < upLevels; i++ {
298                 cwd = path.Join(cwd, "..")
299                 doFileRelPath = path.Join("..", doFileRelPath)
300         }
301         cwd = path.Clean(cwd)
302         doFilePath := path.Join(cwd, doFile)
303         basename := tgt
304         runErr := RunErr{Tgt: tgtOrig}
305         if strings.HasPrefix(doFile, "default.") {
306                 basename = tgt[:len(tgt)-(len(doFile)-len("default.")-len(".do"))-1]
307                 runErr.DoFile = doFileRelPath
308         }
309
310         if err = writeDep(fdDep, cwdOrig, doFileRelPath); err != nil {
311                 cleanup()
312                 return TgtErr{tgtOrig, err}
313         }
314         fdDep.Close()
315         trace(CWait, "%s", runErr.Name())
316
317         // Prepare command line
318         var cmdName string
319         var args []string
320         if err = unix.Access(doFilePath, unix.X_OK); err == nil {
321                 cmdName = doFilePath
322                 args = make([]string, 0, 3)
323         } else {
324                 cmdName = "/bin/sh"
325                 if traced || TracedAll {
326                         args = append(args, "-ex")
327                 } else {
328                         args = append(args, "-e")
329                 }
330                 args = append(args, doFile)
331         }
332
333         // Temporary file for stdout
334         fdStdout, err := tempfile(cwdOrig, tgt)
335         if err != nil {
336                 cleanup()
337                 return TgtErr{tgtOrig, err}
338         }
339         stdoutPath := fdStdout.Name()
340         fdStdout.Close()
341         tmpPath := stdoutPath + ".3" // and for $3
342         tmpPathRel, err := filepath.Rel(cwd, tmpPath)
343         if err != nil {
344                 panic(err)
345         }
346         args = append(
347                 args,
348                 path.Join(dirPrefix, tgt),
349                 path.Join(dirPrefix, basename),
350                 tmpPathRel,
351         )
352
353         cmd := exec.Command(cmdName, args...)
354         cmd.Dir = cwd
355         // cmd.Stdin reads from /dev/null by default
356         cmd.Env = append(os.Environ(), fmt.Sprintf("%s=%d", EnvLevel, Level+1))
357         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", EnvDirPrefix, dirPrefix))
358         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", EnvBuildUUID, BuildUUID))
359
360         childStderrPrefix := tempsuffix()
361         cmd.Env = append(cmd.Env, fmt.Sprintf(
362                 "%s=%s", EnvStderrPrefix, childStderrPrefix,
363         ))
364
365         fdNum := 0
366         cmd.ExtraFiles = append(cmd.ExtraFiles, FdOODTgts)
367         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvOODTgtsFd, 3+fdNum))
368         fdNum++
369         cmd.ExtraFiles = append(cmd.ExtraFiles, FdOODTgtsLock)
370         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvOODTgtsLockFd, 3+fdNum))
371         fdNum++
372
373         if FdStatus == nil {
374                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=NO", EnvStatusFd))
375         } else {
376                 cmd.ExtraFiles = append(cmd.ExtraFiles, FdStatus)
377                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvStatusFd, 3+fdNum))
378                 fdNum++
379         }
380
381         // Preparing stderr
382         var fdStderr *os.File
383         if StderrKeep {
384                 fdStderr, err = os.OpenFile(
385                         path.Join(redoDir, tgt+LogSuffix),
386                         os.O_WRONLY|os.O_CREATE,
387                         os.FileMode(0666),
388                 )
389                 if err != nil {
390                         cleanup()
391                         return TgtErr{tgtOrig, err}
392                 }
393                 fdStderr.Truncate(0)
394         }
395         shCtx := fmt.Sprintf(
396                 "sh: %s: %s %s cwd:%s dirprefix:%s",
397                 tgtOrig, cmdName, args, cwd, dirPrefix,
398         )
399         trace(CDebug, "%s", shCtx)
400
401         Jobs.Add(1)
402         go func() {
403                 jsToken := jsAcquire(shCtx)
404                 if JSR == nil {
405                         // infinite jobs
406                         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=NO", EnvJobs))
407                 } else {
408                         cmd.ExtraFiles = append(cmd.ExtraFiles, JSR)
409                         cmd.ExtraFiles = append(cmd.ExtraFiles, JSW)
410                         cmd.Env = append(cmd.Env, fmt.Sprintf(
411                                 "%s=%s %s%d,%d",
412                                 MakeFlagsName, MakeFlags, MakeJSArg, 3+fdNum+0, 3+fdNum+1,
413                         ))
414                         fdNum += 2
415                         cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvJSToken, jsToken))
416                 }
417
418                 if FdStatus != nil {
419                         FdStatus.Write([]byte{StatusRun})
420                 }
421
422                 var finished time.Time
423                 var exitErr *exec.ExitError
424                 started := time.Now()
425                 runErr.Started = &started
426                 fdStdout, err = os.OpenFile(stdoutPath, os.O_RDWR, os.FileMode(0666))
427                 if err != nil {
428                         runErr.Err = err
429                         errs <- runErr
430                         return
431                 }
432                 cmd.Stdout = fdStdout
433                 fdDep, err = os.OpenFile(fdDepPath, os.O_WRONLY|os.O_APPEND, os.FileMode(0666))
434                 if err != nil {
435                         runErr.Err = err
436                         errs <- runErr
437                         return
438                 }
439                 cmd.ExtraFiles = append(cmd.ExtraFiles, fdDep)
440                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%d", EnvDepFd, 3+fdNum))
441                 fdNum++
442                 cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", EnvDepCwd, cwd))
443
444                 defer func() {
445                         jsRelease(shCtx, jsToken)
446                         fdDep.Close()
447                         fdStdout.Close()
448                         if fdStderr != nil {
449                                 fdStderr.Close()
450                                 logRecPath := path.Join(redoDir, tgt+LogSuffix+DepSuffix)
451                                 if fdStderr, err = os.OpenFile(
452                                         logRecPath,
453                                         os.O_WRONLY|os.O_CREATE,
454                                         os.FileMode(0666),
455                                 ); err == nil {
456                                         fdStderr.Truncate(0)
457                                         fields := []recfile.Field{
458                                                 {Name: "Build", Value: BuildUUID},
459                                                 {Name: "PID", Value: strconv.Itoa(cmd.Process.Pid)},
460                                                 {Name: "PPID", Value: strconv.Itoa(os.Getpid())},
461                                                 {Name: "Cwd", Value: cwd},
462                                         }
463                                         ts := new(tai64n.TAI64N)
464                                         ts.FromTime(started)
465                                         fields = append(fields,
466                                                 recfile.Field{Name: "Started", Value: tai64n.Encode(ts[:])},
467                                         )
468                                         ts.FromTime(finished)
469                                         fields = append(fields,
470                                                 recfile.Field{Name: "Finished", Value: tai64n.Encode(ts[:])})
471                                         fields = append(fields, recfile.Field{
472                                                 Name:  "Duration",
473                                                 Value: strconv.FormatInt(finished.Sub(started).Nanoseconds(), 10),
474                                         })
475                                         fields = append(fields, recfile.Field{Name: "Cmd", Value: cmdName})
476                                         for _, arg := range args {
477                                                 fields = append(fields, recfile.Field{Name: "Cmd", Value: arg})
478                                         }
479                                         for _, e := range cmd.Env {
480                                                 fields = append(fields, recfile.Field{Name: "Env", Value: e})
481                                         }
482                                         if exitErr != nil {
483                                                 fields = append(fields, recfile.Field{
484                                                         Name:  "ExitCode",
485                                                         Value: strconv.Itoa(exitErr.ProcessState.ExitCode()),
486                                                 })
487                                         }
488                                         w := bufio.NewWriter(fdStderr)
489                                         _, err = recfile.NewWriter(w).WriteFields(fields...)
490                                         w.Flush()
491                                         fdStderr.Close()
492                                         if err != nil {
493                                                 os.Remove(logRecPath)
494                                         }
495                                 }
496                         }
497                         lockRelease()
498                         os.Remove(fdDep.Name())
499                         os.Remove(fdStdout.Name())
500                         os.Remove(tmpPath)
501                         os.Remove(fdLock.Name())
502                         if FdStatus != nil {
503                                 FdStatus.Write([]byte{StatusDone})
504                         }
505                         Jobs.Done()
506                 }()
507                 stderr, err := cmd.StderrPipe()
508                 if err != nil {
509                         runErr.Err = err
510                         errs <- runErr
511                         return
512                 }
513                 started = time.Now()
514                 err = cmd.Start()
515                 if err != nil {
516                         runErr.Err = err
517                         errs <- runErr
518                         return
519                 }
520                 pid := fmt.Sprintf("[%d]", cmd.Process.Pid)
521                 trace(CDebug, "%s runs %s", tgtOrig, pid)
522
523                 stderrTerm := make(chan struct{}, 0)
524                 go func() {
525                         scanner := bufio.NewScanner(stderr)
526                         var line string
527                         ts := new(tai64n.TAI64N)
528                         for scanner.Scan() {
529                                 line = scanner.Text()
530                                 if strings.HasPrefix(line, childStderrPrefix) {
531                                         line = line[len(childStderrPrefix):]
532                                         os.Stderr.WriteString(StderrPrefix + line + "\n")
533                                         continue
534                                 }
535                                 if fdStderr != nil {
536                                         ts.FromTime(time.Now())
537                                         LogMutex.Lock()
538                                         fmt.Fprintln(fdStderr, tai64n.Encode(ts[:]), line)
539                                         LogMutex.Unlock()
540                                 }
541                                 if StderrSilent {
542                                         continue
543                                 }
544                                 if MyPid == 0 {
545                                         trace(CNone, "%s", line)
546                                 } else {
547                                         trace(CNone, "%s %s", pid, line)
548                                 }
549                         }
550                         close(stderrTerm)
551                 }()
552
553                 // Wait for job completion
554                 <-stderrTerm
555                 err = cmd.Wait()
556                 finished = time.Now()
557                 runErr.Finished = &finished
558                 if err != nil {
559                         // Try to commit .rec anyway
560                         if !NoSync {
561                                 fdDep.Sync()
562                         }
563                         os.Rename(fdDep.Name(), path.Join(redoDir, tgt+DepSuffix))
564                         if !NoSync {
565                                 err = syncDir(redoDir)
566                         }
567
568                         exitErr = err.(*exec.ExitError)
569                         runErr.Err = err
570                         errs <- runErr
571                         return
572                 }
573
574                 // Was $1 touched?
575                 if inodePrev != nil {
576                         if fd, err := os.Open(path.Join(cwdOrig, tgt)); err == nil {
577                                 inode, err := inodeFromFile(fd)
578                                 fd.Close()
579                                 if err == nil && !inode.Equals(inodePrev) {
580                                         runErr.Err = errors.New("$1 was explicitly touched")
581                                         errs <- runErr
582                                         return
583                                 }
584                         }
585                 }
586
587                 // Does it produce both stdout and tmp?
588                 fiStdout, err := os.Stat(fdStdout.Name())
589                 if err != nil {
590                         runErr.Err = err
591                         errs <- runErr
592                         return
593                 }
594                 tmpExists := false
595                 _, err = os.Stat(tmpPath)
596                 if err == nil {
597                         if fiStdout.Size() > 0 {
598                                 runErr.Err = errors.New("created both tmp and stdout")
599                                 errs <- runErr
600                                 return
601                         }
602                         tmpExists = true
603                 } else if !os.IsNotExist(err) {
604                         runErr.Err = err
605                         errs <- runErr
606                         return
607                 }
608
609                 // Determine what file we must process at last
610                 var fd *os.File
611                 if tmpExists {
612                         fd, err = os.Open(tmpPath)
613                         if err != nil {
614                                 goto Finish
615                         }
616                         defer fd.Close()
617                 } else if fiStdout.Size() > 0 {
618                         fd = fdStdout
619                 }
620
621                 // Do we need to ifcreate it, of ifchange with renaming?
622                 if fd == nil {
623                         os.Remove(path.Join(cwdOrig, tgt))
624                         err = ifcreate(fdDep, tgt)
625                         if err != nil {
626                                 goto Finish
627                         }
628                 } else {
629                         if !NoSync {
630                                 err = fd.Sync()
631                                 if err != nil {
632                                         goto Finish
633                                 }
634                         }
635                         err = os.Rename(fd.Name(), path.Join(cwdOrig, tgt))
636                         if err != nil {
637                                 goto Finish
638                         }
639                         if !NoSync {
640                                 err = syncDir(cwdOrig)
641                                 if err != nil {
642                                         goto Finish
643                                 }
644                         }
645                         err = writeDep(fdDep, cwdOrig, tgt)
646                         if err != nil {
647                                 goto Finish
648                         }
649                 }
650
651                 // Commit .rec
652                 if !NoSync {
653                         err = fdDep.Sync()
654                         if err != nil {
655                                 goto Finish
656                         }
657                 }
658                 err = os.Rename(fdDep.Name(), path.Join(redoDir, tgt+DepSuffix))
659                 if err != nil {
660                         goto Finish
661                 }
662                 if !NoSync {
663                         err = syncDir(redoDir)
664                         if err != nil {
665                                 goto Finish
666                         }
667                 }
668         Finish:
669                 runErr.Err = err
670                 errs <- runErr
671         }()
672         return nil
673 }
674
675 func isOkRun(err error) bool {
676         if err == nil {
677                 return true
678         }
679         if err, ok := err.(RunErr); ok && err.Err == nil {
680                 trace(CRedo, "%s", err.Name())
681                 return true
682         }
683         trace(CErr, "%s", err)
684         return false
685 }