From a38c356f7f85b8a2d8c0190f73488f91c83ef078 Mon Sep 17 00:00:00 2001 From: Barnaby Keene Date: Sun, 12 Jul 2020 15:15:07 +0100 Subject: [PATCH] added a "wait status" debug tool (#68) This uses a special function name signature pattern to identify points in the code that are waiting for significant events such as reconfigure and initial clones. These points are logged when the program recieves an interrupt signal. --- main.go | 35 ++++++++++++--------- reconfigurer/git.go | 11 +++++-- watcher/git.go | 77 +++++++++++++++++++++++++-------------------- 3 files changed, 72 insertions(+), 51 deletions(-) diff --git a/main.go b/main.go index 78288c2..a6a348f 100644 --- a/main.go +++ b/main.go @@ -2,9 +2,10 @@ package main import ( "context" - "log" + "fmt" "os" "os/signal" + "regexp" "runtime" "strings" "time" @@ -114,26 +115,32 @@ this repository has new commits, Pico will automatically reconfigure.`, case err = <-errs: } + if strings.ToLower(os.Getenv("LOG_LEVEL")) == "debug" { + doTrace() + } + return }, }, } - if strings.ToLower(os.Getenv("LOG_LEVEL")) == "debug" { - go func() { - sigs := make(chan os.Signal, 1) - signal.Notify(sigs, os.Interrupt) - buf := make([]byte, 1<<20) - for { - <-sigs - stacklen := runtime.Stack(buf, true) - log.Printf("\nPrinting goroutine stack trace because `DEBUG` was set.\n%s\n", buf[:stacklen]) - } - }() - } - err := app.Run(os.Args) if err != nil { zap.L().Fatal("exit", zap.Error(err)) } } + +var waitpoints = regexp.MustCompile(`__waitpoint__(.+)\(`) + +func doTrace() { + buf := make([]byte, 1<<20) + stacklen := runtime.Stack(buf, true) + + fmt.Printf("\nPrinting goroutine stack trace because `DEBUG` was set.\n%s\n", buf[:stacklen]) + fmt.Println("Code that was waiting:") + + for _, s := range waitpoints.FindAllStringSubmatch(string(buf[:stacklen]), 1) { + fmt.Printf(" - %s\n", s[1]) + } + fmt.Println("\nSee the docs on https://pico.sh/ for more information.") +} diff --git a/reconfigurer/git.go b/reconfigurer/git.go index c71747c..fd1b6aa 100644 --- a/reconfigurer/git.go +++ b/reconfigurer/git.go @@ -126,13 +126,18 @@ func (p *GitProvider) watchConfig() (err error) { }() zap.L().Debug("created new config watcher, awaiting setup") + err = p.__waitpoint__watch_config(errs) + + zap.L().Debug("config watcher initialised") + + return +} + +func (p *GitProvider) __waitpoint__watch_config(errs chan error) (err error) { select { case <-p.configWatcher.InitialDone: case err = <-errs: } - - zap.L().Debug("config watcher initialised") - return } diff --git a/watcher/git.go b/watcher/git.go index ccf8d97..7b0a139 100644 --- a/watcher/git.go +++ b/watcher/git.go @@ -60,45 +60,49 @@ func NewGitWatcher( } } -// Start runs the watcher loop and blocks until a fatal error occurs -func (w *GitWatcher) Start() error { - zap.L().Debug("git watcher initialising, waiting for first state to be set") - - // wait for the first config event to set the initial state +func (w *GitWatcher) __waitpoint__start_wait_init() { <-w.initialise +} - zap.L().Debug("git watcher initialised", zap.Any("initial_state", w.state)) - - f := func() (err error) { - select { - case newState := <-w.newState: - zap.L().Debug("git watcher received new state", - zap.Any("new_state", newState)) - - return w.doReconfigure(newState) +func (w *GitWatcher) __waitpoint__start_select_states() (err error) { + select { + case newState := <-w.newState: + zap.L().Debug("git watcher received new state", + zap.Any("new_state", newState)) - case <-w.stateReq: - w.stateRes <- w.state + return w.doReconfigure(newState) - case event := <-w.targetsWatcher.Events: - zap.L().Debug("git watcher received a target event", - zap.Any("new_state", event)) + case <-w.stateReq: + w.stateRes <- w.state - if e := w.handle(event); e != nil { - zap.L().Error("failed to handle event", - zap.String("url", event.URL), - zap.Error(e)) - } + case event := <-w.targetsWatcher.Events: + zap.L().Debug("git watcher received a target event", + zap.Any("new_state", event)) - case e := <-errorMultiplex(w.errors, w.targetsWatcher.Errors): - zap.L().Error("git error", + if e := w.handle(event); e != nil { + zap.L().Error("failed to handle event", + zap.String("url", event.URL), zap.Error(e)) } - return + + case e := <-errorMultiplex(w.errors, w.targetsWatcher.Errors): + zap.L().Error("git error", + zap.Error(e)) } + return +} + +// Start runs the watcher loop and blocks until a fatal error occurs +func (w *GitWatcher) Start() error { + zap.L().Debug("git watcher initialising, waiting for first state to be set") + + // wait for the first config event to set the initial state + w.__waitpoint__start_wait_init() + + zap.L().Debug("git watcher initialised", zap.Any("initial_state", w.state)) for { - err := f() + err := w.__waitpoint__start_select_states() if err != nil { return err } @@ -203,13 +207,18 @@ func (w *GitWatcher) watchTargets() (err error) { }() zap.L().Debug("created targets watcher, awaiting setup") + err = w.__waitpoint__watch_targets(errs) + + zap.L().Debug("targets watcher initialised") + + return +} + +func (w *GitWatcher) __waitpoint__watch_targets(errs chan error) (err error) { select { case <-w.targetsWatcher.InitialDone: case err = <-errs: } - - zap.L().Debug("targets watcher initialised") - return } @@ -222,7 +231,7 @@ func (w *GitWatcher) handle(e gitwatch.Event) (err error) { zap.String("target", target.Name), zap.String("url", target.RepoURL), zap.Time("timestamp", e.Timestamp)) - w.send(target, e.Path, false) + w.__waitpoint__send_target_task(target, e.Path, false) return nil } @@ -257,7 +266,7 @@ func (w GitWatcher) executeTargets(targets []task.Target, shutdown bool) { zap.Int("targets", len(targets))) for _, t := range targets { - w.send(t, filepath.Join(w.directory, t.Name), shutdown) + w.__waitpoint__send_target_task(t, filepath.Join(w.directory, t.Name), shutdown) } } @@ -270,7 +279,7 @@ func (w GitWatcher) getTarget(url string) (target task.Target, exists bool) { return } -func (w GitWatcher) send(target task.Target, path string, shutdown bool) { +func (w GitWatcher) __waitpoint__send_target_task(target task.Target, path string, shutdown bool) { w.bus <- task.ExecutionTask{ Target: target, Path: path,