Merge pull request #3 from schjan/logrus

Better + verbose Logging

Author: markuszm

README.md

@@ -15,5 +15,7 @@ Usage of glock:
         can be job, stage or project (default "job")
   -unlock
         unlock the locked thing
+  -v int
+        (default 3) set verbosity level (3: Warning, 4: Info, 5: Debug) (default 3)
 
 ```

cmd/lock/main.go

@@ -6,7 +6,7 @@ import (
 	"fmt"
 	"github.com/cosee-gitlab/lock"
 	"github.com/cosee-gitlab/lock/db"
-	"log"
+	log "github.com/sirupsen/logrus"
 	"time"
 )
 
@@ -15,30 +15,42 @@ var doLock = flag.Bool("lock", false, "should I aquire a lock? Returns 0 if lock
 var doUnlock = flag.Bool("unlock", false, "unlock the locked thing")
 var lockExpiration = flag.Duration("expiration", 15*time.Minute, "time after the lock gets removed, even if unlock isn't called")
 var scope = flag.String("scope", "job", "can be job, stage or project")
+var verbose = flag.Int("v", 3, "set verbosity level (3: Warning, 4: Info, 5: Debug)")
 
 func main() {
 	flag.Parse()
 
+	if *verbose < 0 || 5 < *verbose {
+		log.Fatalf("Illegal verbosity level: %v", *verbose)
+		return
+	}
+	log.SetLevel(log.Level(*verbose))
+
 	env, err := lock.LoadEnvironment()
 	if err != nil {
 		log.Fatal(err)
+		return
 	}
 
 	if env.JobId == 0 || env.PipelineId == 0 || env.ProjectId == 0 || env.JobName == "" {
 		log.Fatal("It seems that no GitLab environment variables are set")
+		return
 	}
 
 	if env.RedisHost == "" {
 		log.Fatal("Please set LOCKS_REDIS_HOST variable")
+		return
 	}
 
 	if *doLock == *doUnlock {
 		log.Fatal("I can't lock and unlock . Doin' nothing isn't an option, too")
+		return
 	}
 
 	client, err := db.New(env.RedisHost)
 	if err != nil {
 		log.Fatal(err)
+		return
 	}
 
 	var key string
@@ -54,20 +66,23 @@ func main() {
 			key = fmt.Sprintf("%d", env.ProjectId)
 		default:
 			log.Fatalf("%q isn't a valid scope. Scope can be job, stage or project.", *scope)
+			return
 		}
 	}
 
 	if *doLock {
 		err = client.Lock(key, env.JobId, *lockExpiration, context.Background())
 		if err != nil {
 			log.Fatal(err)
+			return
 		}
 	}
 
 	if *doUnlock {
 		err = client.Unlock(key, env.JobId)
 		if err != nil {
 			log.Fatal(err)
+			return
 		}
 	}
 }

db/redis.go

@@ -4,7 +4,7 @@ import (
 	"context"
 	"github.com/go-redis/redis"
 	"github.com/pkg/errors"
-	"log"
+	log "github.com/sirupsen/logrus"
 	"strconv"
 	"time"
 )
@@ -24,6 +24,7 @@ func New(host string) (*r, error) {
 	client := redis.NewClient(options)
 
 	err = client.Ping().Err()
+	log.WithError(err).Debug("Ping()")
 	if err != nil {
 		return nil, err
 	}
@@ -32,6 +33,9 @@ func New(host string) (*r, error) {
 }
 
 func (r *r) Lock(key string, jobId int, expiration time.Duration, ctx context.Context) error {
+	log := log.WithField("key", key)
+	log.Debug("-lock flag was set, so trying to acquire lock")
+
 	locked, err := r.tryLock(key, jobId, expiration)
 	if err != nil {
 		return err
@@ -40,7 +44,7 @@ func (r *r) Lock(key string, jobId int, expiration time.Duration, ctx context.Co
 		return nil
 	}
 
-	log.Printf("somebody else has locked the resource, so trying to get lock for %v", expiration)
+	log.Warnf("somebody else has already locked the resource, so trying to get lock for %v", expiration)
 
 	for {
 		select {
@@ -60,8 +64,12 @@ func (r *r) Lock(key string, jobId int, expiration time.Duration, ctx context.Co
 }
 
 func (r *r) Unlock(key string, jobId int) error {
+	log := log.WithField("key", key)
+	log.Debug("-unlock flag was set, so trying to unlock")
+
 	var lockId int
 	getLockId, err := r.c.Get(key).Result()
+	log.WithField("getLockId", getLockId).WithError(err).Debugf("Get(key:%v)", key)
 	if err != nil {
 		if err == redis.Nil {
 			lockId = 0
@@ -77,21 +85,26 @@ func (r *r) Unlock(key string, jobId int) error {
 	}
 
 	delRes, err := r.c.Del(key).Result()
+	log.WithField("result", delRes).WithError(err).Debugf("Del(key:%v)", key)
 	if err != nil {
 		return err
 	}
 
 	if delRes != 1 {
-		log.Print("Couldn't remove lock. It isn't there")
+		log.Warn("Couldn't remove lock. It isn't there")
 	}
 
 	return nil
 }
 
 func (r *r) tryLock(key string, jobId int, expiration time.Duration) (bool, error) {
+	log := log.WithField("key", key)
+	log.Info("Trying...")
+
 	var newestJob int
 	var lockId int
 	getLockId, err := r.c.Get(key).Result()
+	log.WithField("getLockId", getLockId).WithError(err).Debugf("Get(key:%v)", key)
 	if err != nil {
 		if err == redis.Nil {
 			lockId = 0
@@ -107,6 +120,7 @@ func (r *r) tryLock(key string, jobId int, expiration time.Duration) (bool, erro
 	}
 
 	getNewestJobResult, err := r.c.Get(key + newestJobKey).Result()
+	log.WithField("getNewestJobResult", getNewestJobResult).WithError(err).Debugf("Get(key:%v)", key+newestJobKey)
 	if err != nil {
 		if err == redis.Nil {
 			newestJob = 0
@@ -127,10 +141,12 @@ func (r *r) tryLock(key string, jobId int, expiration time.Duration) (bool, erro
 	if newestJob > jobId {
 		return false, errors.Errorf("Newer Job: %v > Actual Job: %v is also waiting for a lock.", newestJob, jobId)
 	} else if newestJob < jobId {
-		r.c.Set(key+newestJobKey, jobId, 0).Err()
+		err = r.c.Set(key+newestJobKey, jobId, 0).Err()
+		log.WithError(err).Debugf("Set(key:%v, jobId:%v, 0)", key, jobId)
 	}
 
 	set, err := r.c.SetNX(key, jobId, expiration).Result()
+	log.WithError(err).WithField("logAcquired", set).Debugf("SetNX(key:%v, jobId:%v, expiration:%v)", key, jobId, expiration)
 	if err != nil {
 		return false, err
 	}

go.mod

@@ -3,10 +3,13 @@ module github.com/cosee-gitlab/lock
 require (
 	github.com/go-redis/redis v6.14.1+incompatible
 	github.com/kelseyhightower/envconfig v1.3.0
+	github.com/konsorten/go-windows-terminal-sequences v1.0.1 // indirect
 	github.com/kr/pretty v0.1.0 // indirect
 	github.com/onsi/gomega v1.4.2 // indirect
 	github.com/pkg/errors v0.8.0
+	github.com/sirupsen/logrus v1.1.1
+	golang.org/x/crypto v0.0.0-20181015023909-0c41d7ab0a0e // indirect
 	golang.org/x/net v0.0.0-20180926154720-4dfa2610cdf3 // indirect
-	golang.org/x/sys v0.0.0-20180928133829-e4b3c5e90611 // indirect
+	golang.org/x/sys v0.0.0-20181011152604-fa43e7bc11ba // indirect
 	gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 // indirect
 )

go.sum

@@ -1,3 +1,4 @@
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/fsnotify/fsnotify v1.4.7 h1:IXs+QLmnXW2CcXuY+8Mzv/fWEsPGWxqefPtCP5CnV9I=
 github.com/fsnotify/fsnotify v1.4.7/go.mod h1:jwhsz4b93w/PPRr/qN1Yymfu8t87LnFCMoQvtojpjFo=
 github.com/go-redis/redis v6.14.1+incompatible h1:kSJohAREGMr344uMa8PzuIg5OU6ylCbyDkWkkNOfEik=
@@ -8,6 +9,8 @@ github.com/hpcloud/tail v1.0.0 h1:nfCOvKYfkgYP8hkirhJocXT2+zOD8yUNjXaWfTlyFKI=
 github.com/hpcloud/tail v1.0.0/go.mod h1:ab1qPbhIpdTxEkNHXyeSf5vhxWSCs/tWer42PpOxQnU=
 github.com/kelseyhightower/envconfig v1.3.0 h1:IvRS4f2VcIQy6j4ORGIf9145T/AsUB+oY8LyvN8BXNM=
 github.com/kelseyhightower/envconfig v1.3.0/go.mod h1:cccZRl6mQpaq41TPp5QxidR+Sa3axMbJDNb//FQX6Gg=
+github.com/konsorten/go-windows-terminal-sequences v0.0.0-20180402223658-b729f2633dfe/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
@@ -19,16 +22,26 @@ github.com/onsi/gomega v1.4.2 h1:3mYCb7aPxS/RU7TI1y4rkEn1oKmPRjNJLNEXgw7MH2I=
 github.com/onsi/gomega v1.4.2/go.mod h1:ex+gbHU/CVuBBDIJjb2X0qEXbFg53c61hWP/1CpauHY=
 github.com/pkg/errors v0.8.0 h1:WdK/asTD0HN+q6hsWO3/vpuAkAr+tw6aNJNDFFf0+qw=
 github.com/pkg/errors v0.8.0/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/sirupsen/logrus v1.1.1 h1:VzGj7lhU7KEB9e9gMpAV/v5XT2NVSvLJhJLCWbnkgXg=
+github.com/sirupsen/logrus v1.1.1/go.mod h1:zrgwTnHtNr00buQ1vSptGe8m1f/BbgsPukg8qsT7A+A=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
+golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
+golang.org/x/crypto v0.0.0-20181015023909-0c41d7ab0a0e h1:IzypfodbhbnViNUO/MEh0FzCUooG97cIGfdggUrUSyU=
+golang.org/x/crypto v0.0.0-20181015023909-0c41d7ab0a0e/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/net v0.0.0-20180906233101-161cd47e91fd h1:nTDtHvHSdCn1m6ITfMRqtOd/9+7a3s8RBNOZ3eYZzJA=
 golang.org/x/net v0.0.0-20180906233101-161cd47e91fd/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/net v0.0.0-20180926154720-4dfa2610cdf3 h1:dgd4x4kJt7G4k4m93AYLzM8Ni6h2qLTfh9n9vXJT3/0=
 golang.org/x/net v0.0.0-20180926154720-4dfa2610cdf3/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/sync v0.0.0-20180314180146-1d60e4601c6f h1:wMNYb4v58l5UBM7MYRLPG6ZhfOqbKu7X5eyFl8ZhKvA=
 golang.org/x/sync v0.0.0-20180314180146-1d60e4601c6f/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e h1:o3PsSEY8E4eXWkXrIP9YJALUkVZqzHJT5DOasTyn8Vs=
 golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20180928133829-e4b3c5e90611 h1:O33LKL7WyJgjN9CvxfTIomjIClbd/Kq86/iipowHQU0=
 golang.org/x/sys v0.0.0-20180928133829-e4b3c5e90611/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20181011152604-fa43e7bc11ba h1:nZJIJPGow0Kf9bU9QTc1U6OXbs/7Hu4e+cNv+hxH+Zc=
+golang.org/x/sys v0.0.0-20181011152604-fa43e7bc11ba/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=