accesslog: log error bodies and communicate with the recover middleware

HISTORY.md

@@ -609,6 +609,7 @@ New Package-level Variables:
 
 New Context Methods:
 
+- `Context.IsRecovered()` reports whether the current request was recovered from the [recover middleware](https://github.com/kataras/iris/tree/master/middleware/recover). Also the `iris.IsErrPrivate` function and `iris.ErrPrivate` interface have been introduced. 
 - `Context.RecordBody()` same as the Application's `DisableBodyConsumptionOnUnmarshal` configuration field but registers per chain of handlers. It makes the request body readable more than once.
 - `Context.IsRecordingBody() bool` reports whether the request body can be readen multiple times.
 - `Context.ReadHeaders(ptr interface{}) error` binds request headers to "ptr". [Example](https://github.com/kataras/iris/blob/master/_examples/request-body/read-headers/main.go).

_examples/logging/request-logger/accesslog-broker/main.go

@@ -3,6 +3,7 @@ package main
 import (
 	"github.com/kataras/iris/v12"
 	"github.com/kataras/iris/v12/middleware/accesslog"
+	"github.com/kataras/iris/v12/middleware/recover"
 )
 
 func main() {
@@ -16,13 +17,18 @@ func main() {
 
 	ac := accesslog.File("./access.log")
 	ac.TimeFormat = "2006-01-02 15:04:05"
+	// ac.KeepMultiLineError = false // set to false to print errors as one line.
 	// Optionally run logging after response has sent:
 	// ac.Async = true
 	broker := ac.Broker() // <- IMPORTANT
 
 	app := iris.New()
 	app.UseRouter(ac.Handler)
+	app.UseRouter(recover.New())
 
+	app.OnErrorCode(iris.StatusNotFound, notFoundHandler)
+
+	app.Get("/panic", testPanic)
 	app.Get("/", indexHandler)
 	app.Get("/profile/{username}", profileHandler)
 	app.Post("/read_body", readBodyHandler)
@@ -36,6 +42,22 @@ func main() {
 	app.Listen(":8080")
 }
 
+func notFoundHandler(ctx iris.Context) {
+	ctx.Application().Logger().Infof("Not Found Handler for: %s", ctx.Path())
+
+	suggestPaths := ctx.FindClosest(3)
+	if len(suggestPaths) == 0 {
+		ctx.WriteString("The page you're looking does not exist.")
+		return
+	}
+
+	ctx.HTML("Did you mean?<ul>")
+	for _, s := range suggestPaths {
+		ctx.HTML(`<li><a href="%s">%s</a></li>`, s, s)
+	}
+	ctx.HTML("</ul>")
+}
+
 func indexHandler(ctx iris.Context) {
 	ctx.HTML("<h1>Index</h1>")
 }
@@ -55,6 +77,10 @@ func readBodyHandler(ctx iris.Context) {
 	ctx.JSON(iris.Map{"message": "OK", "data": request})
 }
 
+func testPanic(ctx iris.Context) {
+	panic("PANIC HERE")
+}
+
 func logsHandler(b *accesslog.Broker) iris.Handler {
 	return func(ctx iris.Context) {
 		// accesslog.Skip(ctx) // or inline skip.

aliases.go

@@ -162,6 +162,10 @@ type (
 	// Locale describes the i18n locale.
 	// An alias for the `context.Locale`.
 	Locale = context.Locale
+	// ErrPrivate if provided then the error saved in context
+	// should NOT be visible to the client no matter what.
+	// An alias for the `context.ErrPrivate`.
+	ErrPrivate = context.ErrPrivate
 )
 
 // Constants for input argument at `router.RouteRegisterRule`.
@@ -458,6 +462,8 @@ var (
 	// on post data, versioning feature and others.
 	// An alias of `context.ErrNotFound`.
 	ErrNotFound = context.ErrNotFound
+	// IsErrPrivate reports whether the given "err" is a private one.
+	IsErrPrivate = context.IsErrPrivate
 	// NewProblem returns a new Problem.
 	// Head over to the `Problem` type godoc for more.
 	//

context/context.go

@@ -706,12 +706,22 @@ func (ctx *Context) StopWithText(statusCode int, format string, args ...interfac
 //
 // If the status code is a failure one then
 // it will also fire the specified error code handler.
+//
+// If the given "err" is private then the
+// status code's text is rendered instead (unless a registered error handler overrides it).
 func (ctx *Context) StopWithError(statusCode int, err error) {
 	if err == nil {
 		return
 	}
 
 	ctx.SetErr(err)
+	if IsErrPrivate(err) {
+		// error is private, we can't render it, instead .
+		// let the error handler render the code text.
+		ctx.StopWithStatus(statusCode)
+		return
+	}
+
 	ctx.StopWithText(statusCode, err.Error())
 }
 
@@ -4782,7 +4792,32 @@ func (ctx *Context) IsRecording() (*ResponseRecorder, bool) {
 
 // ErrPanicRecovery may be returned from `Context` actions of a `Handler`
 // which recovers from a manual panic.
-// var ErrPanicRecovery = errors.New("recovery from 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.
@@ -5052,6 +5087,21 @@ 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
+			}
+		}
+	}
+
+	return ErrPanicRecovery{}, false
+}
+
 const idContextKey = "iris.context.id"
 
 // SetID sets an ID, any value, to the Request Context.

core/router/handler.go

@@ -130,10 +130,14 @@ type RoutesProvider interface { // api builder
 
 func defaultErrorHandler(ctx *context.Context) {
 	if err := ctx.GetErr(); err != nil {
-		ctx.WriteString(err.Error())
-	} else {
-		ctx.WriteString(context.StatusText(ctx.GetStatusCode()))
+		if !context.IsErrPrivate(err) {
+			ctx.WriteString(err.Error())
+			return
+		}
 	}
+
+	ctx.WriteString(context.StatusText(ctx.GetStatusCode()))
+
 }
 
 func (h *routerHandler) Build(provider RoutesProvider) error {

middleware/accesslog/accesslog.go

@@ -6,6 +6,7 @@ import (
 	"io"
 	"net/http/httputil"
 	"os"
+	"strings"
 	"sync"
 	"time"
 
@@ -150,6 +151,10 @@ type AccessLog struct {
 	// Note that, if this is true then it uses a response recorder.
 	ResponseBody bool
 
+	// KeepMultiLineError displays the Context's error as it's.
+	// If set to false then it replaces all line characters with spaces.
+	KeepMultiLineError bool
+
 	// Map log fields with custom request values.
 	// See `AddFields` method.
 	FieldSetters []FieldSetter
@@ -168,11 +173,12 @@ type AccessLog struct {
 // Example: https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog
 func New(w io.Writer) *AccessLog {
 	ac := &AccessLog{
-		BytesReceived: true,
-		BytesSent:     true,
-		BodyMinify:    true,
-		RequestBody:   true,
-		ResponseBody:  true,
+		BytesReceived:      true,
+		BytesSent:          true,
+		BodyMinify:         true,
+		RequestBody:        true,
+		ResponseBody:       true,
+		KeepMultiLineError: true,
 	}
 
 	if w == nil {
@@ -367,7 +373,28 @@ func (ac *AccessLog) Handler(ctx *context.Context) {
 	// So we initialize them whenever, and if, asked.
 
 	// Proceed to the handlers chain.
+	currentIndex := ctx.HandlerIndex(-1)
 	ctx.Next()
+	if context.StatusCodeNotSuccessful(ctx.GetStatusCode()) {
+		_, wasRecovered := ctx.IsRecovered()
+		// The ctx.HandlerName is still accesslog because
+		// on end of router filters the router resets
+		// the handler index, same for errors.
+		// So, as a special case, if it's a failure status code
+		// call FireErorrCode manually instead of wait
+		// to be called on EndRequest (which is, correctly, called on end of everything
+		// so we don't have chance to record its body by default).
+		//
+		// Note: this however will call the error handler twice
+		// if the end-developer registered that using `UseError` instead of `UseRouter`,
+		// there is a way to fix that too: by checking the handler index diff:
+		if currentIndex == ctx.HandlerIndex(-1) || wasRecovered {
+			// if handler index before and after ctx.Next
+			// is the same, then it means we are in `UseRouter`
+			// and on error handler.
+			ctx.Application().FireErrorCode(ctx)
+		}
+	}
 
 	if shouldSkip(ctx) { // normal flow, we can get the context by executing the handler first.
 		return
@@ -398,12 +425,12 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 			// If there is an error here
 			// we may need to NOT read the body for security reasons, e.g.
 			// unauthorized user tries to send a malicious body.
-			requestBody = fmt.Sprintf("error(%s)", ctxErr.Error())
+			requestBody = ac.getErrorText(ctxErr)
 		} else {
 			requestData, err := ctx.GetBody()
 			requestBodyLength := len(requestData)
 			if err != nil && ac.RequestBody {
-				requestBody = fmt.Sprintf("error(%s)", err)
+				requestBody = ac.getErrorText(err)
 			} else if requestBodyLength > 0 {
 				if ac.RequestBody {
 					if ac.BodyMinify {
@@ -554,3 +581,15 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm
 
 	return
 }
+
+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())
+
+	if !ac.KeepMultiLineError {
+		return lineBreaksReplacer.Replace(text)
+	}
+
+	return text
+}

middleware/recover/recover.go

@@ -41,12 +41,13 @@ func New() context.Handler {
 
 				// when stack finishes
 				logMessage := fmt.Sprintf("Recovered from a route's Handler('%s')\n", ctx.HandlerName())
-				logMessage += fmt.Sprintf("At Request: %s\n", getRequestLogs(ctx))
-				logMessage += fmt.Sprintf("Trace: %s\n", err)
-				logMessage += fmt.Sprintf("\n%s", stacktrace)
+				logMessage += fmt.Sprint(getRequestLogs(ctx))
+				logMessage += fmt.Sprintf("%s\n", err)
+				logMessage += fmt.Sprintf("%s\n", stacktrace)
 				ctx.Application().Logger().Warn(logMessage)
 
-				ctx.StopWithStatus(500)
+				// see accesslog.isPanic too.
+				ctx.StopWithPlainError(500, context.ErrPanicRecovery{Cause: err, Stacktrace: stacktrace})
 			}
 		}()