From ee9bbb0bf285dedfaca95e7557eac236329be2ab Mon Sep 17 00:00:00 2001 From: peusebiu Date: Tue, 16 Jan 2024 19:08:14 +0200 Subject: [PATCH] feat(log): print traceback when panics occur (#2166) Signed-off-by: Petu Eusebiu --- THIRD-PARTY-LICENSES.md | 2 - go.mod | 3 +- go.sum | 1 - pkg/api/controller.go | 6 +-- pkg/api/controller_test.go | 34 +++++++++++++++ pkg/api/recovery.go | 85 ++++++++++++++++++++++++++++++++++++++ 6 files changed, 122 insertions(+), 9 deletions(-) create mode 100644 pkg/api/recovery.go diff --git a/THIRD-PARTY-LICENSES.md b/THIRD-PARTY-LICENSES.md index 3ddb6a5f..717f6def 100644 --- a/THIRD-PARTY-LICENSES.md +++ b/THIRD-PARTY-LICENSES.md @@ -147,7 +147,6 @@ github.com/emirpasic/gods|https://github.com/emirpasic/gods/blob/v1.18.1/LICENSE github.com/evanphx/json-patch|https://github.com/evanphx/json-patch/blob/v5.6.0/LICENSE|BSD-3-Clause github.com/exponent-io/jsonpath|https://github.com/exponent-io/jsonpath/blob/d6023ce2651d/LICENSE|MIT github.com/fatih/color|https://github.com/fatih/color/blob/v1.15.0/LICENSE.md|MIT -github.com/felixge/httpsnoop|https://github.com/felixge/httpsnoop/blob/v1.0.4/LICENSE.txt|MIT github.com/fsnotify/fsnotify|https://github.com/fsnotify/fsnotify/blob/v1.7.0/LICENSE|BSD-3-Clause github.com/go-asn1-ber/asn1-ber|https://github.com/go-asn1-ber/asn1-ber/blob/v1.5.5/LICENSE|MIT github.com/go-chi/chi|https://github.com/go-chi/chi/blob/v4.1.2/LICENSE|MIT @@ -198,7 +197,6 @@ github.com/google/uuid|https://github.com/google/uuid/blob/v1.4.0/LICENSE|BSD-3- github.com/google/wire|https://github.com/google/wire/blob/v0.5.0/LICENSE|Apache-2.0 github.com/googleapis/enterprise-certificate-proxy/client|https://github.com/googleapis/enterprise-certificate-proxy/blob/v0.3.2/LICENSE|Apache-2.0 github.com/googleapis/gax-go/v2|https://github.com/googleapis/gax-go/blob/v2.12.0/v2/LICENSE|BSD-3-Clause -github.com/gorilla/handlers|https://github.com/gorilla/handlers/blob/v1.5.2/LICENSE|BSD-3-Clause github.com/gorilla/mux|https://github.com/gorilla/mux/blob/v1.8.0/LICENSE|BSD-3-Clause github.com/gorilla/schema|https://github.com/gorilla/schema/blob/v1.2.0/LICENSE|BSD-3-Clause github.com/gorilla/securecookie|https://github.com/gorilla/securecookie/blob/v1.1.2/LICENSE|BSD-3-Clause diff --git a/go.mod b/go.mod index cc42fab7..f5f98465 100644 --- a/go.mod +++ b/go.mod @@ -50,7 +50,6 @@ require ( github.com/aws/aws-secretsmanager-caching-go v1.1.3 github.com/containers/image/v5 v5.29.0 github.com/google/go-github/v52 v52.0.0 - github.com/gorilla/handlers v1.5.2 github.com/gorilla/securecookie v1.1.2 github.com/gorilla/sessions v1.2.2 github.com/migueleliasweb/go-github-mock v0.0.22 @@ -124,7 +123,6 @@ require ( github.com/emicklei/go-restful/v3 v3.11.0 // indirect github.com/evanphx/json-patch v5.6.0+incompatible // indirect github.com/exponent-io/jsonpath v0.0.0-20151013193312-d6023ce2651d // indirect - github.com/felixge/httpsnoop v1.0.4 // indirect github.com/go-errors/errors v1.4.2 // indirect github.com/go-gorp/gorp/v3 v3.0.5 // indirect github.com/go-ini/ini v1.67.0 // indirect @@ -139,6 +137,7 @@ require ( github.com/google/licenseclassifier/v2 v2.0.0 // indirect github.com/google/s2a-go v0.1.7 // indirect github.com/google/shlex v0.0.0-20191202100458-e7afc7fbc510 // indirect + github.com/gorilla/handlers v1.5.2 // indirect github.com/gosuri/uitable v0.0.4 // indirect github.com/gregjones/httpcache v0.0.0-20180305231024-9cad4c3443a7 // indirect github.com/jmoiron/sqlx v1.3.5 // indirect diff --git a/go.sum b/go.sum index 6e5981c6..ec886794 100644 --- a/go.sum +++ b/go.sum @@ -670,7 +670,6 @@ github.com/fatih/color v1.13.0/go.mod h1:kLAiJbzzSOZDVNGyDpeOxJ47H46qBXwg5ILebYF github.com/fatih/color v1.15.0 h1:kOqh6YHBtK8aywxGerMG2Eq3H6Qgoqeo13Bk2Mv/nBs= github.com/fatih/color v1.15.0/go.mod h1:0h5ZqXfHYED7Bhv2ZJamyIOUej9KtShiJESRwBDUSsw= github.com/felixge/httpsnoop v1.0.4 h1:NFTV2Zj1bL4mc9sqWACXbQFVBBg2W3GPvqp8/ESS2Wg= -github.com/felixge/httpsnoop v1.0.4/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U= github.com/fortytw2/leaktest v1.3.0 h1:u8491cBMTQ8ft8aeV+adlcytMZylmA5nnwwkRZjI8vw= github.com/foxcpp/go-mockdns v1.0.0 h1:7jBqxd3WDWwi/6WhDvacvH1XsN3rOLXyHM1uhvIx6FI= github.com/frankban/quicktest v1.14.3/go.mod h1:mgiwOwqx65TmIk1wJ6Q7wvnVMocbUorkibMOrVTHZps= diff --git a/pkg/api/controller.go b/pkg/api/controller.go index 4c1ad625..582411b6 100644 --- a/pkg/api/controller.go +++ b/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)) diff --git a/pkg/api/controller_test.go b/pkg/api/controller_test.go index cd94621b..9db8a225 100644 --- a/pkg/api/controller_test.go +++ b/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() diff --git a/pkg/api/recovery.go b/pkg/api/recovery.go new file mode 100644 index 00000000..ee143c3f --- /dev/null +++ b/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 +}