From f81bd8c65637a775a2287551cc836b8c28b39e0b Mon Sep 17 00:00:00 2001
From: 6543 <6543@obermui.de>
Date: Mon, 27 Sep 2021 23:32:08 +0200
Subject: [PATCH]  Extend Logging & Report to WebHook Caller back if pulls are
 disabled (#369)

* Add more logging
* Format Code
* Add TODOs
* Fix nits
* Delete two unused functions
* Report to WebHook Caller back if pulls are disabled
---
 cmd/server/server.go                     |  2 ++
 server/api/hook.go                       | 26 ++++++++++++++++--------
 server/api/z.go                          |  3 ++-
 server/model/const.go                    |  2 ++
 server/model/repo.go                     |  7 -------
 server/remote/coding/coding_test.go      |  9 --------
 server/remote/remote.go                  |  4 ++++
 server/router/middleware/session/repo.go | 13 ------------
 server/router/middleware/session/user.go | 12 -----------
 server/router/router.go                  | 10 +++++++--
 server/shared/configFetcher.go           | 21 ++++++++++++++++---
 shared/token/token.go                    | 22 ++++++++++++--------
 12 files changed, 67 insertions(+), 64 deletions(-)

diff --git a/cmd/server/server.go b/cmd/server/server.go
index 0d9e8b5df..93e6e8edb 100644
--- a/cmd/server/server.go
+++ b/cmd/server/server.go
@@ -54,7 +54,9 @@ import (
 func loop(c *cli.Context) error {
 
 	// debug level if requested by user
+	// TODO: format output & options to switch to json aka. option to add channels to send logs to
 	if c.Bool("debug") {
+		logrus.SetReportCaller(true)
 		logrus.SetLevel(logrus.DebugLevel)
 	} else {
 		logrus.SetLevel(logrus.WarnLevel)
diff --git a/server/api/hook.go b/server/api/hook.go
index d34ce5091..82e837324 100644
--- a/server/api/hook.go
+++ b/server/api/hook.go
@@ -79,7 +79,7 @@ func BlockTilQueueHasRunningItem(c *gin.Context) {
 func PostHook(c *gin.Context) {
 	remote_ := remote.FromContext(c)
 
-	tmprepo, build, err := remote_.Hook(c.Request)
+	tmpRepo, build, err := remote_.Hook(c.Request)
 	if err != nil {
 		logrus.Errorf("failure to parse hook. %s", err)
 		c.AbortWithError(400, err)
@@ -89,7 +89,7 @@ func PostHook(c *gin.Context) {
 		c.Writer.WriteHeader(200)
 		return
 	}
-	if tmprepo == nil {
+	if tmpRepo == nil {
 		logrus.Errorf("failure to ascertain repo from hook.")
 		c.Writer.WriteHeader(400)
 		return
@@ -104,14 +104,14 @@ func PostHook(c *gin.Context) {
 		return
 	}
 
-	repo, err := store.GetRepoOwnerName(c, tmprepo.Owner, tmprepo.Name)
+	repo, err := store.GetRepoOwnerName(c, tmpRepo.Owner, tmpRepo.Name)
 	if err != nil {
-		logrus.Errorf("failure to find repo %s/%s from hook. %s", tmprepo.Owner, tmprepo.Name, err)
+		logrus.Errorf("failure to find repo %s/%s from hook. %s", tmpRepo.Owner, tmpRepo.Name, err)
 		c.AbortWithError(404, err)
 		return
 	}
 	if !repo.IsActive {
-		logrus.Errorf("ignoring hook. %s/%s is inactive.", tmprepo.Owner, tmprepo.Name)
+		logrus.Errorf("ignoring hook. %s/%s is inactive.", tmpRepo.Owner, tmpRepo.Name)
 		c.AbortWithError(204, err)
 		return
 	}
@@ -139,6 +139,7 @@ func PostHook(c *gin.Context) {
 
 	if build.Event == model.EventPull && !repo.AllowPull {
 		logrus.Infof("ignoring hook. repo %s is disabled for pull requests.", repo.FullName)
+		c.Writer.Write([]byte("pulls are disabled on woodpecker for this repo"))
 		c.Writer.WriteHeader(204)
 		return
 	}
@@ -154,9 +155,14 @@ func PostHook(c *gin.Context) {
 	// may be stale. Therefore, we should refresh prior to dispatching
 	// the build.
 	if refresher, ok := remote_.(remote.Refresher); ok {
-		ok, _ := refresher.Refresh(user)
-		if ok {
-			store.UpdateUser(c, user)
+		ok, err := refresher.Refresh(user)
+		if err != nil {
+			logrus.Errorf("failed to refresh oauth2 token: %s", err)
+		} else if ok {
+			if err := store.UpdateUser(c, user); err != nil {
+				logrus.Errorf("error while updating user: %s", err)
+				// move forward
+			}
 		}
 	}
 
@@ -286,12 +292,16 @@ func PostHook(c *gin.Context) {
 	queueBuild(build, repo, buildItems)
 }
 
+// TODO: parse yaml once and not for each filter function
 func branchFiltered(build *model.Build, remoteYamlConfigs []*remote.FileMeta) (bool, error) {
+	logrus.Tracef("hook.branchFiltered(): build branch: '%s' build event: '%s' config count: %d", build.Branch, build.Event, len(remoteYamlConfigs))
 	for _, remoteYamlConfig := range remoteYamlConfigs {
 		parsedPipelineConfig, err := yaml.ParseString(string(remoteYamlConfig.Data))
 		if err != nil {
+			logrus.Tracef("parse config '%s': %s", remoteYamlConfig.Name, err)
 			return false, err
 		}
+		logrus.Tracef("config '%s': %#v", remoteYamlConfig.Name, parsedPipelineConfig)
 
 		if !parsedPipelineConfig.Branches.Match(build.Branch) && build.Event != model.EventTag && build.Event != model.EventDeploy {
 		} else {
diff --git a/server/api/z.go b/server/api/z.go
index a74e27d57..8e8aaf004 100644
--- a/server/api/z.go
+++ b/server/api/z.go
@@ -15,9 +15,10 @@
 package api
 
 import (
-	"github.com/gin-gonic/gin"
 	"github.com/woodpecker-ci/woodpecker/server/store"
 	"github.com/woodpecker-ci/woodpecker/version"
+
+	"github.com/gin-gonic/gin"
 )
 
 // Health endpoint returns a 500 if the server state is unhealthy.
diff --git a/server/model/const.go b/server/model/const.go
index 7b1bc465e..f550eb287 100644
--- a/server/model/const.go
+++ b/server/model/const.go
@@ -21,6 +21,8 @@ const (
 	EventDeploy = "deployment"
 )
 
+// TODO: type StatusValue string
+
 const (
 	StatusSkipped  = "skipped"
 	StatusPending  = "pending"
diff --git a/server/model/repo.go b/server/model/repo.go
index 96fca7246..f4916eb90 100644
--- a/server/model/repo.go
+++ b/server/model/repo.go
@@ -19,13 +19,6 @@ import (
 	"strings"
 )
 
-type RepoLite struct {
-	Owner    string `json:"owner"`
-	Name     string `json:"name"`
-	FullName string `json:"full_name"`
-	Avatar   string `json:"avatar_url"`
-}
-
 // Repo represents a repository.
 //
 // swagger:model repo
diff --git a/server/remote/coding/coding_test.go b/server/remote/coding/coding_test.go
index 133b6ba34..78df27ed3 100644
--- a/server/remote/coding/coding_test.go
+++ b/server/remote/coding/coding_test.go
@@ -289,15 +289,6 @@ var (
 		Name:  "not_found_project",
 	}
 
-	fakeRepos = []*model.RepoLite{
-		&model.RepoLite{
-			Owner:    "demo1",
-			Name:     "test1",
-			FullName: "demo1/test1",
-			Avatar:   "/static/project_icon/scenery-5.png",
-		},
-	}
-
 	fakeBuild = &model.Build{
 		Commit: "4504a072cc",
 	}
diff --git a/server/remote/remote.go b/server/remote/remote.go
index b401aa7e1..64374857d 100644
--- a/server/remote/remote.go
+++ b/server/remote/remote.go
@@ -24,6 +24,10 @@ import (
 	"golang.org/x/net/context"
 )
 
+// TODO: use pagination
+// TODO: use context
+// TODO: add Driver() who return source forge back
+
 type Remote interface {
 	// Login authenticates the session and returns the
 	// remote user details.
diff --git a/server/router/middleware/session/repo.go b/server/router/middleware/session/repo.go
index 7ba588a17..de5224104 100644
--- a/server/router/middleware/session/repo.go
+++ b/server/router/middleware/session/repo.go
@@ -38,18 +38,6 @@ func Repo(c *gin.Context) *model.Repo {
 	return r
 }
 
-func Repos(c *gin.Context) []*model.RepoLite {
-	v, ok := c.Get("repos")
-	if !ok {
-		return nil
-	}
-	r, ok := v.([]*model.RepoLite)
-	if !ok {
-		return nil
-	}
-	return r
-}
-
 func SetRepo() gin.HandlerFunc {
 	return func(c *gin.Context) {
 		var (
@@ -93,7 +81,6 @@ func Perm(c *gin.Context) *model.Perm {
 }
 
 func SetPerm() gin.HandlerFunc {
-
 	return func(c *gin.Context) {
 		user := User(c)
 		repo := Repo(c)
diff --git a/server/router/middleware/session/user.go b/server/router/middleware/session/user.go
index 659444bb0..6103c87b0 100644
--- a/server/router/middleware/session/user.go
+++ b/server/router/middleware/session/user.go
@@ -36,18 +36,6 @@ func User(c *gin.Context) *model.User {
 	return u
 }
 
-func Token(c *gin.Context) *token.Token {
-	v, ok := c.Get("token")
-	if !ok {
-		return nil
-	}
-	u, ok := v.(*token.Token)
-	if !ok {
-		return nil
-	}
-	return u
-}
-
 func SetUser() gin.HandlerFunc {
 	return func(c *gin.Context) {
 		var user *model.User
diff --git a/server/router/router.go b/server/router/router.go
index bd3eef278..559d2d408 100644
--- a/server/router/router.go
+++ b/server/router/router.go
@@ -17,8 +17,6 @@ package router
 import (
 	"net/http"
 
-	"github.com/gin-gonic/gin"
-
 	"github.com/woodpecker-ci/woodpecker/server/api"
 	"github.com/woodpecker-ci/woodpecker/server/api/debug"
 	"github.com/woodpecker-ci/woodpecker/server/api/metrics"
@@ -26,6 +24,9 @@ import (
 	"github.com/woodpecker-ci/woodpecker/server/router/middleware/session"
 	"github.com/woodpecker-ci/woodpecker/server/router/middleware/token"
 	"github.com/woodpecker-ci/woodpecker/server/web"
+
+	"github.com/gin-gonic/gin"
+	"github.com/sirupsen/logrus"
 )
 
 // Load loads the router
@@ -34,6 +35,11 @@ func Load(serveHTTP func(w http.ResponseWriter, r *http.Request), middleware ...
 	e := gin.New()
 	e.Use(gin.Recovery())
 
+	e.Use(func(c *gin.Context) {
+		logrus.Tracef("[%s] %s", c.Request.Method, c.Request.URL.String())
+		c.Next()
+	})
+
 	e.Use(header.NoCache)
 	e.Use(header.Options)
 	e.Use(header.Secure)
diff --git a/server/shared/configFetcher.go b/server/shared/configFetcher.go
index ce75c4518..8924066e4 100644
--- a/server/shared/configFetcher.go
+++ b/server/shared/configFetcher.go
@@ -7,6 +7,8 @@ import (
 
 	"github.com/woodpecker-ci/woodpecker/server/model"
 	"github.com/woodpecker-ci/woodpecker/server/remote"
+
+	"github.com/sirupsen/logrus"
 )
 
 type configFetcher struct {
@@ -25,10 +27,14 @@ func NewConfigFetcher(remote remote.Remote, user *model.User, repo *model.Repo,
 	}
 }
 
+// Fetch
+// TODO: dedupe code
 func (cf *configFetcher) Fetch() (files []*remote.FileMeta, err error) {
 	var file []byte
 	config := strings.TrimSpace(cf.repo.Config)
 
+	logrus.Tracef("Start Fetching config for '%s'", cf.repo.FullName)
+
 	for i := 0; i < 5; i++ {
 		select {
 		case <-time.After(time.Second * time.Duration(i)):
@@ -37,6 +43,7 @@ func (cf *configFetcher) Fetch() (files []*remote.FileMeta, err error) {
 				if !strings.HasSuffix(config, "/") {
 					file, err = cf.remote_.File(cf.user, cf.repo, cf.build, config)
 					if err == nil && len(file) != 0 {
+						logrus.Tracef("ConfigFetch[%s]: found file '%s'", cf.repo.FullName, config)
 						return []*remote.FileMeta{{
 							Name: config,
 							Data: file,
@@ -47,29 +54,37 @@ func (cf *configFetcher) Fetch() (files []*remote.FileMeta, err error) {
 				// or a folder
 				files, err = cf.remote_.Dir(cf.user, cf.repo, cf.build, strings.TrimSuffix(config, "/"))
 				if err == nil {
+					logrus.Tracef("ConfigFetch[%s]: found %d files in '%s'", cf.repo.FullName, len(files), config)
 					return filterPipelineFiles(files), nil
 				}
 			} else {
+				logrus.Tracef("ConfigFetch[%s]: user did not defined own config follow default procedure", cf.repo.FullName)
 				// no user defined config so try .woodpecker/*.yml -> .woodpecker.yml -> .drone.yml
 
 				// test .woodpecker/ folder
 				// if folder is not supported we will get a "Not implemented" error and continue
-				files, err = cf.remote_.Dir(cf.user, cf.repo, cf.build, ".woodpecker")
+				config = ".woodpecker"
+				files, err = cf.remote_.Dir(cf.user, cf.repo, cf.build, config)
+				logrus.Tracef("ConfigFetch[%s]: found %d files in '%s'", cf.repo.FullName, len(files), config)
 				files = filterPipelineFiles(files)
 				if err == nil && len(files) != 0 {
 					return files, nil
 				}
 
-				file, err = cf.remote_.File(cf.user, cf.repo, cf.build, ".woodpecker.yml")
+				config = ".woodpecker.yml"
+				file, err = cf.remote_.File(cf.user, cf.repo, cf.build, config)
 				if err == nil && len(file) != 0 {
+					logrus.Tracef("ConfigFetch[%s]: found file '%s'", cf.repo.FullName, config)
 					return []*remote.FileMeta{{
 						Name: ".woodpecker.yml",
 						Data: file,
 					}}, nil
 				}
 
-				file, err = cf.remote_.File(cf.user, cf.repo, cf.build, ".drone.yml")
+				config = ".drone.yml"
+				file, err = cf.remote_.File(cf.user, cf.repo, cf.build, config)
 				if err == nil && len(file) != 0 {
+					logrus.Tracef("ConfigFetch[%s]: found file '%s'", cf.repo.FullName, config)
 					return []*remote.FileMeta{{
 						Name: ".drone.yml",
 						Data: file,
diff --git a/shared/token/token.go b/shared/token/token.go
index 1bc5dce34..38c34c069 100644
--- a/shared/token/token.go
+++ b/shared/token/token.go
@@ -19,6 +19,7 @@ import (
 	"net/http"
 
 	"github.com/golang-jwt/jwt"
+	"github.com/sirupsen/logrus"
 )
 
 type SecretFunc func(*Token) (string, error)
@@ -31,7 +32,7 @@ const (
 	AgentToken = "agent"
 )
 
-// Default algorithm used to sign JWT tokens.
+// SignerAlgo id default algorithm used to sign JWT tokens.
 const SignerAlgo = "HS256"
 
 type Token struct {
@@ -39,7 +40,7 @@ type Token struct {
 	Text string
 }
 
-func Parse(raw string, fn SecretFunc) (*Token, error) {
+func parse(raw string, fn SecretFunc) (*Token, error) {
 	token := &Token{}
 	parsed, err := jwt.Parse(raw, keyFunc(token, fn))
 	if err != nil {
@@ -51,21 +52,24 @@ func Parse(raw string, fn SecretFunc) (*Token, error) {
 }
 
 func ParseRequest(r *http.Request, fn SecretFunc) (*Token, error) {
-	var token = r.Header.Get("Authorization")
+	token := r.Header.Get("Authorization")
 
 	// first we attempt to get the token from the
 	// authorization header.
 	if len(token) != 0 {
-		token = r.Header.Get("Authorization")
-		fmt.Sscanf(token, "Bearer %s", &token)
-		return Parse(token, fn)
+		logrus.Tracef("token.ParseRequest: found token in header: %s", token)
+		bearer := token
+		if _, err := fmt.Sscanf(token, "Bearer %s", &bearer); err != nil {
+			return nil, err
+		}
+		return parse(bearer, fn)
 	}
 
 	// then we attempt to get the token from the
 	// access_token url query parameter
 	token = r.FormValue("access_token")
 	if len(token) != 0 {
-		return Parse(token, fn)
+		return parse(token, fn)
 	}
 
 	// and finally we attempt to get the token from
@@ -74,7 +78,7 @@ func ParseRequest(r *http.Request, fn SecretFunc) (*Token, error) {
 	if err != nil {
 		return nil, err
 	}
-	return Parse(cookie.Value, fn)
+	return parse(cookie.Value, fn)
 }
 
 func CheckCsrf(r *http.Request, fn SecretFunc) error {
@@ -88,7 +92,7 @@ func CheckCsrf(r *http.Request, fn SecretFunc) error {
 
 	// parse the raw CSRF token value and validate
 	raw := r.Header.Get("X-CSRF-TOKEN")
-	_, err := Parse(raw, fn)
+	_, err := parse(raw, fn)
 	return err
 }