From 2bb04823b03f1aba0bb357d957ee047a17efce57 Mon Sep 17 00:00:00 2001 From: "Gerasimos (Makis) Maropoulos" Date: Thu, 10 Sep 2020 21:03:34 +0300 Subject: [PATCH] recover, accesslog middlewares: give more information to the stored error, accesslog: make use of that information and introduce panic log levels relative to: https://github.com/kataras/iris/issues/1601#issuecomment-690541789 --- .../request-logger/accesslog-broker/main.go | 7 +- context/context.go | 98 +++++++++++-------- middleware/accesslog/accesslog.go | 39 +++++++- middleware/recover/recover.go | 35 +++++-- 4 files changed, 131 insertions(+), 48 deletions(-) diff --git a/_examples/logging/request-logger/accesslog-broker/main.go b/_examples/logging/request-logger/accesslog-broker/main.go index 4ad995a3..ed970ba1 100644 --- a/_examples/logging/request-logger/accesslog-broker/main.go +++ b/_examples/logging/request-logger/accesslog-broker/main.go @@ -21,7 +21,12 @@ func main() { ac.AddOutput(os.Stdout) ac.TimeFormat = "2006-01-02 15:04:05" - // ac.KeepMultiLineError = false // set to false to print errors as one line. + + // Set to false to print errors as one line: + // ac.KeepMultiLineError = false + // Set the "depth" of a panic trace: + ac.PanicLog = accesslog.LogHandler // or LogCallers or LogStack + // Optionally run logging after response has sent: // ac.Async = true broker := ac.Broker() // <- IMPORTANT diff --git a/context/context.go b/context/context.go index a782882c..adb63e1e 100644 --- a/context/context.go +++ b/context/context.go @@ -4790,35 +4790,6 @@ func (ctx *Context) IsRecording() (*ResponseRecorder, bool) { return rr, ok } -// ErrPanicRecovery may be returned from `Context` actions of a `Handler` -// which recovers from a manual panic. -type ErrPanicRecovery struct { - ErrPrivate - Cause interface{} - Stacktrace string -} - -// Error implements the Go standard error type. -func (e ErrPanicRecovery) Error() string { - return fmt.Sprintf("%v\n%s", e.Cause, e.Stacktrace) -} - -// ErrPrivate if provided then the error saved in context -// should NOT be visible to the client no matter what. -type ErrPrivate interface { - IrisPrivateError() -} - -// IsErrPrivate reports whether the given "err" is a private one. -func IsErrPrivate(err error) bool { - if err == nil { - return false - } - - _, ok := err.(ErrPrivate) - return ok -} - // ErrTransactionInterrupt can be used to manually force-complete a Context's transaction // and log(warn) the wrapped error's message. // Usage: `... return fmt.Errorf("my custom error message: %w", context.ErrTransactionInterrupt)`. @@ -5093,19 +5064,68 @@ func (ctx *Context) GetErr() error { return nil } -// IsRecovered reports whether this handler has been recovered -// by the Iris recover middleware. -func (ctx *Context) IsRecovered() (ErrPanicRecovery, bool) { - if ctx.GetStatusCode() == 500 { - // Panic error from recovery middleware is private. - if err := ctx.GetErr(); err != nil { - if panicErr, ok := err.(ErrPanicRecovery); ok { - return panicErr, true - } +// ErrPanicRecovery may be returned from `Context` actions of a `Handler` +// which recovers from a manual panic. +type ErrPanicRecovery struct { + ErrPrivate + Cause interface{} + Callers []string // file:line callers. + Stack []byte // the full debug stack. + RegisteredHandlers []string // file:line of all registered handlers. + CurrentHandler string // the handler panic came from. +} + +// Error implements the Go standard error type. +func (e *ErrPanicRecovery) Error() string { + if e.Cause != nil { + if err, ok := e.Cause.(error); ok { + return err.Error() } } - return ErrPanicRecovery{}, false + return fmt.Sprintf("%v\n%s", e.Cause, strings.Join(e.Callers, "\n")) +} + +// Is completes the internal errors.Is interface. +func (e *ErrPanicRecovery) Is(err error) bool { + _, ok := IsErrPanicRecovery(err) + return ok +} + +// IsErrPanicRecovery reports whether the given "err" is a type of ErrPanicRecovery. +func IsErrPanicRecovery(err error) (*ErrPanicRecovery, bool) { + if err == nil { + return nil, false + } + v, ok := err.(*ErrPanicRecovery) + return v, ok +} + +// ErrPrivate if provided then the error saved in context +// should NOT be visible to the client no matter what. +type ErrPrivate interface { + IrisPrivateError() +} + +// IsErrPrivate reports whether the given "err" is a private one. +func IsErrPrivate(err error) bool { + if err == nil { + return false + } + + _, ok := err.(ErrPrivate) + return ok +} + +// IsRecovered reports whether this handler has been recovered +// by the Iris recover middleware. +func (ctx *Context) IsRecovered() (*ErrPanicRecovery, bool) { + if ctx.GetStatusCode() == 500 { + // Panic error from recovery middleware is private. + return IsErrPanicRecovery(ctx.GetErr()) + } + + return nil, false } const idContextKey = "iris.context.id" diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index d0263240..a6e8036e 100644 --- a/middleware/accesslog/accesslog.go +++ b/middleware/accesslog/accesslog.go @@ -156,8 +156,18 @@ type AccessLog struct { // KeepMultiLineError displays the Context's error as it's. // If set to false then it replaces all line characters with spaces. + // + // See `PanicLog` to customize recovered-from-panic errors even further. KeepMultiLineError bool + // What the logger should write to the output destination + // when recovered from a panic. + // Available options: + // * LogHandler (default, logs the handler's file:line only) + // * LogCallers (logs callers separated by line breaker) + // * LogStack (logs the debug stack) + PanicLog PanicLog + // Map log fields with custom request values. // See `AddFields` method. FieldSetters []FieldSetter @@ -170,6 +180,18 @@ type AccessLog struct { logsPool *sync.Pool } +// PanicLog holds the type for the available panic log levels. +type PanicLog uint8 + +const ( + // LogHandler logs the handler's file:line that recovered from. + LogHandler PanicLog = iota + // LogCallers logs all callers separated by new lines. + LogCallers + // LogStack logs the whole debug stack. + LogStack +) + // New returns a new AccessLog value with the default values. // Writes to the "w". Output be further modified through its `Set/AddOutput` methods. // Register by its `Handler` method. @@ -589,8 +611,21 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm var lineBreaksReplacer = strings.NewReplacer("\n\r", " ", "\n", " ") -func (ac *AccessLog) getErrorText(err error) string { // caller checks for nil. - text := fmt.Sprintf("error(%s)", err.Error()) +func (ac *AccessLog) getErrorText(err error) (text string) { // caller checks for nil. + if errPanic, ok := context.IsErrPanicRecovery(err); ok { + switch ac.PanicLog { + case LogHandler: + text = errPanic.CurrentHandler + case LogCallers: + text = strings.Join(errPanic.Callers, "\n") + case LogStack: + text = string(errPanic.Stack) + } + + text = fmt.Sprintf("error(%v %s)", errPanic.Cause, text) + } else { + text = fmt.Sprintf("error(%s)", err.Error()) + } if !ac.KeepMultiLineError { return lineBreaksReplacer.Replace(text) diff --git a/middleware/recover/recover.go b/middleware/recover/recover.go index 1166e409..949ad076 100644 --- a/middleware/recover/recover.go +++ b/middleware/recover/recover.go @@ -5,6 +5,8 @@ import ( "fmt" "net/http/httputil" "runtime" + "runtime/debug" + "strings" "github.com/kataras/iris/v12/context" ) @@ -29,25 +31,46 @@ func New() context.Handler { return } - var stacktrace string + var callers []string for i := 1; ; i++ { - _, f, l, got := runtime.Caller(i) + _, file, line, got := runtime.Caller(i) if !got { break } - stacktrace += fmt.Sprintf("%s:%d\n", f, l) + callers = append(callers, fmt.Sprintf("%s:%d", file, line)) } // when stack finishes logMessage := fmt.Sprintf("Recovered from a route's Handler('%s')\n", ctx.HandlerName()) logMessage += fmt.Sprint(getRequestLogs(ctx)) logMessage += fmt.Sprintf("%s\n", err) - logMessage += fmt.Sprintf("%s\n", stacktrace) + logMessage += fmt.Sprintf("%s\n", strings.Join(callers, "\n")) ctx.Application().Logger().Warn(logMessage) - // see accesslog.isPanic too. - ctx.StopWithPlainError(500, context.ErrPanicRecovery{Cause: err, Stacktrace: stacktrace}) + // get the list of registered handlers and the + // handler which panic derived from. + handlers := ctx.Handlers() + handlersFileLines := make([]string, 0, len(handlers)) + currentHandlerIndex := ctx.HandlerIndex(-1) + currentHandlerFileLine := "???" + for i, h := range ctx.Handlers() { + file, line := context.HandlerFileLine(h) + fileline := fmt.Sprintf("%s:%d", file, line) + handlersFileLines = append(handlersFileLines, fileline) + if i == currentHandlerIndex { + currentHandlerFileLine = fileline + } + } + + // see accesslog.wasRecovered too. + ctx.StopWithPlainError(500, &context.ErrPanicRecovery{ + Cause: err, + Callers: callers, + Stack: debug.Stack(), + RegisteredHandlers: handlersFileLines, + CurrentHandler: currentHandlerFileLine, + }) } }()