feat(log): print traceback when panics occur (#2166)

Signed-off-by: Petu Eusebiu <peusebiu@cisco.com>

pkg/api/controller.go

@@ -14,7 +14,6 @@ import (
 	"syscall"
 	"time"
 
-	"github.com/gorilla/handlers"
 	"github.com/gorilla/mux"
 	"github.com/zitadel/oidc/pkg/client/rp"
 
@@ -117,9 +116,8 @@ func (c *Controller) Run() error {
 
 	engine.Use(
 		SessionLogger(c),
-		handlers.RecoveryHandler(
-			handlers.PrintRecoveryStack(true),
-		))
+		RecoveryHandler(c.Log),
+	)
 
 	if c.Audit != nil {
 		engine.Use(SessionAuditLogger(c.Audit))

pkg/api/controller_test.go

@@ -61,6 +61,7 @@ import (
 	"zotregistry.io/zot/pkg/storage"
 	storageConstants "zotregistry.io/zot/pkg/storage/constants"
 	"zotregistry.io/zot/pkg/storage/gc"
+	storageTypes "zotregistry.io/zot/pkg/storage/types"
 	authutils "zotregistry.io/zot/pkg/test/auth"
 	test "zotregistry.io/zot/pkg/test/common"
 	"zotregistry.io/zot/pkg/test/deprecated"
@@ -959,6 +960,39 @@ func TestBlobReferenced(t *testing.T) {
 	})
 }
 
+func TestPrintTracebackOnPanic(t *testing.T) {
+	Convey("Run server on unavailable port", t, func() {
+		port := test.GetFreePort()
+		baseURL := test.GetBaseURL(port)
+
+		conf := config.New()
+		conf.HTTP.Port = port
+
+		logFile, err := os.CreateTemp("", "zot-log*.txt")
+		So(err, ShouldBeNil)
+		conf.Log.Output = logFile.Name()
+		defer os.Remove(logFile.Name()) // clean up
+
+		ctlr := makeController(conf, t.TempDir())
+		cm := test.NewControllerManager(ctlr)
+
+		cm.StartAndWait(port)
+		defer cm.StopServer()
+
+		ctlr.StoreController.SubStore = make(map[string]storageTypes.ImageStore)
+		ctlr.StoreController.SubStore["/a"] = nil
+
+		resp, err := resty.R().Get(baseURL + "/v2/_catalog")
+		So(err, ShouldBeNil)
+		So(resp, ShouldNotBeNil)
+		So(resp.StatusCode(), ShouldEqual, http.StatusInternalServerError)
+
+		data, err := os.ReadFile(logFile.Name())
+		So(err, ShouldBeNil)
+		So(string(data), ShouldContainSubstring, "invalid memory address or nil pointer dereference")
+	})
+}
+
 func TestInterruptedBlobUpload(t *testing.T) {
 	Convey("Successfully cleaning interrupted blob uploads", t, func() {
 		port := test.GetFreePort()

pkg/api/recovery.go

@@ -0,0 +1,85 @@
+package api
+
+import (
+	"encoding/json"
+	"net/http"
+	"runtime"
+
+	"github.com/gorilla/mux"
+
+	"zotregistry.io/zot/pkg/log"
+)
+
+type Stack struct {
+	Frames []Frame `json:"stack"`
+}
+
+type Frame struct {
+	Name string `json:"function"`
+	File string `json:"file"`
+	Line int    `json:"line"`
+}
+
+// RecoveryHandler is a HTTP middleware that recovers from a panic.
+// It logs the panic and its traceback in json format, writes http.StatusInternalServerError
+// and continues to the next handler.
+func RecoveryHandler(log log.Logger) mux.MiddlewareFunc {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(response http.ResponseWriter, request *http.Request) {
+			defer func() {
+				if err := recover(); err != nil {
+					response.WriteHeader(http.StatusInternalServerError)
+
+					stack := Stack{
+						Frames: getStacktrace(),
+					}
+
+					recoveredErr, ok := err.(error)
+					if ok {
+						buf, err := json.Marshal(stack)
+						if err == nil {
+							log.Error().Err(recoveredErr).RawJSON("traceback", buf).Msg("panic recovered") //nolint: check-logs
+						}
+					}
+				}
+			}()
+
+			// Process request
+			next.ServeHTTP(response, request)
+		})
+	}
+}
+
+func getStacktrace() []Frame {
+	stack := []Frame{}
+	//nolint: varnamelen
+	pc := make([]uintptr, 64)
+
+	n := runtime.Callers(0, pc)
+	if n == 0 {
+		return []Frame{}
+	}
+
+	// first three frames are from this file, don't need them.
+	pc = pc[3:]
+	frames := runtime.CallersFrames(pc)
+
+	// loop to get frames.
+	for {
+		frame, more := frames.Next()
+
+		// store this frame
+		stack = append(stack, Frame{
+			Name: frame.Function,
+			File: frame.File,
+			Line: frame.Line,
+		})
+
+		// check whether there are more frames to process after this one.
+		if !more {
+			break
+		}
+	}
+
+	return stack
+}