Trace Logging on Permission Denied & ColorFormat (#6618)

* Add log.ColorFormat and log.ColorFormatted

Structs can now implement log.ColorFormatted to provide their own
colored format when logged with `%-v` or additional flags.

Signed-off-by: Andrew Thornton <art27@cantab.net>

* Add basic ColorFormat to repository and user

Signed-off-by: Andrew Thornton <art27@cantab.net>

* Add basic ColorFormat to access and unit

Signed-off-by: Andrew Thornton <art27@cantab.net>

* Add ColorFormat to permission and on trace log it

Signed-off-by: Andrew Thornton <art27@cantab.net>

* Add log.NewColoredIDValue to make ID value coloring consistent

Signed-off-by: Andrew Thornton <art27@cantab.net>

* formatting changes

* Add some better tracing to permission denied for read issues/pulls

Signed-off-by: Andrew Thornton <art27@cantab.net>

* Add Trace logging on permission denied

Signed-off-by: Andrew Thornton <art27@cantab.net>

* Remove isTrace() check from deferred func

* Adjust repo and allow logging of team

* use FormatInt instead of Itoa

* Add blank line

Signed-off-by: Andrew Thornton <art27@cantab.net>

* Update access.go

3 files changed, 101 insertions, 8 deletions

diff --git a/modules/context/permission.go b/modules/context/permission.go
index 70f8695300..6ac935686b 100644
--- a/modules/context/permission.go
+++ b/modules/context/permission.go
@@ -6,6 +6,8 @@ package context
 
 import (
 	"code.gitea.io/gitea/models"
+	"code.gitea.io/gitea/modules/log"
+
 	macaron "gopkg.in/macaron.v1"
 )
 
@@ -45,6 +47,22 @@ func RequireRepoWriterOr(unitTypes ...models.UnitType) macaron.Handler {
 func RequireRepoReader(unitType models.UnitType) macaron.Handler {
 	return func(ctx *Context) {
 		if !ctx.Repo.CanRead(unitType) {
+			if log.IsTrace() {
+				if ctx.IsSigned {
+					log.Trace("Permission Denied: User %-v cannot read %-v in Repo %-v\n"+
+						"User in Repo has Permissions: %-+v",
+						ctx.User,
+						unitType,
+						ctx.Repo.Repository,
+						ctx.Repo.Permission)
+				} else {
+					log.Trace("Permission Denied: Anonymous user cannot read %-v in Repo %-v\n"+
+						"Anonymous user in Repo has Permissions: %-+v",
+						unitType,
+						ctx.Repo.Repository,
+						ctx.Repo.Permission)
+				}
+			}
 			ctx.NotFound(ctx.Req.RequestURI, nil)
 			return
 		}
@@ -59,6 +77,25 @@ func RequireRepoReaderOr(unitTypes ...models.UnitType) macaron.Handler {
 				return
 			}
 		}
+		if log.IsTrace() {
+			var format string
+			var args []interface{}
+			if ctx.IsSigned {
+				format = "Permission Denied: User %-v cannot read ["
+				args = append(args, ctx.User)
+			} else {
+				format = "Permission Denied: Anonymous user cannot read ["
+			}
+			for _, unit := range unitTypes {
+				format += "%-v, "
+				args = append(args, unit)
+			}
+
+			format = format[:len(format)-2] + "] in Repo %-v\n" +
+				"User in Repo has Permissions: %-+v"
+			args = append(args, ctx.Repo.Repository, ctx.Repo.Permission)
+			log.Trace(format, args...)
+		}
 		ctx.NotFound(ctx.Req.RequestURI, nil)
 	}
 }
diff --git a/modules/log/colors.go b/modules/log/colors.go
index ed6477d431..0ec8ce4ba8 100644
--- a/modules/log/colors.go
+++ b/modules/log/colors.go
@@ -7,6 +7,7 @@ package log
 import (
 	"fmt"
 	"io"
+	"reflect"
 	"strconv"
 	"strings"
 )
@@ -195,11 +196,12 @@ normalLoop:
 		lasti := i
 
 		if c.mode == escapeAll {
-			for i < end && (bytes[i] >= ' ' || bytes[i] == '\n') {
+			for i < end && (bytes[i] >= ' ' || bytes[i] == '\n' || bytes[i] == '\t') {
 				i++
 			}
 		} else {
-			for i < end && bytes[i] >= ' ' {
+			// Allow tabs if we're not escaping everything
+			for i < end && (bytes[i] >= ' ' || bytes[i] == '\t') {
 				i++
 			}
 		}
@@ -266,6 +268,39 @@ normalLoop:
 	return totalWritten, nil
 }
 
+// ColorSprintf returns a colored string from a format and arguments
+// arguments will be wrapped in ColoredValues to protect against color spoofing
+func ColorSprintf(format string, args ...interface{}) string {
+	if len(args) > 0 {
+		v := make([]interface{}, len(args))
+		for i := 0; i < len(v); i++ {
+			v[i] = NewColoredValuePointer(&args[i])
+		}
+		return fmt.Sprintf(format, v...)
+	}
+	return fmt.Sprintf(format)
+}
+
+// ColorFprintf will write to the provided writer similar to ColorSprintf
+func ColorFprintf(w io.Writer, format string, args ...interface{}) (int, error) {
+	if len(args) > 0 {
+		v := make([]interface{}, len(args))
+		for i := 0; i < len(v); i++ {
+			v[i] = NewColoredValuePointer(&args[i])
+		}
+		return fmt.Fprintf(w, format, v...)
+	}
+	return fmt.Fprintf(w, format)
+}
+
+// ColorFormatted structs provide their own colored string when formatted with ColorSprintf
+type ColorFormatted interface {
+	// ColorFormat provides the colored representation of the value
+	ColorFormat(s fmt.State)
+}
+
+var colorFormattedType = reflect.TypeOf((*ColorFormatted)(nil)).Elem()
+
 // ColoredValue will Color the provided value
 type ColoredValue struct {
 	colorBytes *[]byte
@@ -316,8 +351,33 @@ func NewColoredValueBytes(value interface{}, colorBytes *[]byte) *ColoredValue {
 	}
 }
 
-// Format will format the provided value and protect against ANSI spoofing within the value
+// NewColoredIDValue is a helper function to create a ColoredValue from a Value
+// The Value will be colored with FgCyan
+// If a ColoredValue is provided it is not changed
+func NewColoredIDValue(value interface{}) *ColoredValue {
+	return NewColoredValueBytes(&value, &fgCyanBytes)
+}
+
+// Format will format the provided value and protect against ANSI color spoofing within the value
+// If the wrapped value is ColorFormatted and the format is "%-v" then its ColorString will
+// be used. It is presumed that this ColorString is safe.
 func (cv *ColoredValue) Format(s fmt.State, c rune) {
+	if c == 'v' && s.Flag('-') {
+		if val, ok := (*cv.Value).(ColorFormatted); ok {
+			val.ColorFormat(s)
+			return
+		}
+		v := reflect.ValueOf(*cv.Value)
+		t := v.Type()
+
+		if reflect.PtrTo(t).Implements(colorFormattedType) {
+			vp := reflect.New(t)
+			vp.Elem().Set(v)
+			val := vp.Interface().(ColorFormatted)
+			val.ColorFormat(s)
+			return
+		}
+	}
 	s.Write([]byte(*cv.colorBytes))
 	fmt.Fprintf(&protectedANSIWriter{w: s}, fmtString(s, c), *(cv.Value))
 	s.Write([]byte(*cv.resetBytes))
diff --git a/modules/log/logger.go b/modules/log/logger.go
index 925ab02b71..9704ffd3d8 100644
--- a/modules/log/logger.go
+++ b/modules/log/logger.go
@@ -69,11 +69,7 @@ func (l *Logger) Log(skip int, level Level, format string, v ...interface{}) err
 	}
 	msg := format
 	if len(v) > 0 {
-		args := make([]interface{}, len(v))
-		for i := 0; i < len(args); i++ {
-			args[i] = NewColoredValuePointer(&v[i])
-		}
-		msg = fmt.Sprintf(format, args...)
+		msg = ColorSprintf(format, v...)
 	}
 	stack := ""
 	if l.GetStacktraceLevel() <= level {