kubernetes
/
git-sync
mirror of https://github.com/kubernetes/git-sync.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Better logging around hooks 

This also returns stderr distinct from stdout.
This commit is contained in:
Tim Hockin 2023-05-12 15:21:07 -07:00
parent ed170912c9
commit 9318041657
5 changed files with 44 additions and 35 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

48
main.go
View File

@ -1218,12 +1218,12 @@ func addUser() error {
} }
// Run runs `git` with the specified args. // 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...) return git.run.WithCallDepth(1).Run(ctx, cwd.String(), nil, git.cmd, args...)
} }
// Run runs `git` with the specified args and stdin. // 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...) 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). // Running `git init` in an existing repo is safe (according to git docs).
git.log.V(0).Info("initializing repo directory", "path", git.root) 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 return err
} }
if !git.sanityCheckRepo(ctx) { 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. // 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) git.log.Error(err, "can't get repo toplevel", "path", git.root)
return false return false
} else { } 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 // Consistency-check the repo. Don't use --verbose because it can be
// REALLY verbose. // 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) git.log.Error(err, "repo fsck failed", "path", git.root)
return false 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 // Consistency-check the worktree. Don't use --verbose because it can be
// REALLY verbose. // 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()) git.log.Error(err, "worktree fsck failed", "path", worktree.Path())
return false 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 { if err := os.RemoveAll(worktree.Path().String()); err != nil {
return fmt.Errorf("error removing directory: %v", err) 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 err
} }
return nil 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) 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 { if err != nil {
return "", err return "", err
} }
@ -1540,14 +1540,14 @@ func (git *repoSync) configureWorktree(ctx context.Context, worktree worktree) e
} }
args := []string{"sparse-checkout", "init"} 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 return err
} }
} }
// Reset the worktree's working copy to the specific ref. // Reset the worktree's working copy to the specific ref.
git.log.V(1).Info("setting worktree HEAD", "hash", hash) 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 return err
} }
@ -1562,7 +1562,7 @@ func (git *repoSync) configureWorktree(ctx context.Context, worktree worktree) e
if git.depth != 0 { if git.depth != 0 {
submodulesArgs = append(submodulesArgs, "--depth", strconv.Itoa(git.depth)) 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 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. // 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) cleanupErrs = append(cleanupErrs, err)
} }
// Expire old refs. // 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) cleanupErrs = append(cleanupErrs, err)
} }
@ -1605,7 +1605,7 @@ func (git *repoSync) cleanup(ctx context.Context) error {
case gcAggressive: case gcAggressive:
args = append(args, "--aggressive") 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) 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 // Fetch both the bare and dereferenced ref. git sorts the results and
// prints the dereferenced result, if present, after the bare result, so we // prints the dereferenced result, if present, after the bare result, so we
// always want the last result it produces. // 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 { if err != nil {
return "", err 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, // is not a hash or is not known to this repo, even if it appears to be a hash,
// this will return false. // this will return false.
func (git *repoSync) IsKnownHash(ctx context.Context, ref string) (bool, error) { 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 err != nil {
if strings.Contains(err.Error(), "unknown revision") { if strings.Contains(err.Error(), "unknown revision") {
return false, nil return false, nil
@ -1738,7 +1738,7 @@ func (git *repoSync) SyncRepo(ctx context.Context, refreshCreds func(context.Con
if remoteHash == "" { if remoteHash == "" {
// If git thinks it tastes like a hash, we just use that and if it // If git thinks it tastes like a hash, we just use that and if it
// is wrong, we will fail later. // 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 { if err != nil {
return false, "", err 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 // Reset the repo (note: not the worktree - that happens later) to the new
// ref. This makes subsequent fetches much less expensive. It uses --soft // ref. This makes subsequent fetches much less expensive. It uses --soft
// so no files are checked out. // 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 return false, "", err
} }
@ -1863,7 +1863,7 @@ func (git *repoSync) fetch(ctx context.Context, ref string) error {
args = append(args, "--unshallow") 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 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) { 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 { if err != nil {
return false, fmt.Errorf("can't determine repo shallowness: %w", err) 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)) 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) 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 { if err != nil {
return fmt.Errorf("can't configure git credentials: %w", err) 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) 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) 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 { 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) 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) return fmt.Errorf("can't parse --git-config flag: %v", err)
} }
for _, kv := range configs { 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) return fmt.Errorf("error configuring additional git configs %q %q: %v", kv.key, kv.val, err)
} }
} }

12
pkg/cmd/cmd.go
View File

@ -46,18 +46,18 @@ func NewRunner(log logintf) Runner {
} }
// Run runs given command // 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 // call depth = 2 to erase the runWithStdin frame and this one
return runWithStdin(ctx, r.log.WithCallDepth(2), cwd, env, "", command, args...) return runWithStdin(ctx, r.log.WithCallDepth(2), cwd, env, "", command, args...)
} }
// RunWithStdin runs given command with standard input // 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 // call depth = 2 to erase the runWithStdin frame and this one
return runWithStdin(ctx, r.log.WithCallDepth(2), cwd, env, stdin, command, args...) 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...) cmdStr := cmdForLog(command, args...)
log.V(5).Info("running command", "cwd", cwd, "cmd", cmdStr) 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()) stdout := strings.TrimSpace(outbuf.String())
stderr := strings.TrimSpace(errbuf.String()) stderr := strings.TrimSpace(errbuf.String())
if ctx.Err() == context.DeadlineExceeded { 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 { 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) 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 { func cmdForLog(command string, args ...string) string {

7
pkg/hook/exechook.go
View File

@ -68,8 +68,11 @@ func (h *Exechook) Do(ctx context.Context, hash string) error {
env := os.Environ() env := os.Environ()
env = append(env, envKV("GITSYNC_HASH", hash)) env = append(env, envKV("GITSYNC_HASH", hash))
h.log.V(0).Info("running exechook", "command", h.command, "timeout", h.timeout) h.log.V(0).Info("running exechook", "hash", hash, "command", h.command, "timeout", h.timeout)
_, err := h.cmdrunner.Run(ctx, worktreePath, env, h.command, h.args...) 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 return err
} }

2
pkg/hook/hook.go
View File

@ -140,7 +140,7 @@ func (r *HookRunner) Run(ctx context.Context) {
} }
if err := r.hook.Do(ctx, hash); err != nil { 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") updateHookRunCountMetric(r.hook.Name(), "error")
// don't want to sleep unnecessarily terminating anyways // don't want to sleep unnecessarily terminating anyways
r.sendOneTimeResultAndTerminate(false) r.sendOneTimeResultAndTerminate(false)

10
pkg/hook/webhook.go
View File

@ -19,6 +19,7 @@ package hook
import ( import (
"context" "context"
"fmt" "fmt"
"io"
"net/http" "net/http"
"time" "time"
) )
@ -71,12 +72,17 @@ func (w *Webhook) Do(ctx context.Context, hash string) error {
if err != nil { if err != nil {
return err 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 the webhook has a success statusCode, check against it
if w.success > 0 && resp.StatusCode != w.success { 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 return nil
} }