improve route debug info, see HISTORY.md

Former-commit-id: ae245bae5fefa57c5f7663f7d1d661ec68ad366a

HISTORY.md

@@ -180,7 +180,9 @@ Other Improvements:
     - New Router [Wrapper](middleware/grpc).
     - New MVC `.Handle(ctrl, mvc.GRPC{...})` option which allows to register gRPC services per-party (without the requirement of a full wrapper) and optionally strict access to gRPC clients only, see the [example here](_examples/mvc/grpc-compatible).
 
-- Improved logging (with `app.Logger().SetLevel("debug")`) for MVC-registered routes.
+- Improved tracing (with `app.Logger().SetLevel("debug")`) for routes. Example:
+
+![DBUG routes](https://iris-go.com/images/v12.2.0-dbug.png)
 
 - New `iris.WithLowercaseRouting` option which forces all routes' paths to be lowercase and converts request paths to their lowercase for matching.
 

_examples/mvc/grpc-compatible/main.go

@@ -31,7 +31,12 @@ func main() {
 
 func newApp() *iris.Application {
 	app := iris.New()
-	app.Logger().SetLevel("debug")
+	// app.Configure(iris.WithLowercaseRouting) // OPTIONAL.
+	app.Logger().SetLevel("debug").SetTimeFormat("")
+
+	app.Get("/", func(ctx iris.Context) {
+		ctx.HTML("<h1>Index Page</h1>")
+	})
 
 	ctrl := &myController{}
 	// Register gRPC server.

context/handler.go

@@ -51,25 +51,30 @@ func HandlerFileLine(h interface{}) (file string, line int) {
 }
 
 // HandlerFileLineRel same as `HandlerFileLine` but it returns the path as relative to the "workingDir".
-func HandlerFileLineRel(h interface{}, workingDir string) (string, int) {
-	file, line := HandlerFileLine(h)
+func HandlerFileLineRel(h interface{}, workingDir string) (file string, line int) {
+	file, line = HandlerFileLine(h)
 	if relFile, err := filepath.Rel(workingDir, file); err == nil {
-		file = "./" + relFile
+		if !strings.HasPrefix(relFile, "..") {
+			// Only if it's relative to this path, not parent.
+			file = "./" + relFile
+		}
 	}
 
-	return file, line
+	return
 }
 
-// MainHandlerName tries to find the main handler than end-developer
+// MainHandlerName tries to find the main handler that end-developer
 // registered on the provided chain of handlers and returns its function name.
-func MainHandlerName(handlers Handlers) (name string) {
+func MainHandlerName(handlers Handlers) (name string, index int) {
 	for i := 0; i < len(handlers); i++ {
 		name = HandlerName(handlers[i])
+		index = i
 		if !strings.HasPrefix(name, "github.com/kataras/iris/v12") ||
 			strings.HasPrefix(name, "github.com/kataras/iris/v12/core/router.StripPrefix") ||
 			strings.HasPrefix(name, "github.com/kataras/iris/v12/core/router.FileServer") {
 			break
 		}
+
 	}
 
 	return

core/router/api_builder.go

@@ -444,7 +444,9 @@ func (api *APIBuilder) CreateRoutes(methods []string, relativePath string, handl
 	mainHandlers := context.Handlers(handlers)
 	// before join the middleware + handlers + done handlers and apply the execution rules.
 
-	possibleMainHandlerName := context.MainHandlerName(mainHandlers)
+	possibleMainHandlerName, mainHandlerIndex := context.MainHandlerName(mainHandlers)
+	wd, _ := os.Getwd()
+	mainHandlerFileName, mainHandlerFileNumber := context.HandlerFileLineRel(handlers[mainHandlerIndex], wd)
 
 	// TODO: for UseGlobal/DoneGlobal that doesn't work.
 	applyExecutionRules(api.handlerExecutionRules, &beginHandlers, &doneHandlers, &mainHandlers)
@@ -470,8 +472,11 @@ func (api *APIBuilder) CreateRoutes(methods []string, relativePath string, handl
 			continue
 		}
 
-		route.SourceFileName = filename
-		route.SourceLineNumber = line
+		route.SourceFileName = mainHandlerFileName
+		route.SourceLineNumber = mainHandlerFileNumber
+
+		route.RegisterFileName = filename
+		route.RegisterLineNumber = line
 
 		// Add UseGlobal & DoneGlobal Handlers
 		route.Use(api.beginGlobalHandlers...)
@@ -1011,8 +1016,8 @@ func getCaller() (string, int) {
 		}
 
 		if !strings.Contains(file, "/kataras/iris") ||
-			strings.Contains(file, "/kataras/iris/_examples") ||
-			strings.Contains(file, "iris-contrib/examples") {
+			strings.Contains(file, "_examples") ||
+			strings.Contains(file, "examples") {
 			if relFile, err := filepath.Rel(wd, file); err == nil {
 				file = "./" + relFile
 			}

core/router/route.go

@@ -2,12 +2,16 @@ package router
 
 import (
 	"fmt"
+	"net/http"
+	"os"
 	"strings"
 	"time"
 
 	"github.com/kataras/iris/v12/context"
 	"github.com/kataras/iris/v12/macro"
 	"github.com/kataras/iris/v12/macro/handler"
+
+	"github.com/kataras/pio"
 )
 
 // Route contains the information about a registered Route.
@@ -37,8 +41,12 @@ type Route struct {
 	FormattedPath string `json:"formattedPath"`
 
 	// the source code's filename:filenumber that this route was created from.
-	SourceFileName   string
-	SourceLineNumber int
+	SourceFileName   string `json:"sourceFileName"`
+	SourceLineNumber int    `json:"sourceLineNumber"`
+
+	// where the route registered.
+	RegisterFileName   string `json:"registerFileName"`
+	RegisterLineNumber int    `json:"registerLineNumber"`
 
 	// StaticSites if not empty, refers to the system (or virtual if embedded) directory
 	// and sub directories that this "GET" route was registered to serve files and folders
@@ -317,34 +325,82 @@ func (r *Route) ResolvePath(args ...string) string {
 }
 
 // Trace returns some debug infos as a string sentence.
-// Should be called after Build.
+// 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 {
-	printfmt := fmt.Sprintf("[%s:%d] %s:", r.SourceFileName, r.SourceLineNumber, r.Method)
+	// Color the method.
+	color := pio.Black
+	switch r.Method {
+	case http.MethodGet:
+		color = pio.Green
+	case http.MethodPost:
+		color = pio.Magenta
+	case http.MethodPut:
+		color = pio.Blue
+	case http.MethodDelete:
+		color = pio.Red
+	case http.MethodConnect:
+		color = pio.Green
+	case http.MethodHead:
+		color = pio.Green
+	case http.MethodPatch:
+		color = pio.Blue
+	case http.MethodOptions:
+		color = pio.Gray
+	case http.MethodTrace:
+		color = pio.Yellow
+	}
+
+	path := r.Tmpl().Src
 	if r.Subdomain != "" {
-		printfmt += fmt.Sprintf(" %s", r.Subdomain)
+		path = fmt.Sprintf("%s %s", r.Subdomain, path)
 	}
-	printfmt += fmt.Sprintf(" %s", r.Tmpl().Src)
 
+	// @method: @path
+	s := fmt.Sprintf("%s: %s", pio.Rich(r.Method, color), path)
+
+	// (@description)
 	if r.Description != "" {
-		printfmt += fmt.Sprintf(" (%s)", r.Description)
+		s += fmt.Sprintf(" %s", pio.Rich(r.Description, pio.Cyan, pio.Underline))
 	}
 
-	mainHandlerName := r.MainHandlerName
-	if !strings.HasSuffix(mainHandlerName, ")") {
-		mainHandlerName += "()"
+	// (@route_rel_location)
+	s += fmt.Sprintf(" (%s:%d)", r.RegisterFileName, r.RegisterLineNumber)
+
+	// if the main handler is not an anonymous function (so, differs from @route_rel_location)
+	// then * @handler_name (@handler_rel_location)
+	if r.SourceFileName != r.RegisterFileName || r.SourceLineNumber != r.RegisterLineNumber {
+		s += fmt.Sprintf("\n     ⬝ %s (%s:%d)", r.MainHandlerName, r.SourceFileName, r.SourceLineNumber)
 	}
 
-	if l := r.RegisteredHandlersLen(); l > 1 {
-		printfmt += fmt.Sprintf(" -> %s and %d more", mainHandlerName, l-1)
-	} else {
-		printfmt += fmt.Sprintf(" -> %s", mainHandlerName)
+	wd, _ := os.Getwd()
+
+	for _, h := range r.Handlers {
+		name := context.HandlerName(h)
+		if name == r.MainHandlerName {
+			continue
+		}
+
+		// trim the path for Iris' internal middlewares, e.g.
+		// irs/mvc.GRPC.Apply.func1
+		if internalName := "github.com/kataras/iris/v12"; strings.HasPrefix(name, internalName) {
+			name = strings.Replace(name, internalName, "iris", 1)
+		}
+
+		file, line := context.HandlerFileLineRel(h, wd)
+		if file == r.RegisterFileName && line == r.RegisterLineNumber {
+			continue
+		}
+
+		// * @handler_name (@handler_rel_location)
+		s += fmt.Sprintf("\n     ⬝ %s (%s:%d)", name, file, line)
 	}
 
-	// printfmt := fmt.Sprintf("%s: %s >> %s", r.Method, r.Subdomain+r.Tmpl().Src, r.MainHandlerName)
-	// if l := len(r.Handlers); l > 0 {
-	// 	printfmt += fmt.Sprintf(" and %d more", l)
-	// }
-	return printfmt // without new line.
+	return s
 }
 
 type routeReadOnlyWrapper struct {

go.mod

@@ -21,7 +21,8 @@ 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.10
+	github.com/kataras/golog v0.0.11
+	github.com/kataras/pio v0.0.3
 	github.com/kataras/neffos v0.0.14
 	github.com/kataras/sitemap v0.0.5
 	github.com/klauspost/compress v1.9.7

iris.go

@@ -641,7 +641,7 @@ func (app *Application) NewHost(srv *http.Server) *host.Supervisor {
 		srv.Addr = addr
 	}
 
-	app.logger.Debugf("Host: addr is %s", srv.Addr)
+	// app.logger.Debugf("Host: addr is %s", srv.Addr)
 
 	// create the new host supervisor
 	// bind the constructed server and return it
@@ -657,21 +657,21 @@ func (app *Application) NewHost(srv *http.Server) *host.Supervisor {
 		app.config.vhost = netutil.ResolveVHost(srv.Addr)
 	}
 
-	app.logger.Debugf("Host: virtual host is %s", app.config.vhost)
+	// app.logger.Debugf("Host: virtual host is %s", app.config.vhost)
 
 	// the below schedules some tasks that will run among the server
 
 	if !app.config.DisableStartupLog {
 		// show the available info to exit from app.
 		su.RegisterOnServe(host.WriteStartupLogOnServe(app.logger.Printer.Output)) // app.logger.Writer -> Info
-		app.logger.Debugf("Host: register startup notifier")
+		// app.logger.Debugf("Host: register startup notifier")
 	}
 
 	if !app.config.DisableInterruptHandler {
 		// when CTRL+C/CMD+C pressed.
 		shutdownTimeout := 5 * time.Second
 		host.RegisterOnInterrupt(host.ShutdownOnInterrupt(su, shutdownTimeout))
-		app.logger.Debugf("Host: register server shutdown on interrupt(CTRL+C/CMD+C)")
+		// app.logger.Debugf("Host: register server shutdown on interrupt(CTRL+C/CMD+C)")
 	}
 
 	su.IgnoredErrors = append(su.IgnoredErrors, app.config.IgnoreServerErrors...)
@@ -1017,7 +1017,9 @@ func (app *Application) Run(serve Runner, withOrWithout ...Configurator) error {
 	app.Configure(withOrWithout...)
 	app.tryStartTunneling()
 
-	app.logger.Debugf("Application: running using %d host(s)", len(app.Hosts)+1)
+	if len(app.Hosts) > 0 {
+		app.logger.Debugf("Application: running using %d host(s)", len(app.Hosts)+1 /* +1 the current */)
+	}
 
 	// this will block until an error(unless supervisor's DeferFlow called from a Task).
 	err := serve(app)

mvc/grpc.go

@@ -59,7 +59,7 @@ func (g GRPC) Apply(c *ControllerActivator) {
 		if route := c.Handle(http.MethodPost, path, m.Name, pre); route != nil {
 			route.Description = "gRPC"
 			if g.Strict {
-				route.Description = "-only"
+				route.Description += "-only"
 			}
 		}
 	}