Tidy up trace logging for scheduler.

CHANGELOG.md

@@ -1,3 +1,6 @@
+Development
+  - tidy up trace logging for scheduler
+
 0.6.2
   - do not attempt to aggregate a failed attestation
   - error appropriately when misconfigured

services/scheduler/basic/service.go

@@ -125,8 +125,8 @@ func (s *Service) ScheduleJob(ctx context.Context, name string, runtime time.Tim
 				s.mutex.Unlock()
 				log.Trace().Str("job", name).Str("scheduled", fmt.Sprintf("%v", runtime)).Msg("Timer triggered; job running")
 				s.monitor.JobStartedOnTimer()
-				log.Trace().Str("job", name).Str("scheduled", fmt.Sprintf("%v", runtime)).Msg("Job complete")
 				jobFunc(ctx, data)
+				log.Trace().Str("job", name).Str("scheduled", fmt.Sprintf("%v", runtime)).Msg("Job complete")
 			} else {
 				// Job has been taken by another thread; do nothing.
 				s.mutex.Unlock()
@@ -137,7 +137,10 @@ func (s *Service) ScheduleJob(ctx context.Context, name string, runtime time.Tim
 	return nil
 }
 
-// SchedulePeriodicJob scheduls a periodic job for a given time.
+// SchedulePeriodicJob schedules a job to run in a loop.
+// The loop starts by calling runtimeFunc, which sets the time for the first run.
+// Once the time as specified by runtimeFunc is met, jobFunc is called.
+// Once jobFunc returns, go back to the beginning of the loop.
 func (s *Service) SchedulePeriodicJob(ctx context.Context, name string, runtimeFunc scheduler.RuntimeFunc, runtimeData interface{}, jobFunc scheduler.JobFunc, jobData interface{}) error {
 	if name == "" {
 		return scheduler.ErrNoJobName
@@ -206,6 +209,7 @@ func (s *Service) SchedulePeriodicJob(ctx context.Context, name string, runtimeF
 				log.Trace().Str("job", name).Str("scheduled", fmt.Sprintf("%v", runtime)).Msg("Run triggered; job running")
 				s.monitor.JobStartedOnSignal()
 				jobFunc(ctx, jobData)
+				log.Trace().Str("job", name).Str("scheduled", fmt.Sprintf("%v", runtime)).Msg("Job complete")
 				s.unlockJob(ctx, name)
 			case <-time.After(time.Until(runtime)):
 				s.mutex.Lock()
@@ -214,6 +218,7 @@ func (s *Service) SchedulePeriodicJob(ctx context.Context, name string, runtimeF
 				log.Trace().Str("job", name).Str("scheduled", fmt.Sprintf("%v", runtime)).Msg("Timer triggered; job running")
 				s.monitor.JobStartedOnTimer()
 				jobFunc(ctx, jobData)
+				log.Trace().Str("job", name).Str("scheduled", fmt.Sprintf("%v", runtime)).Msg("Job complete")
 				s.unlockJob(ctx, name)
 			}
 		}
@@ -259,7 +264,6 @@ func (s *Service) ListJobs(ctx context.Context) []string {
 
 // RunJobIfExists runs a job if it exists.
 // This does not return an error if the job does not exist.
-// If the job does not exist it will return an appropriate error.
 func (s *Service) RunJobIfExists(ctx context.Context, name string) error {
 	s.mutex.RLock()
 	defer s.mutex.RUnlock()
@@ -326,7 +330,7 @@ func (s *Service) lockJob(ctx context.Context, name string) {
 }
 
 // unlockJob unlocks a specific job.
-// This assumes that the service mutex is held.
+// This should be called without the service mutex held, to avoid lock<>lock<>unlock situations.
 func (s *Service) unlockJob(ctx context.Context, name string) {
 	job, exists := s.jobs[name]
 	if !exists {

services/scheduler/basic/service_test.go

@@ -439,3 +439,29 @@ func TestListJobs(t *testing.T) {
 	require.Len(t, jobs, 1)
 	require.Contains(t, jobs, "Test job 2")
 }
+
+func TestLongRunningPeriodicJob(t *testing.T) {
+	ctx := context.Background()
+	s, err := basic.New(ctx, basic.WithLogLevel(zerolog.Disabled), basic.WithMonitor(&nullmetrics.Service{}))
+	require.NoError(t, err)
+	require.NotNil(t, s)
+
+	// Job takes 200 ms.
+	run := uint32(0)
+	jobFunc := func(ctx context.Context, data interface{}) {
+		time.Sleep(200 * time.Millisecond)
+		atomic.AddUint32(&run, 1)
+	}
+
+	// Job runs every 150 ms.
+	runtimeFunc := func(ctx context.Context, data interface{}) (time.Time, error) {
+		return time.Now().Add(150 * time.Millisecond), nil
+	}
+
+	// Schedule the job.
+	require.NoError(t, s.SchedulePeriodicJob(ctx, "Test long running periodic job", runtimeFunc, nil, jobFunc, nil))
+
+	// Sleep for 800 ms.  Expect two runs (150+200+150+200+150).
+	time.Sleep(800 * time.Millisecond)
+	assert.Equal(t, uint32(2), run)
+}

services/scheduler/service.go

@@ -52,7 +52,10 @@ type Service interface {
 	ScheduleJob(ctx context.Context, name string, runtime time.Time, job JobFunc, data interface{}) error
 
 	// SchedulePeriodicJob schedules a job to run in a loop.
-	SchedulePeriodicJob(ctx context.Context, name string, runtime RuntimeFunc, runtineData interface{}, job JobFunc, jobData interface{}) error
+	// The loop starts by calling runtimeFunc, which sets the time for the first run.
+	// Once the time as specified by runtimeFunc is met, jobFunc is called.
+	// Once jobFunc returns, go back to the beginning of the loop.
+	SchedulePeriodicJob(ctx context.Context, name string, runtime RuntimeFunc, runtimeData interface{}, job JobFunc, jobData interface{}) error
 
 	// CancelJob cancels a known job.
 	// If this is a period job then all future instances are cancelled.