From 9318041657eaa2f56a58f1728f7286bf4b37cfbd Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Fri, 12 May 2023 15:21:07 -0700 Subject: [PATCH] Better logging around hooks This also returns stderr distinct from stdout. --- main.go | 48 ++++++++++++++++++++++---------------------- pkg/cmd/cmd.go | 12 +++++------ pkg/hook/exechook.go | 7 +++++-- pkg/hook/hook.go | 2 +- pkg/hook/webhook.go | 10 +++++++-- 5 files changed, 44 insertions(+), 35 deletions(-) diff --git a/main.go b/main.go index 93b4a2c..e77fa6b 100644 --- a/main.go +++ b/main.go @@ -1218,12 +1218,12 @@ func addUser() error { } // Run runs `git` with the specified args. -func (git *repoSync) Run(ctx context.Context, cwd absPath, args ...string) (string, error) { +func (git *repoSync) Run(ctx context.Context, cwd absPath, args ...string) (string, string, error) { return git.run.WithCallDepth(1).Run(ctx, cwd.String(), nil, git.cmd, args...) } // Run runs `git` with the specified args and stdin. -func (git *repoSync) RunWithStdin(ctx context.Context, cwd absPath, stdin string, args ...string) (string, error) { +func (git *repoSync) RunWithStdin(ctx context.Context, cwd absPath, stdin string, args ...string) (string, string, error) { return git.run.WithCallDepth(1).RunWithStdin(ctx, cwd.String(), nil, stdin, git.cmd, args...) } @@ -1263,7 +1263,7 @@ func (git *repoSync) initRepo(ctx context.Context) error { // Running `git init` in an existing repo is safe (according to git docs). git.log.V(0).Info("initializing repo directory", "path", git.root) - if _, err := git.Run(ctx, git.root, "init", "-b", "git-sync"); err != nil { + if _, _, err := git.Run(ctx, git.root, "init", "-b", "git-sync"); err != nil { return err } if !git.sanityCheckRepo(ctx) { @@ -1309,7 +1309,7 @@ func (git *repoSync) sanityCheckRepo(ctx context.Context) bool { } // Check that this is actually the root of the repo. - if root, err := git.Run(ctx, git.root, "rev-parse", "--show-toplevel"); err != nil { + if root, _, err := git.Run(ctx, git.root, "rev-parse", "--show-toplevel"); err != nil { git.log.Error(err, "can't get repo toplevel", "path", git.root) return false } else { @@ -1322,7 +1322,7 @@ func (git *repoSync) sanityCheckRepo(ctx context.Context) bool { // Consistency-check the repo. Don't use --verbose because it can be // REALLY verbose. - if _, err := git.Run(ctx, git.root, "fsck", "--no-progress", "--connectivity-only"); err != nil { + if _, _, err := git.Run(ctx, git.root, "fsck", "--no-progress", "--connectivity-only"); err != nil { git.log.Error(err, "repo fsck failed", "path", git.root) return false } @@ -1348,7 +1348,7 @@ func (git *repoSync) sanityCheckWorktree(ctx context.Context, worktree worktree) // Consistency-check the worktree. Don't use --verbose because it can be // REALLY verbose. - if _, err := git.Run(ctx, worktree.Path(), "fsck", "--no-progress", "--connectivity-only"); err != nil { + if _, _, err := git.Run(ctx, worktree.Path(), "fsck", "--no-progress", "--connectivity-only"); err != nil { git.log.Error(err, "worktree fsck failed", "path", worktree.Path()) return false } @@ -1454,7 +1454,7 @@ func (git *repoSync) removeWorktree(ctx context.Context, worktree worktree) erro if err := os.RemoveAll(worktree.Path().String()); err != nil { return fmt.Errorf("error removing directory: %v", err) } - if _, err := git.Run(ctx, git.root, "worktree", "prune", "--verbose"); err != nil { + if _, _, err := git.Run(ctx, git.root, "worktree", "prune", "--verbose"); err != nil { return err } return nil @@ -1475,7 +1475,7 @@ func (git *repoSync) createWorktree(ctx context.Context, hash string) (worktree, } git.log.V(0).Info("adding worktree", "path", worktree.Path(), "hash", hash) - _, err := git.Run(ctx, git.root, "worktree", "add", "--force", "--detach", worktree.Path().String(), hash, "--no-checkout") + _, _, err := git.Run(ctx, git.root, "worktree", "add", "--force", "--detach", worktree.Path().String(), hash, "--no-checkout") if err != nil { return "", err } @@ -1540,14 +1540,14 @@ func (git *repoSync) configureWorktree(ctx context.Context, worktree worktree) e } args := []string{"sparse-checkout", "init"} - if _, err = git.Run(ctx, worktree.Path(), args...); err != nil { + if _, _, err = git.Run(ctx, worktree.Path(), args...); err != nil { return err } } // Reset the worktree's working copy to the specific ref. git.log.V(1).Info("setting worktree HEAD", "hash", hash) - if _, err := git.Run(ctx, worktree.Path(), "reset", "--hard", hash, "--"); err != nil { + if _, _, err := git.Run(ctx, worktree.Path(), "reset", "--hard", hash, "--"); err != nil { return err } @@ -1562,7 +1562,7 @@ func (git *repoSync) configureWorktree(ctx context.Context, worktree worktree) e if git.depth != 0 { submodulesArgs = append(submodulesArgs, "--depth", strconv.Itoa(git.depth)) } - if _, err := git.Run(ctx, worktree.Path(), submodulesArgs...); err != nil { + if _, _, err := git.Run(ctx, worktree.Path(), submodulesArgs...); err != nil { return err } } @@ -1585,12 +1585,12 @@ func (git *repoSync) cleanup(ctx context.Context) error { } // Let git know we don't need those old commits any more. - if _, err := git.Run(ctx, git.root, "worktree", "prune", "--verbose"); err != nil { + if _, _, err := git.Run(ctx, git.root, "worktree", "prune", "--verbose"); err != nil { cleanupErrs = append(cleanupErrs, err) } // Expire old refs. - if _, err := git.Run(ctx, git.root, "reflog", "expire", "--expire-unreachable=all", "--all"); err != nil { + if _, _, err := git.Run(ctx, git.root, "reflog", "expire", "--expire-unreachable=all", "--all"); err != nil { cleanupErrs = append(cleanupErrs, err) } @@ -1605,7 +1605,7 @@ func (git *repoSync) cleanup(ctx context.Context) error { case gcAggressive: args = append(args, "--aggressive") } - if _, err := git.Run(ctx, git.root, args...); err != nil { + if _, _, err := git.Run(ctx, git.root, args...); err != nil { cleanupErrs = append(cleanupErrs, err) } } @@ -1637,7 +1637,7 @@ func (git *repoSync) remoteHashForRef(ctx context.Context, ref string) (string, // Fetch both the bare and dereferenced ref. git sorts the results and // prints the dereferenced result, if present, after the bare result, so we // always want the last result it produces. - output, err := git.Run(ctx, git.root, "ls-remote", "-q", git.repo, ref, ref+"^{}") + output, _, err := git.Run(ctx, git.root, "ls-remote", "-q", git.repo, ref, ref+"^{}") if err != nil { return "", err } @@ -1664,7 +1664,7 @@ func lastNonEmptyLine(text string) string { // is not a hash or is not known to this repo, even if it appears to be a hash, // this will return false. func (git *repoSync) IsKnownHash(ctx context.Context, ref string) (bool, error) { - output, err := git.Run(ctx, git.root, "rev-parse", ref+"^{commit}") + output, _, err := git.Run(ctx, git.root, "rev-parse", ref+"^{commit}") if err != nil { if strings.Contains(err.Error(), "unknown revision") { return false, nil @@ -1738,7 +1738,7 @@ func (git *repoSync) SyncRepo(ctx context.Context, refreshCreds func(context.Con if remoteHash == "" { // If git thinks it tastes like a hash, we just use that and if it // is wrong, we will fail later. - output, err := git.Run(ctx, git.root, "rev-parse", git.ref) + output, _, err := git.Run(ctx, git.root, "rev-parse", git.ref) if err != nil { return false, "", err } @@ -1789,7 +1789,7 @@ func (git *repoSync) SyncRepo(ctx context.Context, refreshCreds func(context.Con // Reset the repo (note: not the worktree - that happens later) to the new // ref. This makes subsequent fetches much less expensive. It uses --soft // so no files are checked out. - if _, err := git.Run(ctx, git.root, "reset", "--soft", "FETCH_HEAD"); err != nil { + if _, _, err := git.Run(ctx, git.root, "reset", "--soft", "FETCH_HEAD"); err != nil { return false, "", err } @@ -1863,7 +1863,7 @@ func (git *repoSync) fetch(ctx context.Context, ref string) error { args = append(args, "--unshallow") } } - if _, err := git.Run(ctx, git.root, args...); err != nil { + if _, _, err := git.Run(ctx, git.root, args...); err != nil { return err } @@ -1871,7 +1871,7 @@ func (git *repoSync) fetch(ctx context.Context, ref string) error { } func (git *repoSync) isShallow(ctx context.Context) (bool, error) { - boolStr, err := git.Run(ctx, git.root, "rev-parse", "--is-shallow-repository") + boolStr, _, err := git.Run(ctx, git.root, "rev-parse", "--is-shallow-repository") if err != nil { return false, fmt.Errorf("can't determine repo shallowness: %w", err) } @@ -1897,7 +1897,7 @@ func (git *repoSync) StoreCredentials(ctx context.Context, username, password st git.log.V(9).Info("md5 of credentials", "username", md5sum(username), "password", md5sum(password)) creds := fmt.Sprintf("url=%v\nusername=%v\npassword=%v\n", git.repo, username, password) - _, err := git.RunWithStdin(ctx, "", creds, "credential", "approve") + _, _, err := git.RunWithStdin(ctx, "", creds, "credential", "approve") if err != nil { return fmt.Errorf("can't configure git credentials: %w", err) } @@ -1946,7 +1946,7 @@ func (git *repoSync) SetupCookieFile(ctx context.Context) error { return fmt.Errorf("can't access git cookiefile: %w", err) } - if _, err = git.Run(ctx, "", "config", "--global", "http.cookiefile", pathToCookieFile); err != nil { + if _, _, err = git.Run(ctx, "", "config", "--global", "http.cookiefile", pathToCookieFile); err != nil { return fmt.Errorf("can't configure git cookiefile: %w", err) } @@ -2037,7 +2037,7 @@ func (git *repoSync) SetupDefaultGitConfigs(ctx context.Context) error { }} for _, kv := range configs { - if _, err := git.Run(ctx, "", "config", "--global", kv.key, kv.val); err != nil { + if _, _, err := git.Run(ctx, "", "config", "--global", kv.key, kv.val); err != nil { return fmt.Errorf("error configuring git %q %q: %v", kv.key, kv.val, err) } } @@ -2054,7 +2054,7 @@ func (git *repoSync) SetupExtraGitConfigs(ctx context.Context, configsFlag strin return fmt.Errorf("can't parse --git-config flag: %v", err) } for _, kv := range configs { - if _, err := git.Run(ctx, "", "config", "--global", kv.key, kv.val); err != nil { + if _, _, err := git.Run(ctx, "", "config", "--global", kv.key, kv.val); err != nil { return fmt.Errorf("error configuring additional git configs %q %q: %v", kv.key, kv.val, err) } } diff --git a/pkg/cmd/cmd.go b/pkg/cmd/cmd.go index d1a7871..861199a 100644 --- a/pkg/cmd/cmd.go +++ b/pkg/cmd/cmd.go @@ -46,18 +46,18 @@ func NewRunner(log logintf) Runner { } // Run runs given command -func (r Runner) Run(ctx context.Context, cwd string, env []string, command string, args ...string) (string, error) { +func (r Runner) Run(ctx context.Context, cwd string, env []string, command string, args ...string) (string, string, error) { // call depth = 2 to erase the runWithStdin frame and this one return runWithStdin(ctx, r.log.WithCallDepth(2), cwd, env, "", command, args...) } // RunWithStdin runs given command with standard input -func (r Runner) RunWithStdin(ctx context.Context, cwd string, env []string, stdin, command string, args ...string) (string, error) { +func (r Runner) RunWithStdin(ctx context.Context, cwd string, env []string, stdin, command string, args ...string) (string, string, error) { // call depth = 2 to erase the runWithStdin frame and this one return runWithStdin(ctx, r.log.WithCallDepth(2), cwd, env, stdin, command, args...) } -func runWithStdin(ctx context.Context, log logintf, cwd string, env []string, stdin, command string, args ...string) (string, error) { +func runWithStdin(ctx context.Context, log logintf, cwd string, env []string, stdin, command string, args ...string) (string, string, error) { cmdStr := cmdForLog(command, args...) log.V(5).Info("running command", "cwd", cwd, "cmd", cmdStr) @@ -80,14 +80,14 @@ func runWithStdin(ctx context.Context, log logintf, cwd string, env []string, st stdout := strings.TrimSpace(outbuf.String()) stderr := strings.TrimSpace(errbuf.String()) if ctx.Err() == context.DeadlineExceeded { - return "", fmt.Errorf("Run(%s): %w: { stdout: %q, stderr: %q }", cmdStr, ctx.Err(), stdout, stderr) + return "", "", fmt.Errorf("Run(%s): %w: { stdout: %q, stderr: %q }", cmdStr, ctx.Err(), stdout, stderr) } if err != nil { - return "", fmt.Errorf("Run(%s): %w: { stdout: %q, stderr: %q }", cmdStr, err, stdout, stderr) + return "", "", fmt.Errorf("Run(%s): %w: { stdout: %q, stderr: %q }", cmdStr, err, stdout, stderr) } log.V(6).Info("command result", "stdout", stdout, "stderr", stderr, "time", wallTime) - return stdout, nil + return stdout, stderr, nil } func cmdForLog(command string, args ...string) string { diff --git a/pkg/hook/exechook.go b/pkg/hook/exechook.go index 1eee1f0..9bd13e2 100644 --- a/pkg/hook/exechook.go +++ b/pkg/hook/exechook.go @@ -68,8 +68,11 @@ func (h *Exechook) Do(ctx context.Context, hash string) error { env := os.Environ() env = append(env, envKV("GITSYNC_HASH", hash)) - h.log.V(0).Info("running exechook", "command", h.command, "timeout", h.timeout) - _, err := h.cmdrunner.Run(ctx, worktreePath, env, h.command, h.args...) + h.log.V(0).Info("running exechook", "hash", hash, "command", h.command, "timeout", h.timeout) + stdout, stderr, err := h.cmdrunner.Run(ctx, worktreePath, env, h.command, h.args...) + if err == nil { + h.log.V(1).Info("exechook succeeded", "hash", hash, "stdout", stdout, "stderr", stderr) + } return err } diff --git a/pkg/hook/hook.go b/pkg/hook/hook.go index 4f4893f..9432e38 100644 --- a/pkg/hook/hook.go +++ b/pkg/hook/hook.go @@ -140,7 +140,7 @@ func (r *HookRunner) Run(ctx context.Context) { } if err := r.hook.Do(ctx, hash); err != nil { - r.log.Error(err, "hook failed") + r.log.Error(err, "hook failed", "hash", hash, "retry", r.backoff) updateHookRunCountMetric(r.hook.Name(), "error") // don't want to sleep unnecessarily terminating anyways r.sendOneTimeResultAndTerminate(false) diff --git a/pkg/hook/webhook.go b/pkg/hook/webhook.go index 1f01918..42a662c 100644 --- a/pkg/hook/webhook.go +++ b/pkg/hook/webhook.go @@ -19,6 +19,7 @@ package hook import ( "context" "fmt" + "io" "net/http" "time" ) @@ -71,12 +72,17 @@ func (w *Webhook) Do(ctx context.Context, hash string) error { if err != nil { return err } - resp.Body.Close() + defer resp.Body.Close() + body, err := io.ReadAll(resp.Body) + if err != nil { + return err + } // If the webhook has a success statusCode, check against it if w.success > 0 && resp.StatusCode != w.success { - return fmt.Errorf("received response code %d expected %d", resp.StatusCode, w.success) + return fmt.Errorf("received response code %d expected %d, body: %q", resp.StatusCode, w.success, body) } + w.log.V(1).Info("webhook succeeded", "hash", hash, "status", resp.StatusCode, "headers", resp.Header, "body", body) return nil }