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 <[email protected]>

* Add basic ColorFormat to repository and user

Signed-off-by: Andrew Thornton <[email protected]>

* Add basic ColorFormat to access and unit

Signed-off-by: Andrew Thornton <[email protected]>

* Add ColorFormat to permission and on trace log it

Signed-off-by: Andrew Thornton <[email protected]>

* Add log.NewColoredIDValue to make ID value coloring consistent

Signed-off-by: Andrew Thornton <[email protected]>

* formatting changes

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

Signed-off-by: Andrew Thornton <[email protected]>

* Add Trace logging on permission denied

Signed-off-by: Andrew Thornton <[email protected]>

* 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 <[email protected]>

* Update access.go

Author: zeripath

docs/content/doc/advanced/logging-documentation.en-us.md

@@ -362,6 +362,17 @@ also set the `resetBytes` to the cached `resetBytes`.
 The `colorBytes` and `resetBytes` are not exported to prevent
 accidental overwriting of internal values.
 
+## ColorFormat & ColorFormatted
+
+Structs may implement the `log.ColorFormatted` interface by implementing the `ColorFormat(fmt.State)` function.
+
+If a `log.ColorFormatted` struct is logged with `%-v` format, its `ColorFormat` will be used instead of the usual `%v`. The full `fmt.State` will be passed to allow implementers to look at additional flags.
+
+In order to help implementers provide `ColorFormat` methods. There is a
+`log.ColorFprintf(...)` function in the log module that will wrap values in `log.ColoredValue` and recognise `%-v`.
+
+In general it is recommended not to make the results of this function too verbose to help increase its versatility. Usually this should simply be an `ID`:`Name`. If you wish to make a more verbose result, it is recommended to use `%-+v` as your marker.
+
 ## Log Spoofing protection
 
 In order to protect the logs from being spoofed with cleverly
@@ -392,5 +403,5 @@ func newNewoneLogService() {
 }
 ```
 
-You should then add `newOneLogService` to `NewServices()` in 
+You should then add `newOneLogService` to `NewServices()` in
 `modules/setting/setting.go`

models/access.go

@@ -1,10 +1,15 @@
 // Copyright 2014 The Gogs Authors. All rights reserved.
+// Copyright 2019 The Gitea Authors. All rights reserved.
 // Use of this source code is governed by a MIT-style
 // license that can be found in the LICENSE file.
 
 package models
 
-import "fmt"
+import (
+	"fmt"
+
+	"code.gitea.io/gitea/modules/log"
+)
 
 // AccessMode specifies the users access mode
 type AccessMode int
@@ -37,6 +42,13 @@ func (mode AccessMode) String() string {
 	}
 }
 
+// ColorFormat provides a ColorFormatted version of this AccessMode
+func (mode AccessMode) ColorFormat(s fmt.State) {
+	log.ColorFprintf(s, "%d:%s",
+		log.NewColoredIDValue(mode),
+		mode)
+}
+
 // ParseAccessMode returns corresponding access mode to given permission string.
 func ParseAccessMode(permission string) AccessMode {
 	switch permission {

models/org_team.go

@@ -34,6 +34,16 @@ type Team struct {
 	Units       []*TeamUnit `xorm:"-"`
 }
 
+// ColorFormat provides a basic color format for a Team
+func (t *Team) ColorFormat(s fmt.State) {
+	log.ColorFprintf(s, "%d:%s (OrgID: %d) %-v",
+		log.NewColoredIDValue(t.ID),
+		t.Name,
+		log.NewColoredIDValue(t.OrgID),
+		t.Authorize)
+
+}
+
 // GetUnits return a list of available units for a team
 func (t *Team) GetUnits() error {
 	return t.getUnits(x)

models/repo.go

@@ -18,6 +18,7 @@ import (
 	"path/filepath"
 	"regexp"
 	"sort"
+	"strconv"
 	"strings"
 	"time"
 
@@ -210,6 +211,24 @@ type Repository struct {
 	UpdatedUnix util.TimeStamp `xorm:"INDEX updated"`
 }
 
+// ColorFormat returns a colored string to represent this repo
+func (repo *Repository) ColorFormat(s fmt.State) {
+	var ownerName interface{}
+
+	if repo.OwnerName != "" {
+		ownerName = repo.OwnerName
+	} else if repo.Owner != nil {
+		ownerName = repo.Owner.Name
+	} else {
+		ownerName = log.NewColoredIDValue(strconv.FormatInt(repo.OwnerID, 10))
+	}
+
+	log.ColorFprintf(s, "%d:%s/%s",
+		log.NewColoredIDValue(repo.ID),
+		ownerName,
+		repo.Name)
+}
+
 // AfterLoad is invoked from XORM after setting the values of all fields of this object.
 func (repo *Repository) AfterLoad() {
 	// FIXME: use models migration to solve all at once.

models/repo_permission.go

@@ -4,6 +4,12 @@
 
 package models
 
+import (
+	"fmt"
+
+	"code.gitea.io/gitea/modules/log"
+)
+
 // Permission contains all the permissions related variables to a repository for a user
 type Permission struct {
 	AccessMode AccessMode
@@ -90,12 +96,67 @@ func (p *Permission) CanWriteIssuesOrPulls(isPull bool) bool {
 	return p.CanWrite(UnitTypeIssues)
 }
 
+// ColorFormat writes a colored string for these Permissions
+func (p *Permission) ColorFormat(s fmt.State) {
+	noColor := log.ColorBytes(log.Reset)
+
+	format := "AccessMode: %-v, %d Units, %d UnitsMode(s): [ "
+	args := []interface{}{
+		p.AccessMode,
+		log.NewColoredValueBytes(len(p.Units), &noColor),
+		log.NewColoredValueBytes(len(p.UnitsMode), &noColor),
+	}
+	if s.Flag('+') {
+		for i, unit := range p.Units {
+			config := ""
+			if unit.Config != nil {
+				configBytes, err := unit.Config.ToDB()
+				config = string(configBytes)
+				if err != nil {
+					config = string(err.Error())
+				}
+			}
+			format += "\nUnits[%d]: ID: %d RepoID: %d Type: %-v Config: %s"
+			args = append(args,
+				log.NewColoredValueBytes(i, &noColor),
+				log.NewColoredIDValue(unit.ID),
+				log.NewColoredIDValue(unit.RepoID),
+				unit.Type,
+				config)
+		}
+		for key, value := range p.UnitsMode {
+			format += "\nUnitMode[%-v]: %-v"
+			args = append(args,
+				key,
+				value)
+		}
+	} else {
+		format += "..."
+	}
+	format += " ]"
+	log.ColorFprintf(s, format, args...)
+}
+
 // GetUserRepoPermission returns the user permissions to the repository
 func GetUserRepoPermission(repo *Repository, user *User) (Permission, error) {
 	return getUserRepoPermission(x, repo, user)
 }
 
 func getUserRepoPermission(e Engine, repo *Repository, user *User) (perm Permission, err error) {
+	if log.IsTrace() {
+		defer func() {
+			if user == nil {
+				log.Trace("Permission Loaded for anonymous user in %-v:\nPermissions: %-+v",
+					repo,
+					perm)
+				return
+			}
+			log.Trace("Permission Loaded for %-v in %-v:\nPermissions: %-+v",
+				user,
+				repo,
+				perm)
+		}()
+	}
 	// anonymous user visit private repo.
 	// TODO: anonymous user visit public unit of private repo???
 	if user == nil && repo.IsPrivate {

models/unit.go

@@ -5,7 +5,10 @@
 package models
 
 import (
+	"fmt"
 	"strings"
+
+	"code.gitea.io/gitea/modules/log"
 )
 
 // UnitType is Unit's Type
@@ -22,6 +25,33 @@ const (
 	UnitTypeExternalTracker                     // 7 ExternalTracker
 )
 
+func (u UnitType) String() string {
+	switch u {
+	case UnitTypeCode:
+		return "UnitTypeCode"
+	case UnitTypeIssues:
+		return "UnitTypeIssues"
+	case UnitTypePullRequests:
+		return "UnitTypePullRequests"
+	case UnitTypeReleases:
+		return "UnitTypeReleases"
+	case UnitTypeUncyclo:
+		return "UnitTypeUncyclo"
+	case UnitTypeExternalUncyclo:
+		return "UnitTypeExternalUncyclo"
+	case UnitTypeExternalTracker:
+		return "UnitTypeExternalTracker"
+	}
+	return fmt.Sprintf("Unknown UnitType %d", u)
+}
+
+// ColorFormat provides a ColorFormatted version of this UnitType
+func (u UnitType) ColorFormat(s fmt.State) {
+	log.ColorFprintf(s, "%d:%s",
+		log.NewColoredIDValue(u),
+		u)
+}
+
 var (
 	// allRepUnitTypes contains all the unit types
 	allRepUnitTypes = []UnitType{

models/user.go

@@ -146,6 +146,13 @@ type User struct {
 	Theme         string `xorm:"NOT NULL DEFAULT ''"`
 }
 
+// ColorFormat writes a colored string to identify this struct
+func (u *User) ColorFormat(s fmt.State) {
+	log.ColorFprintf(s, "%d:%s",
+		log.NewColoredIDValue(u.ID),
+		log.NewColoredValue(u.Name))
+}
+
 // BeforeUpdate is invoked from XORM before updating this object.
 func (u *User) BeforeUpdate() {
 	if u.MaxRepoCreation < -1 {

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)
 	}
 }