logging: several improvements

Former-commit-id: 12538c74a1aa55314c35ac3cf2665646b704851d

HISTORY.md

@@ -182,8 +182,16 @@ Other Improvements:
 
 - Improved tracing (with `app.Logger().SetLevel("debug")`) for routes. Example:
 
+#### DBUG Routes (1)
+
 ![DBUG routes](https://iris-go.com/images/v12.2.0-dbug.png)
 
+### DBUG Routes (2)
+
+![DBUG routes](https://iris-go.com/images/v12.2.0-dbug2.png)
+
+- Finally, Log level's and Route debug information colorization is respected across outputs. Previously if the application used more than one output destination (e.g. a file through `app.Logger().AddOutput`) the color support was automatically disabled from all, including the terminal one, this problem is fixed now. Developers can now see colors in their terminals while log files are kept with clear text.
+
 - New `iris.WithLowercaseRouting` option which forces all routes' paths to be lowercase and converts request paths to their lowercase for matching.
 
 - New `app.Validator { Struct(interface{}) error }` field and `app.Validate` method were added. The `app.Validator = ` can be used to integrate a 3rd-party package such as [go-playground/validator](https://github.com/go-playground/validator). If set-ed then Iris `Context`'s `ReadJSON`, `ReadXML`, `ReadMsgPack`, `ReadYAML`, `ReadForm`, `ReadQuery`, `ReadBody` methods will return the validation error on data validation failures. The [read-json-struct-validation](_examples/http_request/read-json-struct-validation) example was updated.
@@ -224,6 +232,7 @@ Breaking Changes:
 
 Change the MIME type of `Javascript .js` and `JSONP` as the HTML specification now recommends to `"text/javascript"` instead of the obselete `"application/javascript"`. This change was pushed to the `Go` language itself as well. See <https://go-review.googlesource.com/c/go/+/186927/>.
 
+- `route.Trace() string` changed to `route.Trace(w io.Writer)`, to achieve the same result just pass a `bytes.Buffer`
 - `var mvc.AutoBinding` removed as the default behavior now resolves such dependencies automatically (see [[FEATURE REQUEST] MVC serving gRPC-compatible controller](https://github.com/kataras/iris/issues/1449))
 - `mvc#Application.SortByNumMethods()` removed as the default behavior now binds the "thinnest"  empty `interface{}` automatically (see [MVC: service injecting fails](https://github.com/kataras/iris/issues/1343))
 - `mvc#BeforeActivation.Dependencies().Add` should be replaced with `mvc#BeforeActivation.Dependencies().Register` instead

_examples/routing/overview/main.go

@@ -1,14 +1,24 @@
 package main
 
 import (
+	"os"
+	"time"
+
 	"github.com/kataras/iris/v12"
 	"github.com/kataras/iris/v12/middleware/logger"
 )
 
 func main() {
 	app := iris.New()
+	// Set Logger level to "debug",
+	// see your terminal and the created file.
 	app.Logger().SetLevel("debug")
 
+	// Write logs to a file too.
+	f := newLogFile()
+	defer f.Close()
+	app.Logger().AddOutput(f)
+
 	// Register a request logger middleware to the application.
 	app.Use(logger.New())
 
@@ -93,7 +103,7 @@ func main() {
 	usersRoutes.Delete("/{id:uint64}", func(ctx iris.Context) {
 		id, _ := ctx.Params().GetUint64("id")
 		ctx.Writef("delete user by id: %d", id)
-	}).SetDescription("Deletes a User")
+	}).SetDescription("deletes a user")
 
 	// Subdomains, depends on the host, you have to edit the hosts or nginx/caddy's configuration if you use them.
 	//
@@ -162,3 +172,21 @@ func info(ctx iris.Context) {
 	ctx.Writef("\nInfo\n\n")
 	ctx.Writef("Method: %s\nSubdomain: %s\nPath: %s\nParameters length: %d", method, subdomain, path, paramsLen)
 }
+
+// get a filename based on the date, file logs works that way the most times
+// but these are just a sugar.
+func todayFilename() string {
+	today := time.Now().Format("Jan 02 2006")
+	return today + ".txt"
+}
+
+func newLogFile() *os.File {
+	filename := todayFilename()
+	// open an output file, this will append to the today's file if server restarted.
+	f, err := os.OpenFile(filename, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
+	if err != nil {
+		panic(err)
+	}
+
+	return f
+}

_examples/routing/route-register-rule/main.go

@@ -33,9 +33,9 @@ func newApp() *iris.Application {
 }
 
 func getHandler(ctx iris.Context) {
-	ctx.Writef("From %s", ctx.GetCurrentRoute().Trace())
+	ctx.Writef("From GET: %s", ctx.GetCurrentRoute().MainHandlerName())
 }
 
 func anyHandler(ctx iris.Context) {
-	ctx.Writef("From %s", ctx.GetCurrentRoute().Trace())
+	ctx.Writef("From %s: %s", ctx.Method(), ctx.GetCurrentRoute().MainHandlerName())
 }

_examples/routing/route-register-rule/main_test.go

@@ -14,9 +14,9 @@ func TestRouteRegisterRuleExample(t *testing.T) {
 	for _, method := range router.AllMethods {
 		tt := e.Request(method, "/").Expect().Status(httptest.StatusOK).Body()
 		if method == "GET" {
-			tt.Equal("From [./main.go:28] GET: / -> github.com/kataras/iris/v12/_examples/routing/route-register-rule.getHandler()")
+			tt.Equal("From GET: github.com/kataras/iris/v12/_examples/routing/route-register-rule.getHandler")
 		} else {
-			tt.Equal("From [./main.go:30] " + method + ": / -> github.com/kataras/iris/v12/_examples/routing/route-register-rule.anyHandler()")
+			tt.Equal("From " + method + ": github.com/kataras/iris/v12/_examples/routing/route-register-rule.anyHandler")
 		}
 	}
 }

context/handler.go

@@ -1,6 +1,7 @@
 package context
 
 import (
+	"os"
 	"path/filepath"
 	"reflect"
 	"regexp"
@@ -9,14 +10,19 @@ import (
 	"sync"
 )
 
+var (
+	// PackageName is the Iris Go module package name.
+	PackageName = strings.TrimSuffix(reflect.TypeOf(Handlers{}).PkgPath(), "/context")
+
+	// WorkingDir is the (initial) current directory.
+	WorkingDir, _ = os.Getwd()
+)
+
 var (
 	handlerNames   = make(map[*regexp.Regexp]string)
 	handlerNamesMu sync.RWMutex
 )
 
-// PackageName is the Iris Go module package name.
-var PackageName = strings.TrimSuffix(reflect.TypeOf(Handlers{}).PkgPath(), "/context")
-
 // SetHandlerName sets a handler name that could be
 // fetched through `HandlerName`. The "original" should be
 // the Go's original regexp-featured (can be retrieved through a `HandlerName` call) function name.
@@ -74,6 +80,11 @@ func HandlerName(h interface{}) string {
 	name := runtime.FuncForPC(pc).Name()
 	handlerNamesMu.RLock()
 	for regex, newName := range handlerNames {
+		if regex.String() == name { // if matches as string, as it's.
+			name = newName
+			break
+		}
+
 		if regex.MatchString(name) {
 			name = newName
 			break
@@ -91,10 +102,11 @@ func HandlerFileLine(h interface{}) (file string, line int) {
 	return runtime.FuncForPC(pc).FileLine(pc)
 }
 
-// HandlerFileLineRel same as `HandlerFileLine` but it returns the path as relative to the "workingDir".
+// HandlerFileLineRel same as `HandlerFileLine` but it returns the path
-func HandlerFileLineRel(h interface{}, workingDir string) (file string, line int) {
+// corresponding to its relative based on the package-level "WorkingDir" variable.
+func HandlerFileLineRel(h interface{}) (file string, line int) {
 	file, line = HandlerFileLine(h)
-	if relFile, err := filepath.Rel(workingDir, file); err == nil {
+	if relFile, err := filepath.Rel(WorkingDir, file); err == nil {
 		if !strings.HasPrefix(relFile, "..") {
 			// Only if it's relative to this path, not parent.
 			file = "./" + relFile

context/route.go

@@ -1,6 +1,7 @@
 package context
 
 import (
+	"io"
 	"os"
 	"path"
 	"path/filepath"
@@ -43,9 +44,9 @@ type RouteReadOnly interface {
 
 	// ResolvePath returns the formatted path's %v replaced with the args.
 	ResolvePath(args ...string) string
-	// Trace returns some debug infos as a string sentence.
+	// Trace should writes debug route info to the "w".
 	// Should be called after Build.
-	Trace() string
+	Trace(w io.Writer)
 
 	// Tmpl returns the path template,
 	// it contains the parsed template

core/router/api_builder.go

@@ -453,8 +453,7 @@ func (api *APIBuilder) CreateRoutes(methods []string, relativePath string, handl
 	// before join the middleware + handlers + done handlers and apply the execution rules.
 
 	mainHandlerName, mainHandlerIndex := context.MainHandlerName(mainHandlers)
-	wd, _ := os.Getwd()
+	mainHandlerFileName, mainHandlerFileNumber := context.HandlerFileLineRel(handlers[mainHandlerIndex])
-	mainHandlerFileName, mainHandlerFileNumber := context.HandlerFileLineRel(handlers[mainHandlerIndex], wd)
 
 	// re-calculate mainHandlerIndex in favor of the middlewares.
 	mainHandlerIndex = len(api.middleware) + len(api.beginGlobalHandlers) + mainHandlerIndex

core/router/handler.go

@@ -11,6 +11,7 @@ import (
 	macroHandler "github.com/kataras/iris/v12/macro/handler"
 
 	"github.com/kataras/golog"
+	"github.com/kataras/pio"
 )
 
 // RequestHandler the middle man between acquiring a context and releasing it.
@@ -156,6 +157,13 @@ func (h *routerHandler) Build(provider RoutesProvider) error {
 	}
 
 	if golog.Default.Level == golog.DebugLevel {
+		tr := "routes"
+		if len(registeredRoutes) == 1 {
+			tr = tr[0 : len(tr)-1]
+		}
+
+		golog.Debugf("API: [%d] %s", len(registeredRoutes), tr)
+
 		// group routes by method and print them without the [DBUG] and time info,
 		// the route logs are colorful.
 		// Note: don't use map, we need to keep registered order, use
@@ -176,9 +184,15 @@ func (h *routerHandler) Build(provider RoutesProvider) error {
 
 		for _, method := range append(AllMethods, MethodNone) {
 			methodRoutes := collect(method)
-			for _, r := range methodRoutes {
+			if len(methodRoutes) == 0 {
-				golog.Println(r.Trace())
+				continue
 			}
+
+			for _, r := range methodRoutes {
+				r.Trace(golog.Default.Printer)
+			}
+
+			golog.Default.Printer.Write(pio.NewLine)
 		}
 	}
 

core/router/route.go

@@ -2,8 +2,8 @@ package router
 
 import (
 	"fmt"
+	"io"
 	"net/http"
-	"os"
 	"strings"
 	"time"
 
@@ -342,9 +342,9 @@ func (r *Route) ResolvePath(args ...string) string {
 }
 
 var ignoreHandlersTraces = [...]string{
-	"iris/macro/handler.MakeHandler.func1",
+	"iris/macro/handler.MakeHandler",
-	"iris/core/router.(*APIBuilder).Favicon.func1",
+	"iris/core/router.(*APIBuilder).Favicon",
-	"iris/core/router.StripPrefix.func1",
+	"iris/core/router.StripPrefix",
 }
 
 func ignoreHandlerTrace(name string) bool {
@@ -357,7 +357,7 @@ func ignoreHandlerTrace(name string) bool {
 	return false
 }
 
-func traceHandlerFile(name, line string, number int) string {
+func traceHandlerFile(method, name, line string, number int) string {
 	file := fmt.Sprintf("(%s:%d)", line, number)
 
 	// trim the path for Iris' internal middlewares, e.g.
@@ -369,21 +369,24 @@ func traceHandlerFile(name, line string, number int) string {
 		name = strings.Replace(name, internalName, "iris-contrib", 1)
 	}
 
+	name = strings.TrimSuffix(name, ".func1")
+
 	if ignoreHandlerTrace(name) {
 		return ""
 	}
 
-	return fmt.Sprintf("\n     ⬝ %s %s", name, file)
+	space := strings.Repeat(" ", len(method)+1)
+	return fmt.Sprintf("\n%s ⬝ %s %s", space, name, file)
 }
 
-// Trace returns some debug infos as a string sentence.
+// Trace prints some debug info about the Route to the "w".
 // Should be called after `Build` state.
 //
 // It prints the @method: @path (@description) (@route_rel_location)
 //               * @handler_name (@handler_rel_location)
 //               * @second_handler ...
 // If route and handler line:number locations are equal then the second is ignored.
-func (r *Route) Trace() string {
+func (r *Route) Trace(w io.Writer) {
 	// Color the method.
 	color := pio.Black
 	switch r.Method {
@@ -398,7 +401,7 @@ func (r *Route) Trace() string {
 	case http.MethodConnect:
 		color = pio.Green
 	case http.MethodHead:
-		color = pio.Green
+		color = 23
 	case http.MethodPatch:
 		color = pio.Blue
 	case http.MethodOptions:
@@ -406,16 +409,29 @@ func (r *Route) Trace() string {
 	case http.MethodTrace:
 		color = pio.Yellow
 	case MethodNone:
-		color = 196 // full red.
+		color = 203 // orange-red.
 	}
 
 	path := r.Tmpl().Src
-	if r.Subdomain != "" {
+
-		path = fmt.Sprintf("%s %s", r.Subdomain, path)
+	if subdomain := r.Subdomain; subdomain != "" {
+		if path == "" {
+			path = "/"
+		}
+
+		if subdomain == "*." { // wildcard.
+			subdomain = "subdomain"
+		}
+
+		r.Description = fmt.Sprintf("%s", subdomain)
+		// path = fmt.Sprintf("%s %s", r.Subdomain, path)
 	}
 
 	// @method: @path
-	s := fmt.Sprintf("%s: %s", pio.Rich(r.Method, color), path)
+	// space := strings.Repeat(" ", len(http.MethodConnect)-len(r.Method))
+	// s := fmt.Sprintf("%s: %s", pio.Rich(r.Method, color), path)
+	pio.WriteRich(w, r.Method, color)
+	fmt.Fprintf(w, ": %s", path)
 
 	// (@description)
 	description := r.Description
@@ -424,57 +440,50 @@ func (r *Route) Trace() string {
 	}
 
 	if description != "" {
-		s += fmt.Sprintf(" %s", pio.Rich(description, pio.Cyan, pio.Underline))
+		// s += fmt.Sprintf(" %s", pio.Rich(description, pio.Cyan, pio.Underline))
+		fmt.Fprint(w, " ")
+		pio.WriteRich(w, description, pio.Cyan, pio.Underline)
 	}
 
 	// (@route_rel_location)
-	s += fmt.Sprintf(" (%s:%d)", r.RegisterFileName, r.RegisterLineNumber)
+	// s += fmt.Sprintf(" (%s:%d)", r.RegisterFileName, r.RegisterLineNumber)
-
+	fmt.Fprintf(w, " (%s:%d)", r.RegisterFileName, r.RegisterLineNumber)
-	wd, _ := os.Getwd()
 
 	for i, h := range r.Handlers {
-		// main handler info can be programmatically
-		// changed to be more specific, respect those options.
 		var (
 			name string
 			file string
 			line int
 		)
 
-		// name = context.HandlerName(h)
-		// file, line = context.HandlerFileLineRel(h, wd)
-		// fmt.Printf("---handler index: %d, name: %s, line: %s:%d\n", i, name, file, line)
-
 		if i == r.MainHandlerIndex {
+			// Main handler info can be programmatically
+			// changed to be more specific, respect these changes.
 			name = r.MainHandlerName
 			file = r.SourceFileName
 			line = r.SourceLineNumber
-			// fmt.Printf("main handler index: %d, name: %s, line: %d\n", i, name, line)
 		} else {
 			name = context.HandlerName(h)
-			file, line = context.HandlerFileLineRel(h, wd)
+			file, line = context.HandlerFileLineRel(h)
 
 			// If a middleware, e.g (macro) which changes the main handler index,
 			// skip it.
 			if file == r.SourceFileName && line == r.SourceLineNumber {
-				// fmt.Printf("[0] SKIP: handler index: %d, name: %s, line: %s:%d\n", i, name, file, line)
 				continue
 			}
-			// fmt.Printf("handler index: %d, name: %s, line: %d\n", i, name, line)
 		}
 
 		// If a handler is an anonymous function then it was already
 		// printed in the first line, skip it.
 		if file == r.RegisterFileName && line == r.RegisterLineNumber {
-			// fmt.Printf("[1] SKIP: handler index: %d, name: %s, line: %s:%d\n", i, name, file, line)
 			continue
 		}
 
 		// * @handler_name (@handler_rel_location)
-		s += traceHandlerFile(name, file, line)
+		fmt.Fprint(w, traceHandlerFile(r.Method, name, file, line))
 	}
 
-	return s
+	fmt.Fprintln(w)
 }
 
 type routeReadOnlyWrapper struct {
@@ -497,8 +506,8 @@ func (rd routeReadOnlyWrapper) Path() string {
 	return rd.Route.tmpl.Src
 }
 
-func (rd routeReadOnlyWrapper) Trace() string {
+func (rd routeReadOnlyWrapper) Trace(w io.Writer) {
-	return rd.Route.Trace()
+	rd.Route.Trace(w)
 }
 
 func (rd routeReadOnlyWrapper) Tmpl() macro.Template {

go.mod

@@ -21,9 +21,9 @@ require (
 	github.com/iris-contrib/pongo2 v0.0.1
 	github.com/iris-contrib/schema v0.0.1
 	github.com/json-iterator/go v1.1.9
-	github.com/kataras/golog v0.0.11
+	github.com/kataras/golog v0.0.12
-	github.com/kataras/pio v0.0.3
 	github.com/kataras/neffos v0.0.14
+	github.com/kataras/pio v0.0.5
 	github.com/kataras/sitemap v0.0.5
 	github.com/klauspost/compress v1.9.7
 	github.com/mediocregopher/radix/v3 v3.4.2

mvc/controller.go

@@ -2,7 +2,6 @@ package mvc
 
 import (
 	"fmt"
-	"os"
 	"reflect"
 	"strings"
 
@@ -337,15 +336,13 @@ func (c *ControllerActivator) handleMany(method, path, funcName string, override
 		return nil
 	}
 
-	wd, _ := os.Getwd()
-
 	for _, r := range routes {
 		// change the main handler's name and file:line
 		// in order to respect the controller's and give
 		// a proper debug/log message.
 		r.MainHandlerName = fmt.Sprintf("%s.%s", c.fullName, funcName)
 		if m, ok := c.Type.MethodByName(funcName); ok {
-			r.SourceFileName, r.SourceLineNumber = context.HandlerFileLineRel(m.Func, wd)
+			r.SourceFileName, r.SourceLineNumber = context.HandlerFileLineRel(m.Func)
 		}
 	}