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

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

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)
+		ok, err := refresher.Refresh(user)
-		if ok {
+		if err != nil {
-			store.UpdateUser(c, user)
+			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 {

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.

server/model/const.go

@@ -21,6 +21,8 @@ const (
 	EventDeploy = "deployment"
 )
 
+// TODO: type StatusValue string
+
 const (
 	StatusSkipped  = "skipped"
 	StatusPending  = "pending"

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

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",
 	}

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.

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)

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

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)

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,

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")
+		logrus.Tracef("token.ParseRequest: found token in header: %s", token)
-		fmt.Sscanf(token, "Bearer %s", &token)
+		bearer := token
-		return Parse(token, fn)
+		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
 }