Added Logging Interface + More Verbosity

Signed-off-by: Sherif Abdel-Naby <sherifabdlnaby@gmail.com>

go.mod

@@ -5,4 +5,5 @@ go 1.16
 require (
 	github.com/google/uuid v1.2.0 // indirect
 	github.com/gorhill/cronexpr v0.0.0-20180427100037-88b0669f7d75 // indirect
+	go.uber.org/zap v1.16.0 // indirect
 )

go.sum

@@ -1,4 +1,53 @@
+github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU=
+github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/google/renameio v0.1.0/go.mod h1:KWCgfxg9yswjAJkECMjeO8J8rahYeXnNhOm40UhjYkI=
 github.com/google/uuid v1.2.0 h1:qJYtXnJRWmpe7m/3XlyhrsLrEURqHRM2kxzoxXqyUDs=
 github.com/google/uuid v1.2.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/gorhill/cronexpr v0.0.0-20180427100037-88b0669f7d75 h1:f0n1xnMSmBLzVfsMMvriDyA75NB/oBgILX2GcHXIQzY=
 github.com/gorhill/cronexpr v0.0.0-20180427100037-88b0669f7d75/go.mod h1:g2644b03hfBX9Ov0ZBDgXXens4rxSxmqFBbhvKv2yVA=
+github.com/jessevdk/go-flags v1.4.1-0.20181029123624-5de817a9aa20 h1:dAOsPLhnBzIyxu0VvmnKjlNcIlgMK+erD6VRHDtweMI=
+github.com/jessevdk/go-flags v1.4.1-0.20181029123624-5de817a9aa20/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI=
+github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck=
+github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
+github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
+github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
+github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
+github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
+github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
+github.com/vburenin/ifacemaker v1.1.0 h1:3ScCGZ+D65Ud9L0x9ofhN0dk5QrfauzMWYfaYsfA+HE=
+github.com/vburenin/ifacemaker v1.1.0/go.mod h1:SlS6qpTccQsoK3ln7mBkUxA4agA8wfPr/IFYqBWerPw=
+go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk=
+go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
+go.uber.org/multierr v1.5.0 h1:KCa4XfM8CWFCpxXRGok+Q0SS/0XBhMDbHHGABQLvD2A=
+go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU=
+go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
+go.uber.org/zap v1.16.0 h1:uFRZXykJGK9lLY4HtgSw44DnIcAM+kRBP7x5m+NpAOM=
+go.uber.org/zap v1.16.0/go.mod h1:MA8QOfq0BHJwdXa996Y4dYkAqRKB8/1K1QMMZVaNZjQ=
+golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
+golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
+golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=
+golang.org/x/mod v0.0.0-20190513183733-4bf6d317e70e/go.mod h1:mXi4GBBbnImb6dmsKGUJ2LatrhH/nqhxcFungHvyanc=
+golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
+golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
+golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
+golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
+golang.org/x/tools v0.0.0-20181201035826-d0ca3933b724 h1:eV9myT/I6o1p8salzgZ0f1pz54PEgUf2NkCxEf6t+xs=
+golang.org/x/tools v0.0.0-20181201035826-d0ca3933b724/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
+golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs=
+golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc=
+golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
+gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI=
+gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg=

interface.go

@@ -1,7 +1,23 @@
 package main
 
-import "time"
+import (
+	"time"
+)
 
 type Timer interface {
 	Next() time.Time
 }
+
+//Logger Sched logging interface similar to uber-go/zap, while keeping the option to change the logging implementation
+// It is a sub-interface of uber-go/zap SugaredLogger.
+type Logger interface {
+	Debugw(msg string, keysAndValues ...interface{})
+	Errorw(msg string, keysAndValues ...interface{})
+	Fatalw(msg string, keysAndValues ...interface{})
+	Infow(msg string, keysAndValues ...interface{})
+	Panicw(msg string, keysAndValues ...interface{})
+	Warnw(msg string, keysAndValues ...interface{})
+	With(args ...interface{}) Logger
+	Named(name string) Logger
+	Sync() error
+}

job/job.go

@@ -7,15 +7,6 @@ import (
 	"time"
 )
 
-type State int64
-
-const (
-	NEW State = iota
-	RUNNING
-	FINISHED
-	PANICKED
-)
-
 type Job struct {
 	id         string
 	jobFunc    func()
@@ -68,20 +59,16 @@ func (j *Job) Run() error {
 }
 
 func (j *Job) run() (err error) {
-	j.mx.RLock()
+	j.mx.Lock()
 	if j.state != NEW {
 		if j.state == RUNNING {
 			err = ErrorJobStarted{Message: "job already started"}
-			return err
+		} else {
+			err = ErrorJobStarted{Message: "job finished execution"}
 		}
-		err = ErrorJobStarted{Message: "job finished execution"}
+		j.mx.Unlock()
 		return err
 	}
-	j.mx.RUnlock()
-
-	j.mx.Lock()
-	j.state = RUNNING
-	j.startTime = time.Now()
 
 	// Handle Panics and set correct state
 	defer func() {
@@ -96,6 +83,9 @@ func (j *Job) run() (err error) {
 		j.mx.Unlock()
 	}()
 
+	j.state = RUNNING
+	j.startTime = time.Now()
+
 	// Unlock State
 	j.mx.Unlock()
 

job/state.go

@@ -0,0 +1,25 @@
+package job
+
+type State int64
+
+const (
+	NEW State = iota
+	RUNNING
+	FINISHED
+	PANICKED
+)
+
+func (s State) String() string {
+	switch s {
+	case NEW:
+		return "NEW"
+	case RUNNING:
+		return "RUNNING"
+	case FINISHED:
+		return "FINISHED"
+	case PANICKED:
+		return "PANICKED"
+	default:
+		return "UNKNOWN"
+	}
+}

log.go

@@ -0,0 +1,29 @@
+package main
+
+import (
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+type logger struct {
+	*zap.SugaredLogger
+}
+
+func (l logger) With(args ...interface{}) Logger {
+	return logger{l.SugaredLogger.With(args)}
+}
+
+func (l logger) Named(name string) Logger {
+	return logger{l.SugaredLogger.Named(name)}
+}
+
+func DefaultLogger() Logger {
+	var logConfig zap.Config
+	logConfig = zap.NewDevelopmentConfig()
+	logConfig.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
+	loggerBase, _ := logConfig.Build()
+	sugarLogger := loggerBase.Sugar().Named("sched")
+	return &logger{
+		sugarLogger,
+	}
+}

schedule.go

@@ -2,7 +2,6 @@ package main
 
 import (
 	"context"
-	"fmt"
 	"github.com/google/uuid"
 	"github.com/sherifabdlnaby/sched/job"
 	"sync"
@@ -24,14 +23,16 @@ type Schedule struct {
 	cancel  context.CancelFunc
 
 	// Concurrent safe JobMap
-	jobMap jobMap
+	activeJobs jobMap
 
 	// Wait-group
 	wg sync.WaitGroup
+
+	logger Logger
 }
 
 // NewScheduleWithID NewSchedule
-func NewScheduleWithID(ID string, jobFunc func(), timer Timer) *Schedule {
+func NewScheduleWithID(ID string, jobFunc func(), timer Timer, logger Logger) *Schedule {
 	ctx, cancel := context.WithCancel(context.Background())
 	return &Schedule{
 		ID:         ID,
@@ -39,12 +40,13 @@ func NewScheduleWithID(ID string, jobFunc func(), timer Timer) *Schedule {
 		timer:      timer,
 		context:    ctx,
 		cancel:     cancel,
-		jobMap:     *newJobMap(),
+		activeJobs: *newJobMap(),
+		logger:     logger,
 	}
 }
 
-func NewSchedule(jobFunc func(), timer Timer) *Schedule {
+func NewSchedule(jobFunc func(), timer Timer, logger Logger) *Schedule {
-	return NewScheduleWithID(uuid.New().String(), jobFunc, timer)
+	return NewScheduleWithID(uuid.New().String(), jobFunc, timer, logger)
 }
 
 func (s *Schedule) Start() {
@@ -53,10 +55,13 @@ func (s *Schedule) Start() {
 
 func (s *Schedule) Stop() {
 	// Cancel Main Context
+	s.logger.Infow("Job Schedule Stopping... canceling scheduled runs", "Job", s.ID)
 	s.cancel()
 
 	// Wait for all instances
+	s.logger.Infow("Job Schedule Stopping... awaiting active jobs to finish", "Job", s.ID)
 	s.wg.Wait()
+	s.logger.Infow("Job Schedule Stopped", "Job", s.ID)
 }
 
 //controlLoop scheduler control loop
@@ -68,13 +73,16 @@ func (s *Schedule) controlLoop() {
 			return
 		default:
 			nextRun := s.timer.Next()
-			nextRunChan := time.After(nextRun.Sub(time.Now()))
+			nextRunDuration := nextRun.Sub(time.Now())
-
+			nextRunChan := time.After(nextRunDuration)
-			// Wait Trigger
+			s.logger.Infow("Job Next Run Scheduled", "Job", s.ID, "After", nextRunDuration.Round(1*time.Second).String(), "At", nextRun.Format(time.RFC3339))
-			<-nextRunChan
+			select {
-
+			case <-s.context.Done():
-			// Run job
+				return
-			go s.runJobInstance()
+			case <-nextRunChan:
+				// Run job
+				go s.runJobInstance()
+			}
 		}
 	}
 }
@@ -85,12 +93,15 @@ func (s *Schedule) runJobInstance() {
 
 	jobInstance := job.NewJob(s.jobSrcFunc)
 
-	s.jobMap.add(jobInstance)
+	s.activeJobs.add(jobInstance)
-	defer s.jobMap.delete(jobInstance)
+	defer s.activeJobs.delete(jobInstance)
+
+	s.logger.Infow("Job Starting", "Job", s.ID, "Instance", jobInstance.ID())
 
 	err := jobInstance.Run()
+
 	if err != nil {
-		// TODO Handle on Error
+		s.logger.Errorw("Job Error", "Job", s.ID, "Instance", jobInstance.ID(), "Duration", jobInstance.Duration().Round(1*time.Millisecond), "State", jobInstance.State().String(), "error", err.Error())
-		fmt.Println(err)
 	}
+	s.logger.Infow("Job Finished", "Job", s.ID, "Instance", jobInstance.ID(), "Duration", jobInstance.Duration().Round(1*time.Millisecond), "State", jobInstance.State().String())
 }