accesslog: add IP in builtin fields, change the format a bit. Default func: remove compression middleware, force-set debug log level, replace the old request logger with the accesslog one, use request id middlewareand keep recovery

.gitignore

@@ -4,6 +4,6 @@ coverage.out
 package-lock.json
 go.sum
 node_modules
-/_examples/issue-*/
+issue-*/
 /_examples/feature-*/
 _examples/**/uploads/*

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

@@ -18,9 +18,9 @@ func main() {
 	*/
 
 	ac := accesslog.File("./access.log")
-	ac.AddOutput(os.Stdout)
+	defer ac.Close()
 
-	ac.TimeFormat = "2006-01-02 15:04:05"
+	ac.AddOutput(os.Stdout)
 
 	// Set to false to print errors as one line:
 	// ac.KeepMultiLineError = false

_examples/logging/request-logger/accesslog-template/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/requestid"
 )
 
 func main() {
@@ -14,21 +15,23 @@ func main() {
 
 	app := iris.New()
 	ac := accesslog.File("./access.log").AddOutput(app.Logger().Printer)
-	ac.TimeFormat = "2006-01-02 15:04:05"
 
 	// 1. Register a field.
 	ac.AddFields(func(ctx iris.Context, fields *accesslog.Fields) {
-		fields.Set("IP", ctx.RemoteAddr())
+		fields.Set("Request ID", ctx.GetID())
 	})
 
 	// 2. Use Template formatter's `Text` value
 	// to define a log line format.
 	ac.SetFormatter(&accesslog.Template{
-		Text: `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.Fields.Get "IP" }}
+		Text: `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.IP}} {{.Fields.Get "Request ID" }}
-`, /*             2020-09-10 21:38:13 / 200 ::1 */
+`, /*             2020-09-11 09:30:10 / 200 ::1 050a0979-c5e4-4c2b-9f08-cb456628edb1 */
 	})
 	// 3. Register the middleware. That's all.
 	app.UseRouter(ac.Handler)
+	// Register the request id middleware, after the logger,  this maps the Context.GetID().
+	// Remember: the accesslog runs the next handlers before itself to provide some fields.
+	app.UseRouter(requestid.New())
 
 	app.Get("/", index)
 
@@ -42,7 +45,7 @@ func index(ctx iris.Context) {
 /* Use a custom *template.Template:
 
 // 2.1 The log line format:
-text := `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.Fields.Get "IP" }}
+text := `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.IP}} {{.Fields.Get "Request ID" }}
 `
 //
 // 2.2 Parse the template, optionally using custom Template Functions.

_examples/logging/request-logger/accesslog/access.log.sample

@@ -1,9 +1,9 @@
-2020-09-08 13:34:42|0s|POST|/read_body||200|324 B|217 B|{"name":"John","email":"example@example.com"}|{"data":{"email":"example@example.com","name":"John"},"message":"OK"}|
+2020-09-08 13:34:42|0s|200|POST|/read_body|::1||324 B|217 B|{"name":"John","email":"example@example.com"}|{"data":{"email":"example@example.com","name":"John"},"message":"OK"}|
-2020-09-08 13:40:28|0s|POST|/read_body||400||85 B|error(invalid character '\r' in string literal)||
+2020-09-08 13:40:28|0s|400|POST|/read_body|::1|||85 B|error(invalid character '\r' in string literal)||
-2020-09-08 13:41:05|1.0024ms|GET|/|a=1 b=2|200|767 B|251 B||<h1>Hello index</h1>|
+2020-09-08 13:41:05|1.0024ms|200|GET|/|a=1 b=2|767 B|251 B||<h1>Hello index</h1>|
-2020-09-08 13:41:26|0s|GET|/public||404|765 B|83 B|||
+2020-09-08 13:41:26|0s|404|GET|/public|::1||765 B|83 B|||
-2020-09-08 13:41:36|0s|GET|/user/kataras|username=kataras|200|771 B|91 B||Hello, kataras!|
+2020-09-08 13:41:36|0s|200|GET|/user/kataras|::1|username=kataras|771 B|91 B||Hello, kataras!|
-2020-09-08 13:41:47|0s|GET|/user/kataras|username=kataras a_query_parameter=name|200|774 B|91 B||Hello, kataras!|
+2020-09-08 13:41:47|0s|200|GET|/user/kataras|::1|username=kataras a_query_parameter=name|774 B|91 B||Hello, kataras!|
-2020-09-08 20:37:33|0s|GET|/admin|auth=admin:admin|200|608 B|164 B||<h2>Username: admin</h2><h3>Password: admin</h3>|
+2020-09-08 20:37:33|0s|200|GET|/admin|::1|auth=admin:admin|608 B|164 B||<h2>Username: admin</h2><h3>Password: admin</h3>|
-2020-09-09 07:56:00|738.1µs|GET|/session|session_id=23fe763f-c9d5-4d65-9e1a-2cc8d23d1aa3 session_test_key=session_test_value|200|818 B|302 B||OK|
+2020-09-09 07:56:00|738.1µs|200|GET|/session|::1|session_id=23fe763f-c9d5-4d65-9e1a-2cc8d23d1aa3 session_test_key=session_test_value|818 B|302 B||OK|
-2020-09-09 08:36:47|2.0095505s|GET|/fields|job_latency=2s|200|544 B|130 B||OK|
+2020-09-09 08:36:47|2.0095505s|200|GET|/fields|::1|job_latency=2s|544 B|130 B||OK|

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

@@ -26,7 +26,8 @@ func makeAccessLog() *accesslog.AccessLog {
 	// Initialize a new access log middleware.
 	// Accepts an `io.Writer`.
 	ac := accesslog.New(w)
-	ac.TimeFormat = "2006-01-02 15:04:05"
+	defer ac.Close()
+	// ac.TimeFormat = "2006-01-02 15:04:05" // default
 
 	// Example of adding more than one field to the logger.
 	// Here we logging all the session values this request has.
@@ -81,7 +82,7 @@ func makeAccessLog() *accesslog.AccessLog {
 		Modify the output format and customize the order
 		with the Template formatter:
 		ac.SetFormatter(&accesslog.Template{
-		    Text: "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n",
+		    Text: "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Code}}|{{.Method}}|{{.Path}}|{{.IP}}|{{.RequestValuesLine}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n",
 		    // Default ^
 		})
 	*/

core/router/api_builder.go

@@ -961,7 +961,7 @@ func (api *APIBuilder) GetRouterFilters() map[Party]*Filter {
 // The context SHOULD call its `Next` method in order to proceed to
 // the next handler in the chain or the main request handler one.
 func (api *APIBuilder) UseRouter(handlers ...context.Handler) {
-	if len(handlers) == 0 {
+	if len(handlers) == 0 || handlers[0] == nil {
 		return
 	}
 

iris.go

@@ -19,8 +19,9 @@ import (
 	"github.com/kataras/iris/v12/core/netutil"
 	"github.com/kataras/iris/v12/core/router"
 	"github.com/kataras/iris/v12/i18n"
-	requestLogger "github.com/kataras/iris/v12/middleware/logger"
+	"github.com/kataras/iris/v12/middleware/accesslog"
 	"github.com/kataras/iris/v12/middleware/recover"
+	"github.com/kataras/iris/v12/middleware/requestid"
 	"github.com/kataras/iris/v12/view"
 
 	"github.com/kataras/golog"
@@ -128,14 +129,40 @@ func New() *Application {
 	return app
 }
 
-// Default returns a new Application instance which on build state registers
+// Default returns a new Application.
-// html view engine on "./views" and load locales from "./locales/*/*".
+// Default with "debug" Logger Level.
-// The return instance recovers on panics and logs the incoming http requests too.
+// Localization enabled on "./locales" directory
+// and HTML templates on "./views" or "./templates" directory.
+// It runs with the AccessLog on "./access.log",
+// Recovery and Request ID middleware already attached.
 func Default() *Application {
 	app := New()
+	// Set default log level.
+	app.logger.SetLevel("debug")
+	app.logger.Debugf(`Log level set to "debug"`)
+
+	// Register the accesslog middleware.
+	logFile, err := os.OpenFile("./access.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
+	if err == nil {
+		// Close the file on shutdown.
+		app.ConfigureHost(func(su *Supervisor) {
+			su.RegisterOnShutdown(func() {
+				logFile.Close()
+			})
+		})
+
+		app.UseRouter(accesslog.New(logFile).Handler)
+		app.logger.Debugf("Using <%s> to log requests", logFile.Name())
+	}
+
+	// Register the requestid middleware
+	// before recover so current Context.GetID() contains the info on panic logs.
+	app.UseRouter(requestid.New())
+	app.logger.Debugf("Using <UUID4> to identify requests")
+
+	// Register the recovery, after accesslog and recover,
+	// before end-developer's middleware.
 	app.UseRouter(recover.New())
-	app.UseRouter(requestLogger.New())
-	app.UseRouter(Compression)
 
 	app.defaultMode = true
 
@@ -544,7 +571,7 @@ func (app *Application) Build() error {
 	if app.defaultMode { // the app.I18n and app.View will be not available until Build.
 		if !app.I18n.Loaded() {
 			for _, s := range []string{"./locales/*/*", "./locales/*", "./translations"} {
-				if _, err := os.Stat(s); os.IsNotExist(err) {
+				if _, err := os.Stat(s); err != nil {
 					continue
 				}
 
@@ -559,7 +586,7 @@ func (app *Application) Build() error {
 
 		if app.view.Len() == 0 {
 			for _, s := range []string{"./views", "./templates", "./web/views"} {
-				if _, err := os.Stat(s); os.IsNotExist(err) {
+				if _, err := os.Stat(s); err != nil {
 					continue
 				}
 

middleware/accesslog/accesslog.go

@@ -10,7 +10,6 @@ import (
 	"sync"
 	"time"
 
-	"github.com/kataras/iris/v12"
 	"github.com/kataras/iris/v12/context"
 	"github.com/kataras/iris/v12/core/memstore"
 )
@@ -27,7 +26,7 @@ const (
 // GetFields returns the accesslog fields for this request.
 // Returns a store which the caller can use to
 // set/get/remove custom log fields. Use its `Set` method.
-func GetFields(ctx iris.Context) (fields *Fields) {
+func GetFields(ctx *context.Context) (fields *Fields) {
 	if v := ctx.Values().Get(fieldsContextKey); v != nil {
 		fields = v.(*Fields)
 	} else {
@@ -40,18 +39,18 @@ func GetFields(ctx iris.Context) (fields *Fields) {
 
 // Skip called when a specific route should be skipped from the logging process.
 // It's an easy to use alternative for iris.NewConditionalHandler.
-func Skip(ctx iris.Context) {
+func Skip(ctx *context.Context) {
 	ctx.Values().Set(skipLogContextKey, struct{}{})
 }
 
 // SkipHandler same as `Skip` but it can be used
 // as a middleware, it executes ctx.Next().
-func SkipHandler(ctx iris.Context) {
+func SkipHandler(ctx *context.Context) {
 	Skip(ctx)
 	ctx.Next()
 }
 
-func shouldSkip(ctx iris.Context) bool {
+func shouldSkip(ctx *context.Context) bool {
 	return ctx.Values().Get(skipLogContextKey) != nil
 }
 
@@ -134,9 +133,11 @@ type AccessLog struct {
 	// Defaults to false.
 	Async bool
 	// The time format for current time on log print.
-	// Defaults to the Iris Application's TimeFormat.
+	// Defaults to ""2006-01-02 15:04:05" on `New` function.
+	// Set it to empty to inherit the Iris Application's TimeFormat.
 	TimeFormat string
-
+	// IP displays the remote address.
+	IP bool
 	// The actual number of bytes received and sent on the network (headers + body).
 	// It is kind of "slow" operation as it uses the httputil to dumb request
 	// and response to get the total amount of bytes (headers + body).
@@ -197,10 +198,15 @@ const (
 // Register by its `Handler` method.
 // See `File` package-level function too.
 //
-// Example: https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog
+// Examples:
+// https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog
+// https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog-template
+// https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog-broker
 func New(w io.Writer) *AccessLog {
 	ac := &AccessLog{
 		Clock:              clockFunc(time.Now),
+		TimeFormat:         "2006-01-02 15:04:05",
+		IP:                 true,
 		BytesReceived:      true,
 		BytesSent:          true,
 		BodyMinify:         true,
@@ -527,6 +533,11 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 		timeFormat = ctx.Application().ConfigurationReadOnly().GetTimeFormat()
 	}
 
+	ip := ""
+	if ac.IP {
+		ip = ctx.RemoteAddr()
+	}
+
 	if err := ac.Print(ctx,
 		// latency between begin and finish of the handlers chain.
 		lat,
@@ -535,6 +546,8 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 		ctx.GetStatusCode(),
 		// original request's method and path.
 		method, path,
+		// remote ip.
+		ip,
 		requestBody, responseBody,
 		bytesReceived, bytesSent,
 		ctx.Params(), ctx.URLParamsSorted(), *fields,
@@ -545,7 +558,7 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 
 // Print writes a log manually.
 // The `Handler` method calls it.
-func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeFormat string, code int, method, path, reqBody, respBody string, bytesReceived, bytesSent int, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) (err error) {
+func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeFormat string, code int, method, path, ip, reqBody, respBody string, bytesReceived, bytesSent int, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) (err error) {
 	now := ac.Clock.Now()
 
 	if hasFormatter, hasBroker := ac.formatter != nil, ac.broker != nil; hasFormatter || hasBroker {
@@ -555,9 +568,10 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm
 		log.TimeFormat = timeFormat
 		log.Timestamp = now.UnixNano() / 1000000
 		log.Latency = latency
+		log.Code = code
 		log.Method = method
 		log.Path = path
-		log.Code = code
+		log.IP = ip
 		log.Query = query
 		log.PathParams = params.Store
 		log.Fields = fields
@@ -593,13 +607,14 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm
 
 	// the number of separators are the same, in order to be easier
 	// for 3rd-party programs to read the result log file.
-	_, err = fmt.Fprintf(ac, "%s|%s|%s|%s|%s|%d|%s|%s|%s|%s|\n",
+	_, err = fmt.Fprintf(ac, "%s|%s|%d|%s|%s|%s|%s|%s|%s|%s|%s|\n",
 		now.Format(timeFormat),
 		latency,
+		code,
 		method,
 		path,
+		ip,
 		requestValues,
-		code,
 		formatBytes(bytesReceived),
 		formatBytes(bytesSent),
 		reqBody,

middleware/accesslog/accesslog_test.go

@@ -35,7 +35,7 @@ func TestAccessLogPrint_Simple(t *testing.T) {
 
 	for i := 0; i < goroutinesN; i++ {
 		wg.Add(1)
-		expected += "0001-01-01 00:00:00|1s|GET|/path_value?url_query=url_query_value|path_param=path_param_value url_query=url_query_value custom=custom_value|200|||Incoming|Outcoming|\n"
+		expected += "0001-01-01 00:00:00|1s|200|GET|/path_value?url_query=url_query_value|::1|path_param=path_param_value url_query=url_query_value custom=custom_value|||Incoming|Outcoming|\n"
 
 		go func() {
 			defer wg.Done()
@@ -47,6 +47,7 @@ func TestAccessLogPrint_Simple(t *testing.T) {
 				200,
 				"GET",
 				"/path_value?url_query=url_query_value",
+				"::1",
 				"Incoming",
 				"Outcoming",
 				0,
@@ -73,7 +74,6 @@ func TestAccessLogPrint_Simple(t *testing.T) {
 func TestAccessLogBroker(t *testing.T) {
 	w := new(bytes.Buffer)
 	ac := New(w)
-	ac.TimeFormat = "2006-01-02 15:04:05"
 	ac.Clock = TClock(time.Time{})
 	broker := ac.Broker()
 
@@ -123,6 +123,7 @@ func TestAccessLogBroker(t *testing.T) {
 			"",
 			"",
 			"",
+			"",
 			0,
 			0,
 			&context.RequestParams{},
@@ -161,7 +162,6 @@ func (*noOpFormatter) Format(*Log) (bool, error) {
 func BenchmarkAccessLogAfter(b *testing.B) {
 	ac := New(ioutil.Discard)
 	ac.Clock = TClock(time.Time{})
-	ac.TimeFormat = "2006-01-02 15:04:05"
 	ac.BytesReceived = false
 	ac.BytesSent = false
 	ac.BodyMinify = false
@@ -169,6 +169,7 @@ func BenchmarkAccessLogAfter(b *testing.B) {
 	ac.ResponseBody = false
 	ac.KeepMultiLineError = true
 	ac.Async = false
+	ac.IP = false
 	ac.SetFormatter(new(noOpFormatter)) // just to create the log structure.)
 
 	ctx := new(context.Context)

middleware/accesslog/log.go

@@ -28,11 +28,13 @@ type Log struct {
 
 	// Request-Response latency.
 	Latency time.Duration `json:"latency"`
+	// The response status code.
+	Code int `json:"code"`
 	// Init request's Method and Path.
 	Method string `json:"method"`
 	Path   string `json:"path"`
-	// The response status code.
+	// The Remote Address.
-	Code int `json:"code"`
+	IP string `json:"ip,omitempty"`
 	// Sorted URL Query arguments.
 	Query []memstore.StringEntry `json:"query,omitempty"`
 	// Dynamic path parameters.
@@ -223,7 +225,7 @@ func (f *Template) SetOutput(dest io.Writer) {
 	f.dest = dest
 }
 
-const defaultTmplText = "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n"
+const defaultTmplText = "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Code}}|{{.Method}}|{{.Path}}|{{.IP}}|{{.RequestValuesLine}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n"
 
 // Format prints the logs in text/template format.
 func (f *Template) Format(log *Log) (bool, error) {