From 75903a2da35b5924bb60093db588c43a767f64ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sybren=20A=2E=20St=C3=BCvel?= Date: Thu, 9 Jun 2022 11:24:02 +0200 Subject: [PATCH] Manager: prepend timestamp to "task assigned to worker" task log entries Add a new `clock` service to the Flamenco struct, which allows us to mock the passing of time, and thus test for timestamps in a stable fashion. --- cmd/flamenco-manager/main.go | 4 +++- internal/manager/api_impl/api_impl.go | 3 +++ internal/manager/api_impl/interfaces.go | 10 ++++++++++ internal/manager/api_impl/jobs.go | 9 +++++++++ internal/manager/api_impl/jobs_query_test.go | 4 ++-- internal/manager/api_impl/jobs_test.go | 3 +-- internal/manager/api_impl/support_test.go | 14 +++++++++++++- internal/manager/api_impl/workers.go | 2 +- internal/manager/api_impl/workers_test.go | 2 +- 9 files changed, 43 insertions(+), 8 deletions(-) diff --git a/cmd/flamenco-manager/main.go b/cmd/flamenco-manager/main.go index ad6d4b58..4112f07d 100644 --- a/cmd/flamenco-manager/main.go +++ b/cmd/flamenco-manager/main.go @@ -161,7 +161,9 @@ func buildFlamencoAPI( } logStorage := task_logs.NewStorage(configService.Get().TaskLogsPath) shamanServer := shaman.NewServer(configService.Get().Shaman, nil) - flamenco := api_impl.NewFlamenco(compiler, persist, webUpdater, logStorage, configService, taskStateMachine, shamanServer) + flamenco := api_impl.NewFlamenco( + compiler, persist, webUpdater, logStorage, configService, + taskStateMachine, shamanServer, timeService) return flamenco } diff --git a/internal/manager/api_impl/api_impl.go b/internal/manager/api_impl/api_impl.go index c494278f..df68b28a 100644 --- a/internal/manager/api_impl/api_impl.go +++ b/internal/manager/api_impl/api_impl.go @@ -22,6 +22,7 @@ type Flamenco struct { config ConfigService stateMachine TaskStateMachine shaman Shaman + clock TimeService // The task scheduler can be locked to prevent multiple Workers from getting // the same task. It is also used for certain other queries, like @@ -40,6 +41,7 @@ func NewFlamenco( cs ConfigService, sm TaskStateMachine, sha Shaman, + ts TimeService, ) *Flamenco { return &Flamenco{ jobCompiler: jc, @@ -49,6 +51,7 @@ func NewFlamenco( config: cs, stateMachine: sm, shaman: sha, + clock: ts, } } diff --git a/internal/manager/api_impl/interfaces.go b/internal/manager/api_impl/interfaces.go index 8b2f9721..0622333d 100644 --- a/internal/manager/api_impl/interfaces.go +++ b/internal/manager/api_impl/interfaces.go @@ -8,7 +8,9 @@ package api_impl import ( "context" "io" + "time" + "github.com/benbjohnson/clock" "github.com/rs/zerolog" "git.blender.org/flamenco/internal/manager/job_compilers" @@ -124,3 +126,11 @@ type Shaman interface { } var _ Shaman = (*shaman.Server)(nil) + +// TimeService provides functionality from the stdlib `time` module, but in a +// way that allows mocking. +type TimeService interface { + Now() time.Time +} + +var _ TimeService = (clock.Clock)(nil) diff --git a/internal/manager/api_impl/jobs.go b/internal/manager/api_impl/jobs.go index bfbc06c3..945495e4 100644 --- a/internal/manager/api_impl/jobs.go +++ b/internal/manager/api_impl/jobs.go @@ -7,8 +7,10 @@ import ( "fmt" "net/http" "os" + "time" "github.com/labstack/echo/v4" + "github.com/rs/zerolog" "git.blender.org/flamenco/internal/manager/job_compilers" "git.blender.org/flamenco/internal/manager/persistence" @@ -219,6 +221,13 @@ func (f *Flamenco) FetchTaskLogTail(e echo.Context, taskID string) error { return e.String(http.StatusOK, tail) } +// taskLogAppendTimestamped writes the given log text, prefixed with the current +// date & time, to the task's log. +func (f *Flamenco) taskLogAppendTimestamped(logger zerolog.Logger, jobID, taskID string, logText string) error { + now := f.clock.Now().Format(time.RFC3339) + return f.logStorage.Write(logger, jobID, taskID, now+" "+logText) +} + func jobDBtoAPI(dbJob *persistence.Job) api.Job { apiJob := api.Job{ SubmittedJob: api.SubmittedJob{ diff --git a/internal/manager/api_impl/jobs_query_test.go b/internal/manager/api_impl/jobs_query_test.go index 56c7a9c5..863d06c0 100644 --- a/internal/manager/api_impl/jobs_query_test.go +++ b/internal/manager/api_impl/jobs_query_test.go @@ -26,8 +26,8 @@ func TestFetchTask(t *testing.T) { dbTask := persistence.Task{ Model: gorm.Model{ ID: 327, - CreatedAt: time.Now().Add(-30 * time.Second), - UpdatedAt: time.Now(), + CreatedAt: mf.clock.Now().Add(-30 * time.Second), + UpdatedAt: mf.clock.Now(), }, UUID: taskUUID, Name: "симпатичная задача", diff --git a/internal/manager/api_impl/jobs_test.go b/internal/manager/api_impl/jobs_test.go index 0507f7b5..57be017e 100644 --- a/internal/manager/api_impl/jobs_test.go +++ b/internal/manager/api_impl/jobs_test.go @@ -8,7 +8,6 @@ import ( "net/http" "os" "testing" - "time" "git.blender.org/flamenco/internal/manager/job_compilers" "git.blender.org/flamenco/internal/manager/persistence" @@ -41,7 +40,7 @@ func TestSubmitJob(t *testing.T) { JobType: submittedJob.Type, Priority: submittedJob.Priority, Status: api.JobStatusUnderConstruction, - Created: time.Now(), + Created: mf.clock.Now(), } mf.jobCompiler.EXPECT().Compile(gomock.Any(), submittedJob).Return(&authoredJob, nil) diff --git a/internal/manager/api_impl/support_test.go b/internal/manager/api_impl/support_test.go index 888bb12b..f9c0f84a 100644 --- a/internal/manager/api_impl/support_test.go +++ b/internal/manager/api_impl/support_test.go @@ -10,7 +10,9 @@ import ( "net/http" "net/http/httptest" "testing" + "time" + "github.com/benbjohnson/clock" "github.com/golang/mock/gomock" "github.com/labstack/echo/v4" "github.com/stretchr/testify/assert" @@ -30,6 +32,7 @@ type mockedFlamenco struct { config *mocks.MockConfigService stateMachine *mocks.MockTaskStateMachine shaman *mocks.MockShaman + clock *clock.Mock } func newMockedFlamenco(mockCtrl *gomock.Controller) mockedFlamenco { @@ -40,7 +43,15 @@ func newMockedFlamenco(mockCtrl *gomock.Controller) mockedFlamenco { cs := mocks.NewMockConfigService(mockCtrl) sm := mocks.NewMockTaskStateMachine(mockCtrl) sha := mocks.NewMockShaman(mockCtrl) - f := NewFlamenco(jc, ps, cb, ls, cs, sm, sha) + + clock := clock.NewMock() + mockedNow, err := time.Parse(time.RFC3339, "2022-06-09T11:14:41+02:00") + if err != nil { + panic(err) + } + clock.Set(mockedNow) + + f := NewFlamenco(jc, ps, cb, ls, cs, sm, sha, clock) return mockedFlamenco{ flamenco: f, @@ -50,6 +61,7 @@ func newMockedFlamenco(mockCtrl *gomock.Controller) mockedFlamenco { logStorage: ls, config: cs, stateMachine: sm, + clock: clock, } } diff --git a/internal/manager/api_impl/workers.go b/internal/manager/api_impl/workers.go index b94631c1..4fa6af78 100644 --- a/internal/manager/api_impl/workers.go +++ b/internal/manager/api_impl/workers.go @@ -319,7 +319,7 @@ func (f *Flamenco) ScheduleTask(e echo.Context) error { } // Add a note to the task log about the worker assignment. - err = f.logStorage.Write(logger, dbTask.Job.UUID, dbTask.UUID, + err = f.taskLogAppendTimestamped(logger, dbTask.Job.UUID, dbTask.UUID, fmt.Sprintf("Task assigned to worker %s (%s)", worker.Name, worker.UUID)) if err != nil { logger.Error().Err(err).Msg("error writing to task log") diff --git a/internal/manager/api_impl/workers_test.go b/internal/manager/api_impl/workers_test.go index f3257fd0..be034e93 100644 --- a/internal/manager/api_impl/workers_test.go +++ b/internal/manager/api_impl/workers_test.go @@ -36,7 +36,7 @@ func TestTaskScheduleHappy(t *testing.T) { mf.persistence.EXPECT().ScheduleTask(echo.Request().Context(), &worker).Return(&task, nil) mf.logStorage.EXPECT().Write(gomock.Any(), job.UUID, task.UUID, - "Task assigned to worker дрон (e7632d62-c3b8-4af0-9e78-01752928952c)") + "2022-06-09T11:14:41+02:00 Task assigned to worker дрон (e7632d62-c3b8-4af0-9e78-01752928952c)") err := mf.flamenco.ScheduleTask(echo) assert.NoError(t, err)