Merge pull request #3826 from MichaelEischer/debug-log-for-release

Debug log for release build

CONTRIBUTING.md

@@ -48,9 +48,8 @@ environment was used and so on. Please tell us at least the following things:
 Remember, the easier it is for us to reproduce the bug, the earlier it will be
 corrected!
 
-In addition, you can compile restic with debug support by running
+In addition, you can instruct restic to create a debug log by setting the
-`go run build.go -tags debug` and instructing it to create a debug
+environment variable `DEBUG_LOG` to a file, e.g. like this:
-log by setting the environment variable `DEBUG_LOG` to a file, e.g. like this:
 
     $ export DEBUG_LOG=/tmp/restic-debug.log
     $ restic backup ~/work

changelog/unreleased/issue-1842

@@ -0,0 +1,8 @@
+Change: Support debug log creation in release builds
+
+Creating a debug log was only possible in debug builds which required users to
+manually build restic. We changed the release builds to allow creating debug
+logs by setting the environment variable `DEBUG_LOG=logname.log`.
+
+https://github.com/restic/restic/issues/1842
+https://github.com/restic/restic/pull/3826

doc/090_participating.rst

@@ -14,18 +14,12 @@
 Participating
 #############
 
-*********
+**********
-Debugging
+Debug Logs
-*********
+**********
 
-The program can be built with debug support like this:
+Set the environment variable ``DEBUG_LOG`` to let restic write extensive debug
-
+messages to the specified filed, e.g.:
-.. code-block:: console
-
-    $ go run build.go -tags debug
-
-Afterwards, extensive debug messages are written to the file in
-environment variable ``DEBUG_LOG``, e.g.:
 
 .. code-block:: console
 
@@ -66,6 +60,21 @@ statements originating in functions that match the pattern ``*unlock*``
     $ DEBUG_FUNCS=*unlock* restic check
 
 
+*********
+Debugging
+*********
+
+The program can be built with debug support like this:
+
+.. code-block:: console
+
+    $ go run build.go -tags debug
+
+This will make the ``restic debug <subcommand>`` available which can be used to
+inspect internal data structures. In addition, this enables profiling support
+which can help with investigation performance and memory usage issues.
+
+
 ************
 Contributing
 ************

internal/debug/debug.go

@@ -1,6 +1,3 @@
-//go:build debug
-// +build debug
-
 package debug
 
 import (

internal/debug/debug_release.go

@@ -1,7 +0,0 @@
-//go:build !debug
-// +build !debug
-
-package debug
-
-// Log prints a message to the debug log (if debug is enabled).
-func Log(fmt string, args ...interface{}) {}

internal/debug/hooks.go

@@ -1,29 +0,0 @@
-//go:build debug
-// +build debug
-
-package debug
-
-var (
-	hooks map[string]func(interface{})
-)
-
-func init() {
-	hooks = make(map[string]func(interface{}))
-}
-
-func Hook(name string, f func(interface{})) {
-	hooks[name] = f
-}
-
-func RunHook(name string, context interface{}) {
-	f, ok := hooks[name]
-	if !ok {
-		return
-	}
-
-	f(context)
-}
-
-func RemoveHook(name string) {
-	delete(hooks, name)
-}

internal/debug/hooks_release.go

@@ -1,10 +0,0 @@
-//go:build !debug
-// +build !debug
-
-package debug
-
-func Hook(name string, f func(interface{})) {}
-
-func RunHook(name string, context interface{}) {}
-
-func RemoveHook(name string) {}

internal/debug/round_tripper.go

@@ -0,0 +1,116 @@
+package debug
+
+import (
+	"fmt"
+	"io"
+	"io/ioutil"
+	"net/http"
+	"net/http/httputil"
+	"os"
+
+	"github.com/restic/restic/internal/errors"
+)
+
+type eofDetectRoundTripper struct {
+	http.RoundTripper
+}
+
+type eofDetectReader struct {
+	eofSeen bool
+	rd      io.ReadCloser
+}
+
+func (rd *eofDetectReader) Read(p []byte) (n int, err error) {
+	n, err = rd.rd.Read(p)
+	if err == io.EOF {
+		rd.eofSeen = true
+	}
+	return n, err
+}
+
+func (rd *eofDetectReader) Close() error {
+	if !rd.eofSeen {
+		buf, err := ioutil.ReadAll(rd)
+		msg := fmt.Sprintf("body not drained, %d bytes not read", len(buf))
+		if err != nil {
+			msg += fmt.Sprintf(", error: %v", err)
+		}
+
+		if len(buf) > 0 {
+			if len(buf) > 20 {
+				buf = append(buf[:20], []byte("...")...)
+			}
+			msg += fmt.Sprintf(", body: %q", buf)
+		}
+
+		fmt.Fprintln(os.Stderr, msg)
+		Log("%s: %+v", msg, errors.New("Close()"))
+	}
+	return rd.rd.Close()
+}
+
+func (tr eofDetectRoundTripper) RoundTrip(req *http.Request) (res *http.Response, err error) {
+	res, err = tr.RoundTripper.RoundTrip(req)
+	if res != nil && res.Body != nil {
+		res.Body = &eofDetectReader{rd: res.Body}
+	}
+	return res, err
+}
+
+type loggingRoundTripper struct {
+	http.RoundTripper
+}
+
+func redactHeader(header http.Header) map[string][]string {
+	removedHeaders := make(map[string][]string)
+	for _, hdr := range []string{
+		"Authorization",
+		"X-Auth-Token", // Swift headers
+		"X-Auth-Key",
+	} {
+		origHeader, hasHeader := header[hdr]
+		if hasHeader {
+			removedHeaders[hdr] = origHeader
+			header[hdr] = []string{"**redacted**"}
+		}
+	}
+	return removedHeaders
+}
+
+func restoreHeader(header http.Header, origHeaders map[string][]string) {
+	for hdr, val := range origHeaders {
+		header[hdr] = val
+	}
+}
+
+func (tr loggingRoundTripper) RoundTrip(req *http.Request) (res *http.Response, err error) {
+	// save original auth and redact it
+	origHeaders := redactHeader(req.Header)
+
+	trace, err := httputil.DumpRequestOut(req, false)
+	if err != nil {
+		Log("DumpRequestOut() error: %v\n", err)
+	} else {
+		Log("------------  HTTP REQUEST -----------\n%s", trace)
+	}
+
+	restoreHeader(req.Header, origHeaders)
+
+	res, err = tr.RoundTripper.RoundTrip(req)
+	if err != nil {
+		Log("RoundTrip() returned error: %v", err)
+	}
+
+	if res != nil {
+		origHeaders := redactHeader(res.Header)
+		trace, err := httputil.DumpResponse(res, false)
+		restoreHeader(res.Header, origHeaders)
+		if err != nil {
+			Log("DumpResponse() error: %v\n", err)
+		} else {
+			Log("------------  HTTP RESPONSE ----------\n%s", trace)
+		}
+	}
+
+	return res, err
+}

internal/debug/round_tripper_debug.go

@@ -3,66 +3,7 @@
 
 package debug
 
-import (
+import "net/http"
-	"fmt"
-	"io"
-	"io/ioutil"
-	"net/http"
-	"net/http/httputil"
-	"os"
-
-	"github.com/restic/restic/internal/errors"
-)
-
-type eofDetectRoundTripper struct {
-	http.RoundTripper
-}
-
-type eofDetectReader struct {
-	eofSeen bool
-	rd      io.ReadCloser
-}
-
-func (rd *eofDetectReader) Read(p []byte) (n int, err error) {
-	n, err = rd.rd.Read(p)
-	if err == io.EOF {
-		rd.eofSeen = true
-	}
-	return n, err
-}
-
-func (rd *eofDetectReader) Close() error {
-	if !rd.eofSeen {
-		buf, err := ioutil.ReadAll(rd)
-		msg := fmt.Sprintf("body not drained, %d bytes not read", len(buf))
-		if err != nil {
-			msg += fmt.Sprintf(", error: %v", err)
-		}
-
-		if len(buf) > 0 {
-			if len(buf) > 20 {
-				buf = append(buf[:20], []byte("...")...)
-			}
-			msg += fmt.Sprintf(", body: %q", buf)
-		}
-
-		fmt.Fprintln(os.Stderr, msg)
-		Log("%s: %+v", msg, errors.New("Close()"))
-	}
-	return rd.rd.Close()
-}
-
-func (tr eofDetectRoundTripper) RoundTrip(req *http.Request) (res *http.Response, err error) {
-	res, err = tr.RoundTripper.RoundTrip(req)
-	if res != nil && res.Body != nil {
-		res.Body = &eofDetectReader{rd: res.Body}
-	}
-	return res, err
-}
-
-type loggingRoundTripper struct {
-	http.RoundTripper
-}
 
 // RoundTripper returns a new http.RoundTripper which logs all requests (if
 // debug is enabled). When debug is not enabled, upstream is returned.
@@ -74,57 +15,3 @@ func RoundTripper(upstream http.RoundTripper) http.RoundTripper {
 	}
 	return eofRoundTripper
 }
-
-func redactHeader(header http.Header) map[string][]string {
-	removedHeaders := make(map[string][]string)
-	for _, hdr := range []string{
-		"Authorization",
-		"X-Auth-Token", // Swift headers
-		"X-Auth-Key",
-	} {
-		origHeader, hasHeader := header[hdr]
-		if hasHeader {
-			removedHeaders[hdr] = origHeader
-			header[hdr] = []string{"**redacted**"}
-		}
-	}
-	return removedHeaders
-}
-
-func restoreHeader(header http.Header, origHeaders map[string][]string) {
-	for hdr, val := range origHeaders {
-		header[hdr] = val
-	}
-}
-
-func (tr loggingRoundTripper) RoundTrip(req *http.Request) (res *http.Response, err error) {
-	// save original auth and redact it
-	origHeaders := redactHeader(req.Header)
-
-	trace, err := httputil.DumpRequestOut(req, false)
-	if err != nil {
-		Log("DumpRequestOut() error: %v\n", err)
-	} else {
-		Log("------------  HTTP REQUEST -----------\n%s", trace)
-	}
-
-	restoreHeader(req.Header, origHeaders)
-
-	res, err = tr.RoundTripper.RoundTrip(req)
-	if err != nil {
-		Log("RoundTrip() returned error: %v", err)
-	}
-
-	if res != nil {
-		origHeaders := redactHeader(res.Header)
-		trace, err := httputil.DumpResponse(res, false)
-		restoreHeader(res.Header, origHeaders)
-		if err != nil {
-			Log("DumpResponse() error: %v\n", err)
-		} else {
-			Log("------------  HTTP RESPONSE ----------\n%s", trace)
-		}
-	}
-
-	return res, err
-}

internal/debug/round_tripper_release.go

@@ -8,5 +8,9 @@ import "net/http"
 // RoundTripper returns a new http.RoundTripper which logs all requests (if
 // debug is enabled). When debug is not enabled, upstream is returned.
 func RoundTripper(upstream http.RoundTripper) http.RoundTripper {
+	if opts.isEnabled {
+		// only use loggingRoundTripper if the debug log is configured
+		return loggingRoundTripper{eofDetectRoundTripper{upstream}}
+	}
 	return upstream
 }

internal/debug/round_tripper_test.go

@@ -1,5 +1,3 @@
-// +build debug
-
 package debug
 
 import (