Export the error details to an error file

The current git-sync process outputs the error information to standard
out, which is inaccessible from outside the container. Users have to
dump the logs using kubectl logs in order to check the error details in
the git-sync process. This commit exports the error details to a file,
which provides users the capability to check the errors directly from
other sidecar containers.

proposal: https://github.com/kubernetes/git-sync/issues/326

cmd/git-sync/main.go

@@ -21,6 +21,7 @@ package main // import "k8s.io/git-sync/cmd/git-sync"
 import (
 	"bytes"
 	"context"
+	"encoding/json"
 	"flag"
 	"fmt"
 	"io/ioutil"
@@ -37,6 +38,7 @@ import (
 	"time"
 
 	"github.com/go-logr/glogr"
+	"github.com/go-logr/logr"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"github.com/spf13/pflag"
@@ -66,6 +68,8 @@ var flRoot = pflag.String("root", envString("GIT_SYNC_ROOT", ""),
 	"the root directory for git-sync operations, under which --link will be created")
 var flLink = pflag.String("link", envString("GIT_SYNC_LINK", ""),
 	"the name of a symlink, under --root, which points to a directory in which --repo is checked out (defaults to the leaf dir of --repo)")
+var flErrorFile = pflag.String("error-file", envString("GIT_SYNC_ERROR_FILE", ""),
+	"the name of a file into which errors will be written under --root (defaults to \"\", disabling error reporting)")
 var flPeriod = pflag.Duration("period", envDuration("GIT_SYNC_PERIOD", 10*time.Second),
 	"how long to wait between syncs, must be >= 10ms; --wait overrides this")
 var flSyncTimeout = pflag.Duration("sync-timeout", envDuration("GIT_SYNC_SYNC_TIMEOUT", 120*time.Second),
@@ -139,7 +143,7 @@ func init() {
 	pflag.CommandLine.MarkDeprecated("dest", "use --link instead")
 }
 
-var log = glogr.New()
+var log *customLogger
 
 // Total pull/error, summary on pull duration
 var (
@@ -174,6 +178,90 @@ const (
 	submodulesOff       submodulesMode = "off"
 )
 
+type customLogger struct {
+	logr.Logger
+	errorFile string
+}
+
+func (l customLogger) Error(err error, msg string, kvList ...interface{}) {
+	l.Logger.Error(err, msg, kvList...)
+	if l.errorFile == "" {
+		return
+	}
+	payload := struct {
+		Msg  string
+		Err  string
+		Args map[string]interface{}
+	}{
+		Msg:  msg,
+		Err:  err.Error(),
+		Args: map[string]interface{}{},
+	}
+	if len(kvList)%2 != 0 {
+		kvList = append(kvList, "<no-value>")
+	}
+	for i := 0; i < len(kvList); i += 2 {
+		k, ok := kvList[i].(string)
+		if !ok {
+			k = fmt.Sprintf("%v", kvList[i])
+		}
+		payload.Args[k] = kvList[i+1]
+	}
+	jb, err := json.Marshal(payload)
+	if err != nil {
+		l.Logger.Error(err, "can't encode error payload")
+		content := fmt.Sprintf("%v", err)
+		l.writeContent([]byte(content))
+	} else {
+		l.writeContent(jb)
+	}
+}
+
+// exportError exports the error to the error file if --export-error is enabled.
+func (l *customLogger) exportError(content string) {
+	if l.errorFile == "" {
+		return
+	}
+	l.writeContent([]byte(content))
+}
+
+// writeContent writes the error content to the error file.
+func (l *customLogger) writeContent(content []byte) {
+	tmpFile, err := ioutil.TempFile(*flRoot, "tmp-err-")
+	if err != nil {
+		l.Logger.Error(err, "can't create temporary error-file", "directory", *flRoot, "prefix", "tmp-err-")
+		return
+	}
+	defer func() {
+		if err := tmpFile.Close(); err != nil {
+			l.Logger.Error(err, "can't close temporary error-file", "filename", tmpFile.Name())
+		}
+	}()
+
+	if _, err = tmpFile.Write(content); err != nil {
+		l.Logger.Error(err, "can't write to temporary error-file", "filename", tmpFile.Name())
+		return
+	}
+
+	if err := os.Rename(tmpFile.Name(), l.errorFile); err != nil {
+		l.Logger.Error(err, "can't rename to error-file", "temp-file", tmpFile.Name(), "error-file", l.errorFile)
+		return
+	}
+}
+
+// deleteErrorFile deletes the error file.
+func (l *customLogger) deleteErrorFile() {
+	if l.errorFile == "" {
+		return
+	}
+	if err := os.Remove(l.errorFile); err != nil {
+		if os.IsNotExist(err) {
+			return
+		}
+		l.Logger.Error(err, "can't delete the error-file", "filename", l.errorFile)
+	}
+}
+
 func init() {
 	prometheus.MustRegister(syncDuration)
 	prometheus.MustRegister(syncCount)
@@ -203,7 +291,7 @@ func envInt(key string, def int) int {
 	if env := os.Getenv(key); env != "" {
 		val, err := strconv.ParseInt(env, 0, 0)
 		if err != nil {
-			log.Error(err, "invalid env value, using default", "key", key, "val", os.Getenv(key), "default", def)
+			fmt.Fprintf(os.Stderr, "WARNING: invalid env value (%v): using default, key=%s, val=%q, default=%d\n", err, key, env, def)
 			return def
 		}
 		return int(val)
@@ -215,7 +303,7 @@ func envFloat(key string, def float64) float64 {
 	if env := os.Getenv(key); env != "" {
 		val, err := strconv.ParseFloat(env, 64)
 		if err != nil {
-			log.Error(err, "invalid env value, using default", "key", key, "val", os.Getenv(key), "default", def)
+			fmt.Fprintf(os.Stderr, "WARNING: invalid env value (%v): using default, key=%s, val=%q, default=%f\n", err, key, env, def)
 			return def
 		}
 		return val
@@ -227,7 +315,7 @@ func envDuration(key string, def time.Duration) time.Duration {
 	if env := os.Getenv(key); env != "" {
 		val, err := time.ParseDuration(env)
 		if err != nil {
-			log.Error(err, "invalid env value, using default", "key", key, "val", os.Getenv(key), "default", def)
+			fmt.Fprintf(os.Stderr, "WARNING: invalid env value (%v): using default, key=%s, val=%q, default=%d\n", err, key, env, def)
 			return def
 		}
 		return val
@@ -239,8 +327,7 @@ func setGlogFlags() {
 	// Force logging to stderr.
 	stderrFlag := flag.Lookup("logtostderr")
 	if stderrFlag == nil {
-		fmt.Fprintf(os.Stderr, "ERROR: can't find glog flag 'logtostderr'\n")
+		handleError(false, "ERROR: can't find glog flag 'logtostderr'")
-		os.Exit(1)
 	}
 	stderrFlag.Value.Set("true")
 
@@ -287,6 +374,12 @@ func main() {
 	flag.CommandLine.Parse(nil) // Otherwise glog complains
 	setGlogFlags()
 
+	var errorFile string
+	if *flErrorFile != "" {
+		errorFile = filepath.Join(*flRoot, *flErrorFile)
+	}
+	log = &customLogger{glogr.New(), errorFile}
+
 	if *flVersion {
 		fmt.Println(version.VERSION)
 		os.Exit(0)
@@ -302,29 +395,21 @@ func main() {
 	}
 
 	if *flRepo == "" {
-		fmt.Fprintf(os.Stderr, "ERROR: --repo must be specified\n")
+		handleError(true, "ERROR: --repo must be specified")
-		pflag.Usage()
-		os.Exit(1)
 	}
 
 	if *flDepth < 0 { // 0 means "no limit"
-		fmt.Fprintf(os.Stderr, "ERROR: --depth must be greater than or equal to 0\n")
+		handleError(true, "ERROR: --depth must be greater than or equal to 0")
-		pflag.Usage()
-		os.Exit(1)
 	}
 
 	switch submodulesMode(*flSubmodules) {
 	case submodulesRecursive, submodulesShallow, submodulesOff:
 	default:
-		fmt.Fprintf(os.Stderr, "ERROR: --submodules must be one of %q, %q, or %q", submodulesRecursive, submodulesShallow, submodulesOff)
+		handleError(true, "ERROR: --submodules must be one of %q, %q, or %q", submodulesRecursive, submodulesShallow, submodulesOff)
-		pflag.Usage()
-		os.Exit(1)
 	}
 
 	if *flRoot == "" {
-		fmt.Fprintf(os.Stderr, "ERROR: --root must be specified\n")
+		handleError(true, "ERROR: --root must be specified")
-		pflag.Usage()
-		os.Exit(1)
 	}
 
 	if *flDest != "" {
@@ -335,79 +420,57 @@ func main() {
 		*flLink = parts[len(parts)-1]
 	}
 	if strings.Contains(*flLink, "/") {
-		fmt.Fprintf(os.Stderr, "ERROR: --link must not contain '/'\n")
+		handleError(true, "ERROR: --link must not contain '/'")
-		pflag.Usage()
-		os.Exit(1)
 	}
 	if strings.HasPrefix(*flLink, ".") {
-		fmt.Fprintf(os.Stderr, "ERROR: --link must not start with '.'\n")
+		handleError(true, "ERROR: --link must not start with '.'")
-		pflag.Usage()
-		os.Exit(1)
 	}
 
 	if *flWait != 0 {
 		*flPeriod = time.Duration(int(*flWait*1000)) * time.Millisecond
 	}
 	if *flPeriod < 10*time.Millisecond {
-		fmt.Fprintf(os.Stderr, "ERROR: --period must be at least 10ms\n")
+		handleError(true, "ERROR: --period must be at least 10ms")
-		pflag.Usage()
-		os.Exit(1)
 	}
 
 	if *flTimeout != 0 {
 		*flSyncTimeout = time.Duration(*flTimeout) * time.Second
 	}
 	if *flSyncTimeout < 10*time.Millisecond {
-		fmt.Fprintf(os.Stderr, "ERROR: --sync-timeout must be at least 10ms\n")
+		handleError(true, "ERROR: --sync-timeout must be at least 10ms")
-		pflag.Usage()
-		os.Exit(1)
 	}
 
 	if *flWebhookURL != "" {
 		if *flWebhookStatusSuccess < -1 {
-			fmt.Fprintf(os.Stderr, "ERROR: --webhook-success-status must be a valid HTTP code or -1\n")
+			handleError(true, "ERROR: --webhook-success-status must be a valid HTTP code or -1")
-			pflag.Usage()
-			os.Exit(1)
 		}
 		if *flWebhookTimeout < time.Second {
-			fmt.Fprintf(os.Stderr, "ERROR: --webhook-timeout must be at least 1s\n")
+			handleError(true, "ERROR: --webhook-timeout must be at least 1s")
-			pflag.Usage()
-			os.Exit(1)
 		}
 		if *flWebhookBackoff < time.Second {
-			fmt.Fprintf(os.Stderr, "ERROR: --webhook-backoff must be at least 1s\n")
+			handleError(true, "ERROR: --webhook-backoff must be at least 1s")
-			pflag.Usage()
-			os.Exit(1)
 		}
 	}
 
 	if *flSSH {
 		if *flUsername != "" {
-			fmt.Fprintf(os.Stderr, "ERROR: only one of --ssh and --username may be specified\n")
+			handleError(false, "ERROR: only one of --ssh and --username may be specified")
-			os.Exit(1)
 		}
 		if *flPassword != "" {
-			fmt.Fprintf(os.Stderr, "ERROR: only one of --ssh and --password may be specified\n")
+			handleError(false, "ERROR: only one of --ssh and --password may be specified")
-			os.Exit(1)
 		}
 		if *flAskPassURL != "" {
-			fmt.Fprintf(os.Stderr, "ERROR: only one of --ssh and --askpass-url may be specified\n")
+			handleError(false, "ERROR: only one of --ssh and --askpass-url may be specified")
-			os.Exit(1)
 		}
 		if *flCookieFile {
-			fmt.Fprintf(os.Stderr, "ERROR: only one of --ssh and --cookie-file may be specified\n")
+			handleError(false, "ERROR: only one of --ssh and --cookie-file may be specified")
-			os.Exit(1)
 		}
 		if *flSSHKeyFile == "" {
-			fmt.Fprintf(os.Stderr, "ERROR: --ssh-key-file must be specified when --ssh is specified\n")
+			handleError(true, "ERROR: --ssh-key-file must be specified when --ssh is specified")
-			pflag.Usage()
-			os.Exit(1)
 		}
 		if *flSSHKnownHosts {
 			if *flSSHKnownHostsFile == "" {
-				fmt.Fprintf(os.Stderr, "ERROR: --ssh-known-hosts-file must be specified when --ssh-known-hosts is specified\n")
+				handleError(true, "ERROR: --ssh-known-hosts-file must be specified when --ssh-known-hosts is specified")
-				pflag.Usage()
-				os.Exit(1)
 			}
 		}
 	}
@@ -585,6 +648,7 @@ func main() {
 
 		if initialSync {
 			if *flOneTime {
+				log.deleteErrorFile()
 				os.Exit(0)
 			}
 			if isHash, err := git.RevIsHash(ctx); err != nil {
@@ -592,12 +656,14 @@ func main() {
 				os.Exit(1)
 			} else if isHash {
 				log.V(0).Info("rev appears to be a git hash, no further sync needed", "rev", git.rev)
+				log.deleteErrorFile()
 				sleepForever()
 			}
 			initialSync = false
 		}
 
 		failCount = 0
+		log.deleteErrorFile()
 		log.V(1).Info("next sync", "waitTime", flPeriod.String())
 		cancel()
 		time.Sleep(*flPeriod)
@@ -716,6 +782,18 @@ func sleepForever() {
 	os.Exit(0)
 }
 
+// handleError prints the error to the standard error, prints the usage if the `printUsage` flag is true,
+// exports the error to the error file and exits the process with the exit code.
+func handleError(printUsage bool, format string, a ...interface{}) {
+	s := fmt.Sprintf(format, a...)
+	fmt.Fprintln(os.Stderr, s)
+	if printUsage {
+		pflag.Usage()
+	}
+	log.exportError(s)
+	os.Exit(1)
+}
+
 // Put the current UID/GID into /etc/passwd so SSH can look it up.  This
 // assumes that we have the permissions to write to it.
 func addUser() error {

test_e2e.sh

@@ -59,6 +59,13 @@ function assert_file_eq() {
     fail "file $1 does not contain '$2': $(cat $1)"
 }
 
+function assert_file_contains() {
+    if grep -q "$2" "$1"; then
+        return
+    fi
+    fail "file $1 does not contain '$2': $(cat $1)"
+}
+
 # Helper: run a docker container.
 function docker_run() {
     docker run \
@@ -1342,3 +1349,43 @@ pass
 echo
 echo "all tests passed: cleaning up $DIR"
 rm -rf "$DIR"
+
+##############################################
+# Test export-error
+##############################################
+testcase "export-error"
+echo "$TESTCASE" > "$REPO"/file
+git -C "$REPO" commit -qam "$TESTCASE"
+(
+  set +o errexit
+  GIT_SYNC \
+      --repo="file://$REPO" \
+      --branch=does-not-exit \
+      --root="$ROOT" \
+      --link="link" \
+      --error-file="error.json" \
+      > "$DIR"/log."$TESTCASE" 2>&1
+  RET=$?
+  if [[ "$RET" != 1 ]]; then
+      fail "expected exit code 1, got $RET"
+  fi
+  assert_file_absent "$ROOT"/link
+  assert_file_absent "$ROOT"/link/file
+  assert_file_contains "$ROOT"/error.json "Remote branch does-not-exit not found in upstream origin"
+)
+
+# the error.json file should be removed if sync succeeds.
+GIT_SYNC \
+    --one-time \
+    --repo="file://$REPO" \
+    --branch=e2e-branch \
+    --root="$ROOT" \
+    --link="link" \
+    --error-file="error.json" \
+    > "$DIR"/log."$TESTCASE" 2>&1
+assert_link_exists "$ROOT"/link
+assert_file_exists "$ROOT"/link/file
+assert_file_eq "$ROOT"/link/file "$TESTCASE"
+assert_file_absent "$ROOT"/error.json
+# Wrap up
+pass