package task_logs // SPDX-License-Identifier: GPL-3.0-or-later import ( "errors" "fmt" "io/fs" "io/ioutil" "os" "path/filepath" "strings" "sync" "testing" "time" "github.com/benbjohnson/clock" "github.com/golang/mock/gomock" "github.com/rs/zerolog" "github.com/rs/zerolog/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "projects.blender.org/studio/flamenco/internal/manager/task_logs/mocks" ) func TestLogWriting(t *testing.T) { s, finish, mocks := taskLogsTestFixtures(t) defer finish() jobUUID := "25c5a51c-e0dd-44f7-9f87-74f3d1fbbd8c" taskUUID := "20ff9d06-53ec-4019-9e2e-1774f05f170a" jobDir := filepath.Join(mocks.temppath, "job-25c5", jobUUID) // Expect broadcastst for each call to s.Write() numWriteCalls := 2 mocks.broadcaster.EXPECT().BroadcastTaskLogUpdate(gomock.Any()).Times(numWriteCalls) mocks.localStorage.EXPECT().ForJob(jobUUID).Times(numWriteCalls).Return(jobDir) err := s.Write(zerolog.Nop(), jobUUID, taskUUID, "Ovo je priča") require.NoError(t, err) err = s.Write(zerolog.Nop(), jobUUID, taskUUID, "Ima dvije linije") require.NoError(t, err) filename := filepath.Join(jobDir, "task-20ff9d06-53ec-4019-9e2e-1774f05f170a.txt") contents, err := ioutil.ReadFile(filename) require.NoError(t, err, "the log file should exist") assert.Equal(t, "Ovo je priča\nIma dvije linije\n", string(contents)) } func TestLogRotation(t *testing.T) { s, finish, mocks := taskLogsTestFixtures(t) defer finish() jobUUID := "25c5a51c-e0dd-44f7-9f87-74f3d1fbbd8c" taskUUID := "20ff9d06-53ec-4019-9e2e-1774f05f170a" jobDir := filepath.Join(mocks.temppath, "job-25c5", jobUUID) mocks.broadcaster.EXPECT().BroadcastTaskLogUpdate(gomock.Any()) mocks.localStorage.EXPECT().ForJob(jobUUID).Return(jobDir).AnyTimes() err := s.Write(zerolog.Nop(), jobUUID, taskUUID, "Ovo je priča") require.NoError(t, err) s.RotateFile(zerolog.Nop(), jobUUID, taskUUID) filename := filepath.Join(jobDir, "task-20ff9d06-53ec-4019-9e2e-1774f05f170a.txt") rotatedFilename := filename + ".1" contents, err := ioutil.ReadFile(rotatedFilename) require.NoError(t, err, "the rotated log file should exist") assert.Equal(t, "Ovo je priča\n", string(contents)) _, err = os.Stat(filename) assert.True(t, errors.Is(err, fs.ErrNotExist)) } func TestLogTailAndSize(t *testing.T) { s, finish, mocks := taskLogsTestFixtures(t) defer finish() jobID := "25c5a51c-e0dd-44f7-9f87-74f3d1fbbd8c" taskID := "20ff9d06-53ec-4019-9e2e-1774f05f170a" jobDir := filepath.Join(mocks.temppath, "job-25c5", jobID) // Expect broadcastst for each call to s.Write() mocks.broadcaster.EXPECT().BroadcastTaskLogUpdate(gomock.Any()).Times(3) mocks.localStorage.EXPECT().ForJob(jobID).Return(jobDir).AnyTimes() // Check tail & size of non-existent log file. contents, err := s.Tail(jobID, taskID) assert.ErrorIs(t, err, os.ErrNotExist) assert.Equal(t, "", contents) size, err := s.TaskLogSize(jobID, taskID) assert.ErrorIs(t, err, fs.ErrNotExist) assert.Equal(t, int64(0), size) // Test a single line. err = s.Write(zerolog.Nop(), jobID, taskID, "Just a single line") require.NoError(t, err) contents, err = s.Tail(jobID, taskID) require.NoError(t, err) assert.Equal(t, "Just a single line\n", string(contents)) // A short file shouldn't do any line stripping. err = s.Write(zerolog.Nop(), jobID, taskID, "And another line!") require.NoError(t, err) contents, err = s.Tail(jobID, taskID) require.NoError(t, err) assert.Equal(t, "Just a single line\nAnd another line!\n", string(contents)) bigString := "" for lineNum := 1; lineNum < 1000; lineNum++ { bigString += fmt.Sprintf("This is line #%d\n", lineNum) } err = s.Write(zerolog.Nop(), jobID, taskID, bigString) require.NoError(t, err) // Check the log size, it should be the entire bigString plus what was written before that. size, err = s.TaskLogSize(jobID, taskID) require.NoError(t, err) expect := int64(len("Just a single line\nAnd another line!\n" + bigString)) assert.Equal(t, expect, size) // Check the tail, it should only be the few last lines of bigString. contents, err = s.Tail(jobID, taskID) require.NoError(t, err) assert.Equal(t, "This is line #887\nThis is line #888\nThis is line #889\nThis is line #890\nThis is line #891\n"+ "This is line #892\nThis is line #893\nThis is line #894\nThis is line #895\nThis is line #896\n"+ "This is line #897\nThis is line #898\nThis is line #899\nThis is line #900\nThis is line #901\n"+ "This is line #902\nThis is line #903\nThis is line #904\nThis is line #905\nThis is line #906\n"+ "This is line #907\nThis is line #908\nThis is line #909\nThis is line #910\nThis is line #911\n"+ "This is line #912\nThis is line #913\nThis is line #914\nThis is line #915\nThis is line #916\n"+ "This is line #917\nThis is line #918\nThis is line #919\nThis is line #920\nThis is line #921\n"+ "This is line #922\nThis is line #923\nThis is line #924\nThis is line #925\nThis is line #926\n"+ "This is line #927\nThis is line #928\nThis is line #929\nThis is line #930\nThis is line #931\n"+ "This is line #932\nThis is line #933\nThis is line #934\nThis is line #935\nThis is line #936\n"+ "This is line #937\nThis is line #938\nThis is line #939\nThis is line #940\nThis is line #941\n"+ "This is line #942\nThis is line #943\nThis is line #944\nThis is line #945\nThis is line #946\n"+ "This is line #947\nThis is line #948\nThis is line #949\nThis is line #950\nThis is line #951\n"+ "This is line #952\nThis is line #953\nThis is line #954\nThis is line #955\nThis is line #956\n"+ "This is line #957\nThis is line #958\nThis is line #959\nThis is line #960\nThis is line #961\n"+ "This is line #962\nThis is line #963\nThis is line #964\nThis is line #965\nThis is line #966\n"+ "This is line #967\nThis is line #968\nThis is line #969\nThis is line #970\nThis is line #971\n"+ "This is line #972\nThis is line #973\nThis is line #974\nThis is line #975\nThis is line #976\n"+ "This is line #977\nThis is line #978\nThis is line #979\nThis is line #980\nThis is line #981\n"+ "This is line #982\nThis is line #983\nThis is line #984\nThis is line #985\nThis is line #986\n"+ "This is line #987\nThis is line #988\nThis is line #989\nThis is line #990\nThis is line #991\n"+ "This is line #992\nThis is line #993\nThis is line #994\nThis is line #995\nThis is line #996\n"+ "This is line #997\nThis is line #998\nThis is line #999\n", string(contents), ) } func TestLogWritingParallel(t *testing.T) { s, finish, mocks := taskLogsTestFixtures(t) defer finish() numGoroutines := 1000 // How many goroutines run in parallel. runLength := 100 // How many characters are logged, per goroutine. wg := sync.WaitGroup{} wg.Add(numGoroutines) jobID := "6d9a05a1-261e-4f6f-93b0-8c4f6b6d500d" taskID := "d19888cc-c389-4a24-aebf-8458ababdb02" jobDir := filepath.Join(mocks.temppath, "job-25c5", jobID) mocks.broadcaster.EXPECT().BroadcastTaskLogUpdate(gomock.Any()).Times(numGoroutines) mocks.localStorage.EXPECT().ForJob(jobID).Return(jobDir).AnyTimes() for i := 0; i < numGoroutines; i++ { // Write lines of 100 characters to the task log. Each goroutine writes a // different character, starting at 'A'. go func(i int32) { defer wg.Done() logger := log.With().Int32("goroutine", i).Logger() letter := rune(int32('A') + (i % 26)) if len(string(letter)) > 1 { panic("this test assumes only single-byte runes are used") } logText := strings.Repeat(string(letter), runLength) require.NoError(t, s.Write(logger, jobID, taskID, logText)) }(int32(i)) } wg.Wait() // Test that the final log contains 1000 lines of of 100 characters, without // any run getting interrupted by another one. contents, err := os.ReadFile(s.Filepath(jobID, taskID)) require.NoError(t, err) lines := strings.Split(string(contents), "\n") assert.Equal(t, numGoroutines+1, len(lines), "each goroutine should have written a single line, and the file should have a newline at the end") for lineIndex, line := range lines { if lineIndex == numGoroutines { assert.Empty(t, line, "the last line should be empty") } else { assert.Lenf(t, line, runLength, "each line should be %d runes long; line #%d is not", line, lineIndex) } } } type TaskLogsMocks struct { temppath string localStorage *mocks.MockLocalStorage clock *clock.Mock broadcaster *mocks.MockChangeBroadcaster } func taskLogsTestFixtures(t *testing.T) (*Storage, func(), *TaskLogsMocks) { mockCtrl := gomock.NewController(t) temppath, err := ioutil.TempDir("", "testlogs") require.NoError(t, err) mocks := &TaskLogsMocks{ temppath: temppath, localStorage: mocks.NewMockLocalStorage(mockCtrl), clock: clock.NewMock(), broadcaster: mocks.NewMockChangeBroadcaster(mockCtrl), } mockedNow, err := time.Parse(time.RFC3339, "2022-06-09T16:52:04+02:00") require.NoError(t, err) mocks.clock.Set(mockedNow) // This should be called at the end of each unit test. finish := func() { os.RemoveAll(temppath) mockCtrl.Finish() } sm := NewStorage(mocks.localStorage, mocks.clock, mocks.broadcaster) return sm, finish, mocks }