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

7 files changed, 165 insertions, 2 deletions

diff --git a/routers/api/v1/api.go b/routers/api/v1/api.go
index ac92f7cd43..d201dff917 100644
--- a/routers/api/v1/api.go
+++ b/routers/api/v1/api.go
@@ -369,6 +369,22 @@ func orgAssignment(args ...bool) macaron.Handler {
 
 func mustEnableIssues(ctx *context.APIContext) {
 	if !ctx.Repo.CanRead(models.UnitTypeIssues) {
+		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,
+					models.UnitTypeIssues,
+					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",
+					models.UnitTypeIssues,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			}
+		}
 		ctx.NotFound()
 		return
 	}
@@ -376,6 +392,22 @@ func mustEnableIssues(ctx *context.APIContext) {
 
 func mustAllowPulls(ctx *context.APIContext) {
 	if !(ctx.Repo.Repository.CanEnablePulls() && ctx.Repo.CanRead(models.UnitTypePullRequests)) {
+		if ctx.Repo.Repository.CanEnablePulls() && 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,
+					models.UnitTypePullRequests,
+					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",
+					models.UnitTypePullRequests,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			}
+		}
 		ctx.NotFound()
 		return
 	}
@@ -384,6 +416,24 @@ func mustAllowPulls(ctx *context.APIContext) {
 func mustEnableIssuesOrPulls(ctx *context.APIContext) {
 	if !ctx.Repo.CanRead(models.UnitTypeIssues) &&
 		!(ctx.Repo.Repository.CanEnablePulls() && ctx.Repo.CanRead(models.UnitTypePullRequests)) {
+		if ctx.Repo.Repository.CanEnablePulls() && log.IsTrace() {
+			if ctx.IsSigned {
+				log.Trace("Permission Denied: User %-v cannot read %-v and %-v in Repo %-v\n"+
+					"User in Repo has Permissions: %-+v",
+					ctx.User,
+					models.UnitTypeIssues,
+					models.UnitTypePullRequests,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			} else {
+				log.Trace("Permission Denied: Anonymous user cannot read %-v and %-v in Repo %-v\n"+
+					"Anonymous user in Repo has Permissions: %-+v",
+					models.UnitTypeIssues,
+					models.UnitTypePullRequests,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			}
+		}
 		ctx.NotFound()
 		return
 	}
diff --git a/routers/api/v1/repo/pull.go b/routers/api/v1/repo/pull.go
index 7abe6241bd..4fbd024f8c 100644
--- a/routers/api/v1/repo/pull.go
+++ b/routers/api/v1/repo/pull.go
@@ -672,7 +672,12 @@ func parseCompareInfo(ctx *context.APIContext, form api.CreatePullRequestOption)
 		return nil, nil, nil, nil, "", ""
 	}
 	if !perm.CanReadIssuesOrPulls(true) {
-		log.Trace("ParseCompareInfo[%d]: cannot create/read pull requests", baseRepo.ID)
+		if log.IsTrace() {
+			log.Trace("Permission Denied: User %-v cannot create/read pull requests in Repo %-v\nUser in headRepo has Permissions: %-+v",
+				ctx.User,
+				headRepo,
+				perm)
+		}
 		ctx.NotFound()
 		return nil, nil, nil, nil, "", ""
 	}
diff --git a/routers/repo/issue.go b/routers/repo/issue.go
index 7a681033af..42661ef738 100644
--- a/routers/repo/issue.go
+++ b/routers/repo/issue.go
@@ -1163,6 +1163,24 @@ func NewComment(ctx *context.Context, form auth.CreateCommentForm) {
 	}
 
 	if !ctx.IsSigned || (ctx.User.ID != issue.PosterID && !ctx.Repo.CanReadIssuesOrPulls(issue.IsPull)) {
+		if log.IsTrace() {
+			if ctx.IsSigned {
+				issueType := "issues"
+				if issue.IsPull {
+					issueType = "pulls"
+				}
+				log.Trace("Permission Denied: User %-v not the Poster (ID: %d) and cannot read %s in Repo %-v.\n"+
+					"User in Repo has Permissions: %-+v",
+					ctx.User,
+					log.NewColoredIDValue(issue.PosterID),
+					issueType,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			} else {
+				log.Trace("Permission Denied: Not logged in")
+			}
+		}
+
 		ctx.Error(403)
 	}
 
@@ -1353,6 +1371,24 @@ func ChangeIssueReaction(ctx *context.Context, form auth.ReactionForm) {
 	}
 
 	if !ctx.IsSigned || (ctx.User.ID != issue.PosterID && !ctx.Repo.CanReadIssuesOrPulls(issue.IsPull)) {
+		if log.IsTrace() {
+			if ctx.IsSigned {
+				issueType := "issues"
+				if issue.IsPull {
+					issueType = "pulls"
+				}
+				log.Trace("Permission Denied: User %-v not the Poster (ID: %d) and cannot read %s in Repo %-v.\n"+
+					"User in Repo has Permissions: %-+v",
+					ctx.User,
+					log.NewColoredIDValue(issue.PosterID),
+					issueType,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			} else {
+				log.Trace("Permission Denied: Not logged in")
+			}
+		}
+
 		ctx.Error(403)
 		return
 	}
@@ -1432,6 +1468,24 @@ func ChangeCommentReaction(ctx *context.Context, form auth.ReactionForm) {
 	}
 
 	if !ctx.IsSigned || (ctx.User.ID != comment.PosterID && !ctx.Repo.CanReadIssuesOrPulls(comment.Issue.IsPull)) {
+		if log.IsTrace() {
+			if ctx.IsSigned {
+				issueType := "issues"
+				if comment.Issue.IsPull {
+					issueType = "pulls"
+				}
+				log.Trace("Permission Denied: User %-v not the Poster (ID: %d) and cannot read %s in Repo %-v.\n"+
+					"User in Repo has Permissions: %-+v",
+					ctx.User,
+					log.NewColoredIDValue(comment.Issue.PosterID),
+					issueType,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			} else {
+				log.Trace("Permission Denied: Not logged in")
+			}
+		}
+
 		ctx.Error(403)
 		return
 	} else if comment.Type != models.CommentTypeComment && comment.Type != models.CommentTypeCode {
diff --git a/routers/repo/issue_watch.go b/routers/repo/issue_watch.go
index c6a436801a..eae663495a 100644
--- a/routers/repo/issue_watch.go
+++ b/routers/repo/issue_watch.go
@@ -11,6 +11,7 @@ import (
 
 	"code.gitea.io/gitea/models"
 	"code.gitea.io/gitea/modules/context"
+	"code.gitea.io/gitea/modules/log"
 )
 
 // IssueWatch sets issue watching
@@ -21,6 +22,23 @@ func IssueWatch(ctx *context.Context) {
 	}
 
 	if !ctx.IsSigned || (ctx.User.ID != issue.PosterID && !ctx.Repo.CanReadIssuesOrPulls(issue.IsPull)) {
+		if log.IsTrace() {
+			if ctx.IsSigned {
+				issueType := "issues"
+				if issue.IsPull {
+					issueType = "pulls"
+				}
+				log.Trace("Permission Denied: User %-v not the Poster (ID: %d) and cannot read %s in Repo %-v.\n"+
+					"User in Repo has Permissions: %-+v",
+					ctx.User,
+					log.NewColoredIDValue(issue.PosterID),
+					issueType,
+					ctx.Repo.Repository,
+					ctx.Repo.Permission)
+			} else {
+				log.Trace("Permission Denied: Not logged in")
+			}
+		}
 		ctx.Error(403)
 		return
 	}
diff --git a/routers/repo/pull.go b/routers/repo/pull.go
index 0616ee2c77..70a1443e8a 100644
--- a/routers/repo/pull.go
+++ b/routers/repo/pull.go
@@ -64,6 +64,18 @@ func getForkRepository(ctx *context.Context) *models.Repository {
 	}
 
 	if forkRepo.IsEmpty || !perm.CanRead(models.UnitTypeCode) {
+		if log.IsTrace() {
+			if forkRepo.IsEmpty {
+				log.Trace("Empty fork repository %-v", forkRepo)
+			} else {
+				log.Trace("Permission Denied: User %-v cannot read %-v of forkRepo %-v\n"+
+					"User in forkRepo has Permissions: %-+v",
+					ctx.User,
+					models.UnitTypeCode,
+					ctx.Repo,
+					perm)
+			}
+		}
 		ctx.NotFound("getForkRepository", nil)
 		return nil
 	}
@@ -704,7 +716,12 @@ func ParseCompareInfo(ctx *context.Context) (*models.User, *models.Repository, *
 		return nil, nil, nil, nil, "", ""
 	}
 	if !perm.CanReadIssuesOrPulls(true) {
-		log.Trace("ParseCompareInfo[%d]: cannot create/read pull requests", baseRepo.ID)
+		if log.IsTrace() {
+			log.Trace("Permission Denied: User: %-v cannot create/read pull requests in Repo: %-v\nUser in headRepo has Permissions: %-+v",
+				ctx.User,
+				headRepo,
+				perm)
+		}
 		ctx.NotFound("ParseCompareInfo", nil)
 		return nil, nil, nil, nil, "", ""
 	}
diff --git a/routers/repo/wiki.go b/routers/repo/wiki.go
index c0fb370dd9..43149c0340 100644
--- a/routers/repo/wiki.go
+++ b/routers/repo/wiki.go
@@ -16,6 +16,7 @@ import (
 	"code.gitea.io/gitea/modules/base"
 	"code.gitea.io/gitea/modules/context"
 	"code.gitea.io/gitea/modules/git"
+	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/markup"
 	"code.gitea.io/gitea/modules/markup/markdown"
 	"code.gitea.io/gitea/modules/util"
@@ -32,6 +33,15 @@ const (
 func MustEnableWiki(ctx *context.Context) {
 	if !ctx.Repo.CanRead(models.UnitTypeWiki) &&
 		!ctx.Repo.CanRead(models.UnitTypeExternalWiki) {
+		if log.IsTrace() {
+			log.Trace("Permission Denied: User %-v cannot read %-v or %-v of repo %-v\n"+
+				"User in repo has Permissions: %-+v",
+				ctx.User,
+				models.UnitTypeWiki,
+				models.UnitTypeExternalWiki,
+				ctx.Repo.Repository,
+				ctx.Repo.Permission)
+		}
 		ctx.NotFound("MustEnableWiki", nil)
 		return
 	}
diff --git a/routers/user/home.go b/routers/user/home.go
index 79377ac500..2293461f08 100644
--- a/routers/user/home.go
+++ b/routers/user/home.go
@@ -14,6 +14,7 @@ import (
 	"code.gitea.io/gitea/models"
 	"code.gitea.io/gitea/modules/base"
 	"code.gitea.io/gitea/modules/context"
+	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/setting"
 	"code.gitea.io/gitea/modules/util"
 
@@ -308,6 +309,14 @@ func Issues(ctx *context.Context) {
 			return
 		}
 		if !perm.CanRead(models.UnitTypeIssues) {
+			if log.IsTrace() {
+				log.Trace("Permission Denied: User %-v cannot read %-v of repo %-v\n"+
+					"User in repo has Permissions: %-+v",
+					ctxUser,
+					models.UnitTypeIssues,
+					repo,
+					perm)
+			}
 			ctx.Status(404)
 			return
 		}