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

_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

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"

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)

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,
+				})
 			}
 		}()