From 1c113d66f308e055c76a80a4ba61b48ac6bc16d1 Mon Sep 17 00:00:00 2001 From: Simon Bauer Date: Thu, 9 Jan 2025 17:18:24 +0100 Subject: [PATCH] Let our logging Handlers only delegate to other Handlers to be able to use Text or JSON output arbitrarily --- cmd/eval-dev-quality/cmd/command.go | 3 +- cmd/eval-dev-quality/cmd/evaluate_test.go | 2 +- cmd/eval-dev-quality/cmd/version.go | 4 +- evaluate/task/repository_test.go | 2 +- evaluate/task/test-integration/task_test.go | 4 +- evaluate/task/transpile_test.go | 2 +- evaluate/task/write-test_test.go | 10 +- log/logger.go | 284 +++++++++++--------- log/logger_test.go | 279 +++++++++---------- util/exec.go | 4 +- 10 files changed, 297 insertions(+), 297 deletions(-) diff --git a/cmd/eval-dev-quality/cmd/command.go b/cmd/eval-dev-quality/cmd/command.go index ac6f5d80..4d1eeb7a 100644 --- a/cmd/eval-dev-quality/cmd/command.go +++ b/cmd/eval-dev-quality/cmd/command.go @@ -49,10 +49,9 @@ func Execute(logger *log.Logger, arguments []string) { logger.Panicf("Could not parse arguments: %+v", err) } if parser.Active == nil { - logger.SetFlags(log.FlagMessageOnly) var sb strings.Builder parser.WriteHelp(&sb) - logger.Info(sb.String()) + logger.PrintfWithoutMeta(sb.String()) } } diff --git a/cmd/eval-dev-quality/cmd/evaluate_test.go b/cmd/eval-dev-quality/cmd/evaluate_test.go index abdd7155..48b45c34 100644 --- a/cmd/eval-dev-quality/cmd/evaluate_test.go +++ b/cmd/eval-dev-quality/cmd/evaluate_test.go @@ -462,7 +462,7 @@ func TestEvaluateExecute(t *testing.T) { ExpectedResultFiles: map[string]func(t *testing.T, filePath string, data string){ filepath.Join("result-directory", "evaluation.log"): func(t *testing.T, filePath string, data string) { - assert.Contains(t, data, "Skipping unavailable provider \"openrouter\"") + assert.Contains(t, data, "Skipping unavailable provider \\\"openrouter\\\"") }, }, ExpectedPanicContains: "ERROR: model openrouter/auto does not exist", diff --git a/cmd/eval-dev-quality/cmd/version.go b/cmd/eval-dev-quality/cmd/version.go index 089179f8..486b09c8 100644 --- a/cmd/eval-dev-quality/cmd/version.go +++ b/cmd/eval-dev-quality/cmd/version.go @@ -24,8 +24,8 @@ func (command *Version) Execute(args []string) (err error) { if revision == "" { revision = "development" } - command.logger.SetFlags(log.FlagMessageOnly) // Remove the timestamp and everything from the log output while still being able to test it. - command.logger.Printf("eval-dev-quality version %s - revision %s", evaluate.Version, revision) + + command.logger.PrintfWithoutMeta("eval-dev-quality version %s - revision %s\n", evaluate.Version, revision) return nil } diff --git a/evaluate/task/repository_test.go b/evaluate/task/repository_test.go index f092c261..201d5c93 100644 --- a/evaluate/task/repository_test.go +++ b/evaluate/task/repository_test.go @@ -204,7 +204,7 @@ func TestRepositoryLoadConfiguration(t *testing.T) { TestDataPath: filepath.Join("..", "..", "testdata"), RepositoryPath: filepath.Join("golang", "plain"), - ExpectedErrorText: "task identifier \"unknown-task\" unknown", + ExpectedErrorText: "task identifier \\\"unknown-task\\\" unknown", MutationBefore: func(t *testing.T, repositoryPath string) { configuration := bytesutil.StringTrimIndentations(` { diff --git a/evaluate/task/test-integration/task_test.go b/evaluate/task/test-integration/task_test.go index fe370df1..3b76630b 100644 --- a/evaluate/task/test-integration/task_test.go +++ b/evaluate/task/test-integration/task_test.go @@ -85,10 +85,10 @@ func TestWriteTestsRun(t *testing.T) { }, }, ValidateLog: func(t *testing.T, data string) { - assert.Contains(t, data, "Evaluating model \"symflower/symbolic-execution\"") + assert.Contains(t, data, "Evaluating model \\\"symflower/symbolic-execution\\\"") assert.Contains(t, data, "Generated 1 test") assert.Contains(t, data, "PASS: TestSymflowerPlain") - assert.Contains(t, data, "Evaluated model \"symflower/symbolic-execution\"") + assert.Contains(t, data, "Evaluated model \\\"symflower/symbolic-execution\\\"") }, }) } diff --git a/evaluate/task/transpile_test.go b/evaluate/task/transpile_test.go index 89519132..860f6d95 100644 --- a/evaluate/task/transpile_test.go +++ b/evaluate/task/transpile_test.go @@ -662,7 +662,7 @@ func TestValidateTranspileRepository(t *testing.T) { Language: &golang.Language{}, ExpectedError: func(t *testing.T, err error) { - assert.ErrorContains(t, err, "the language extension \".unsupported\" is not supported") + assert.ErrorContains(t, err, "the language extension \\\".unsupported\\\" is not supported") }, }) t.Run("Go", func(t *testing.T) { diff --git a/evaluate/task/write-test_test.go b/evaluate/task/write-test_test.go index 203944ce..ecb96a14 100644 --- a/evaluate/task/write-test_test.go +++ b/evaluate/task/write-test_test.go @@ -53,7 +53,7 @@ func TestWriteTestsRun(t *testing.T) { // Generate invalid code for caseA (with and without template). modelMock.RegisterGenerateSuccess(t, "caseA_test.go", "does not compile", metricstesting.AssessmentsWithProcessingTime).Twice() // Generate valid code for caseB (with and without template). - modelMock.RegisterGenerateSuccess(t, "caseB_test.go", "package plain\n\nimport \"testing\"\n\nfunc TestCaseB(t *testing.T){}", metricstesting.AssessmentsWithProcessingTime).Twice() + modelMock.RegisterGenerateSuccess(t, "caseB_test.go", "package plain\n\nimport \\\"testing\\\"\n\nfunc TestCaseB(t *testing.T){}", metricstesting.AssessmentsWithProcessingTime).Twice() validate(t, &tasktesting.TestCaseTask{ Name: "Plain", @@ -93,7 +93,7 @@ func TestWriteTestsRun(t *testing.T) { "exit status 1", // Symflower fix not applicable (overwrote template). }, ValidateLog: func(t *testing.T, data string) { - assert.Equal(t, 1, strings.Count(data, "Evaluating model \"mocked-model\"")) + assert.Equal(t, 1, strings.Count(data, "Evaluating model \\\"mocked-model\\\"")) assert.Equal(t, 4, strings.Count(data, "PASS: TestCaseB")) // Bare model result, with fix, with template, with template and fix. }, }) @@ -120,7 +120,7 @@ func TestWriteTestsRun(t *testing.T) { ExpectedRepositoryAssessment: expectedAssessments, ExpectedProblemContains: expectedProblems, ValidateLog: func(t *testing.T, data string) { - assert.Contains(t, data, "Evaluating model \"mocked-model\"") + assert.Contains(t, data, "Evaluating model \\\"mocked-model\\\"") if assertTestsPass { assert.Contains(t, data, "PASS: TestPlain") } @@ -295,7 +295,7 @@ func TestWriteTestsRun(t *testing.T) { }, ExpectedProblemContains: nil, ValidateLog: func(t *testing.T, data string) { - assert.Contains(t, data, "Evaluating model \"mocked-model\"") + assert.Contains(t, data, "Evaluating model \\\"mocked-model\\\"") }, }) } @@ -390,7 +390,7 @@ func TestWriteTestsRun(t *testing.T) { IdentifierWriteTestsSymflowerTemplateSymflowerFix: metrics.Assessments{}, }, ValidateLog: func(t *testing.T, data string) { - assert.Contains(t, data, "Ignoring file \"plain.go\" (as configured by the repository)") + assert.Contains(t, data, "Ignoring file \\\"plain.go\\\" (as configured by the repository)") }, }) } diff --git a/log/logger.go b/log/logger.go index 481220bb..29291338 100644 --- a/log/logger.go +++ b/log/logger.go @@ -42,20 +42,6 @@ func Attribute(key AttributeKey, value any) (attribute slog.Attr) { return slog.Any(string(key), value) } -// Flags defines how log messages should be printed. -type Flags int - -const ( - // FlagMessageOnly defines to log only the message. - FlagMessageOnly = 0 - // FlagDate defines to log the date. - FlagDate = 1 << iota - // FlagTime defines to log the time. - FlagTime - // FlagStandard defines to log with the standard format. - FlagStandard = FlagDate | FlagTime -) - var ( // openLogFiles holds the files that were opened by some logger. openLogFiles []*os.File @@ -83,27 +69,30 @@ func CloseOpenLogFiles() { openLogFiles = nil } +// openLogFile opens the given file and creates it if necessary. +func openLogFile(filePath string) (file *os.File, err error) { + if err := os.MkdirAll(filepath.Dir(filePath), 0755); err != nil { + return nil, pkgerrors.WithStack(err) + } + + file, err = os.OpenFile(filePath, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0644) + if err != nil { + return nil, pkgerrors.WithStack(err) + } + + addOpenLogFile(file) + + return file, nil +} + // Logger holds a logger to log to. type Logger struct { *slog.Logger } -// newLoggerWithWriter instantiate a logger with a writer. -func newLoggerWithWriter(writer io.Writer, flags Flags) *Logger { - handler := newSpawningHandler(writer, flags) - handler.logFileSpawners = defaultLogFileSpawners - +func newLoggerWithHandler(handler slog.Handler) *Logger { return &Logger{ - Logger: slog.New(handler), - } -} - -// SetFlags sets the flags defining how log messages should be printed. -func (l *Logger) SetFlags(flags Flags) { - if spawningHandler, ok := l.Handler().(*spawningHandler); ok { - spawningHandler.flags = flags - } else { - l.Error("Could not set flags of handler") + Logger: slog.New(newSpawningHandler(handler, defaultLogFileSpawners)), } } @@ -114,6 +103,13 @@ func (l *Logger) With(key AttributeKey, value any) *Logger { } } +// PrintfWithoutMeta prints a message without any timestamp, log level or origin program counter. +func (l *Logger) PrintfWithoutMeta(message string, args ...any) { + // If time, level and PC use default values any Handler should ignore these fields (https://pkg.go.dev/log/slog#Handler). + record := slog.NewRecord(time.Time{}, slog.LevelInfo, fmt.Sprintf(message, args...), 0) + _ = l.Logger.Handler().Handle(context.Background(), record) +} + // Print logs the given message at the "info" level. func (l *Logger) Print(message string) { l.Logger.Info(message) @@ -156,7 +152,7 @@ func (l *Logger) Fatal(v ...any) { // Buffer returns a logger that writes to a buffer. func Buffer() (buffer *bytesutil.SynchronizedBuffer, logger *Logger) { buffer = new(bytesutil.SynchronizedBuffer) - logger = newLoggerWithWriter(buffer, FlagStandard) + logger = newLoggerWithHandler(newPlainTextHandler(buffer)) return buffer, logger } @@ -177,77 +173,47 @@ func File(path string) (logger *Logger, loggerClose func(), err error) { } } - logger = newLoggerWithWriter(file, FlagStandard) + logger = newLoggerWithHandler(slog.NewJSONHandler(file, nil)) return logger, loggerClose, nil } // STDOUT returns a logger that writes to STDOUT. func STDOUT() (logger *Logger) { - return newLoggerWithWriter(os.Stdout, FlagStandard) + return newLoggerWithHandler(newPlainTextHandler(os.Stdout)) } -// newLogWriter returns a logger that writes to a file. -func newLogWriter(parent io.Writer, filePath string) (writer io.Writer, err error) { - file, err := openLogFile(filePath) - if err != nil { - return nil, err - } - addOpenLogFile(file) - - return file, nil -} - -// openLogFile opens the given file and creates it if necessary. -func openLogFile(filePath string) (file *os.File, err error) { - if err := os.MkdirAll(filepath.Dir(filePath), 0755); err != nil { - return nil, pkgerrors.WithStack(err) - } - - file, err = os.OpenFile(filePath, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0644) - if err != nil { - return nil, pkgerrors.WithStack(err) - } - - return file, nil -} - -// spawningHandler is a structural logging handler which spawns a new log file if one of the given log file spawners triggers. +// spawningHandler is a structural logging handler which spawns a new handler on "WithAttrs" if one of the given spawners triggers. type spawningHandler struct { - // writer holds the writer to write the output. - writer io.Writer + // handler holds the handler to forward the records to. + handler slog.Handler - // attributes holds the attributes handed to the logger. + // attributes holds the attributes already handed to the logger. attributes map[AttributeKey]string // logFileSpawners holds the spawners responsible for spawning a new log file. - logFileSpawners []logFileSpawner - - // flags holds the flags deciding which fields are logged. - flags Flags + logFileSpawners []handlerSpawner } // newSpawningHandler returns a new spawning handler. -func newSpawningHandler(writer io.Writer, flags Flags) *spawningHandler { +func newSpawningHandler(handler slog.Handler, spawners []handlerSpawner) *spawningHandler { return &spawningHandler{ - writer: writer, + handler: handler, attributes: map[AttributeKey]string{}, - flags: flags, + logFileSpawners: spawners, } } // Clone returns a copy of the object. func (h *spawningHandler) Clone() (clone *spawningHandler) { return &spawningHandler{ - writer: h.writer, + handler: h.handler, attributes: maps.Clone(h.attributes), logFileSpawners: slices.Clone(h.logFileSpawners), - - flags: h.flags, } } @@ -260,94 +226,88 @@ func (h *spawningHandler) Enabled(ctx context.Context, level slog.Level) bool { // Handle handles the Record. func (h *spawningHandler) Handle(ctx context.Context, record slog.Record) (err error) { - writer := h.writer - attributes := maps.Clone(h.attributes) + // The record might contain temporary attributes so merge them with the static attributes of the handler. + temporaryAttributes := maps.Clone(h.attributes) record.Attrs(func(attribute slog.Attr) bool { - attributes[AttributeKey(attribute.Key)] = attribute.Value.String() + temporaryAttributes[AttributeKey(attribute.Key)] = attribute.Value.String() return true }) - for _, spawner := range artifactLogFileSpawners { - if !spawner.NeedsSpawn(attributes) { - continue - } - logFilePath := spawner.FilePath(attributes) - writer, err = newLogWriter(writer, logFilePath) - if err != nil { - return err - } - } - - if h.flags&FlagDate != 0 { - _, _ = fmt.Fprint(writer, record.Time.Format("2006/01/02")) - _, _ = fmt.Fprint(writer, " ") - } - if h.flags&FlagTime != 0 { - _, _ = fmt.Fprint(writer, record.Time.Format("15:04:05")) - _, _ = fmt.Fprint(writer, " ") + if newHandler := h.spawnIfNecessary(temporaryAttributes); newHandler != nil { + return newHandler.Handle(ctx, record) } - _, _ = fmt.Fprintln(writer, record.Message) - - return nil + return h.handler.Handle(ctx, record) } // WithAttrs returns a new Handler whose attributes consist of both the receiver's attributes and the arguments. // The Handler owns the slice: it may retain, modify or discard it. func (h *spawningHandler) WithAttrs(attributes []slog.Attr) slog.Handler { - // Collect attributes. + // Collect new attributes and merge them with the already existing attributes of the handler. + combinedAttributes := maps.Clone(h.attributes) for _, attribute := range attributes { - h.attributes[AttributeKey(attribute.Key)] = attribute.Value.String() + combinedAttributes[AttributeKey(attribute.Key)] = attribute.Value.String() + } + + if newHandler := h.spawnIfNecessary(combinedAttributes); newHandler != nil { + return newHandler } + // We cannot modify the handler itself but must return a new instance. newHandler := h.Clone() + newHandler.attributes = combinedAttributes - // Check if we need to spawn a new log file. + return newHandler +} + +// spawnIfNecessary checks if the given attributes trigger the creation of a new handler and returns it with the given attributes set. +func (h *spawningHandler) spawnIfNecessary(attributes map[AttributeKey]string) slog.Handler { for i, spawner := range h.logFileSpawners { - if !spawner.NeedsSpawn(h.attributes) { + if !spawner.NeedsSpawn(attributes) { continue } - logFilePath := spawner.FilePath(h.attributes) - writer, err := newLogWriter(h.writer, logFilePath) + child, err := spawner.Spawn(attributes) if err != nil { - _, _ = fmt.Fprintf(h.writer, "ERROR: cannot create new handler: %s\n", err.Error()) - - continue - } - - logMessage := fmt.Sprintf("Spawning new log file at %s", logFilePath) - if err := h.Handle(context.Background(), slog.NewRecord(time.Now(), slog.LevelInfo, logMessage, 0)); err != nil { - _, _ = fmt.Fprintf(h.writer, "ERROR: cannot spawn new log file: %s\n", err.Error()) + logToHandler(h.handler, slog.LevelError, "ERROR: cannot create new handler: %s", err) continue } - newHandler.writer = writer - newHandler.logFileSpawners = slices.Delete(newHandler.logFileSpawners, i, i+1) // The currently triggered log file spawner must not be part of the new handler as it would trigger again and again. + newHandler := h.Clone() + newHandler.handler = child + newHandler.attributes = attributes + newHandler.logFileSpawners = slices.Delete(newHandler.logFileSpawners, i, i+1) // The currently triggered spawner must not be part of the new handler as it would trigger again and again. return newHandler } - return newHandler + return nil } // WithGroup returns a new Handler with the given group appended to the receiver's existing groups. -func (h *spawningHandler) WithGroup(string) slog.Handler { +func (h *spawningHandler) WithGroup(group string) slog.Handler { + logToHandler(h.handler, slog.LevelWarn, "Groups are unsupported %q", group) + return h } -var defaultLogFileSpawners = []logFileSpawner{ - logFileSpawner{ +var defaultLogFileSpawners = []handlerSpawner{ + handlerSpawner{ NeededAttributes: []AttributeKey{ AttributeKeyResultPath, }, - FilePath: func(attributes map[AttributeKey]string) string { - return filepath.Join(attributes[AttributeKeyResultPath], "evaluation.log") + Spawn: func(attributes map[AttributeKey]string) (slog.Handler, error) { + file, err := openLogFile(filepath.Join(attributes[AttributeKeyResultPath], "evaluation.log")) + if err != nil { + return nil, err + } + + return slog.NewJSONHandler(file, nil), nil }, }, - logFileSpawner{ + handlerSpawner{ NeededAttributes: []AttributeKey{ AttributeKeyResultPath, @@ -356,20 +316,22 @@ var defaultLogFileSpawners = []logFileSpawner{ AttributeKeyRepository, AttributeKeyTask, }, - FilePath: func(attributes map[AttributeKey]string) string { + Spawn: func(attributes map[AttributeKey]string) (slog.Handler, error) { resultPath := attributes[AttributeKeyResultPath] modelID := attributes[AttributeKeyModel] languageID := attributes[AttributeKeyLanguage] repositoryName := attributes[AttributeKeyRepository] taskIdentifier := attributes[AttributeKeyTask] - return filepath.Join(resultPath, taskIdentifier, CleanModelNameForFileSystem(modelID), languageID, repositoryName, "evaluation.log") + file, err := openLogFile(filepath.Join(resultPath, taskIdentifier, CleanModelNameForFileSystem(modelID), languageID, repositoryName, "evaluation.log")) + if err != nil { + return nil, err + } + + return slog.NewJSONHandler(file, nil), nil }, }, -} - -var artifactLogFileSpawners = []logFileSpawner{ - logFileSpawner{ + handlerSpawner{ NeededAttributes: []AttributeKey{ AttributeKeyResultPath, @@ -380,7 +342,7 @@ var artifactLogFileSpawners = []logFileSpawner{ AttributeKeyRun, AttributeKeyTask, }, - FilePath: func(attributes map[AttributeKey]string) string { + Spawn: func(attributes map[AttributeKey]string) (slog.Handler, error) { resultPath := attributes[AttributeKeyResultPath] modelID := attributes[AttributeKeyModel] languageID := attributes[AttributeKeyLanguage] @@ -389,21 +351,26 @@ var artifactLogFileSpawners = []logFileSpawner{ run := attributes[AttributeKeyRun] artifact := attributes[AttributeKeyArtifact] - return filepath.Join(resultPath, taskIdentifier, CleanModelNameForFileSystem(modelID), languageID, repositoryName, fmt.Sprintf("%s-%s.log", artifact, run)) + file, err := openLogFile(filepath.Join(resultPath, taskIdentifier, CleanModelNameForFileSystem(modelID), languageID, repositoryName, fmt.Sprintf("%s-%s.log", artifact, run))) + if err != nil { + return nil, err + } + + return slog.NewJSONHandler(file, nil), nil }, }, } -// logFileSpawner defines when a new log file is spawned. -type logFileSpawner struct { - // NeededAttributes holds the list of attributes that need to be set in order to spawn a new log file. +// handlerSpawner defines when a new handler is spawned. +type handlerSpawner struct { + // NeededAttributes holds the list of attributes that need to be set in order to spawn a new handler. NeededAttributes []AttributeKey - // FilePath is called if all needed attributes are set and returns the file path for the new log file. - FilePath func(attributes map[AttributeKey]string) string + // Spawn is called if all needed attributes are set and returns the new handler. + Spawn func(attributes map[AttributeKey]string) (slog.Handler, error) } // NeedsSpawn returns if a new log file has to be spawned. -func (s logFileSpawner) NeedsSpawn(attributes map[AttributeKey]string) bool { +func (s handlerSpawner) NeedsSpawn(attributes map[AttributeKey]string) bool { for _, attributeKey := range s.NeededAttributes { if value := attributes[attributeKey]; value == "" { return false @@ -413,6 +380,59 @@ func (s logFileSpawner) NeedsSpawn(attributes map[AttributeKey]string) bool { return true } +// plainTextHandler wraps a normal TextHandler with the ability to print plain text if no timestamp, log level and program counter are provided. +type plainTextHandler struct { + handler slog.Handler + writer io.Writer +} + +func newPlainTextHandler(writer io.Writer) slog.Handler { + return &plainTextHandler{ + handler: slog.NewTextHandler(writer, nil), + writer: writer, + } +} + +// Enabled implements slog.Handler. +func (p *plainTextHandler) Enabled(context.Context, slog.Level) bool { + return true +} + +// Handle implements slog.Handler. +func (p *plainTextHandler) Handle(ctx context.Context, record slog.Record) error { + // The default "TextHandler" would still print `msg=...` but we just print the message as a whole. + if record.Time.IsZero() && record.Level == slog.LevelInfo && record.PC == 0 { + _, err := p.writer.Write([]byte(record.Message)) + + return err + } + + return p.handler.Handle(ctx, record) +} + +// WithAttrs implements slog.Handler. +func (p *plainTextHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &plainTextHandler{ + handler: p.handler.WithAttrs(attrs), + writer: p.writer, + } +} + +// WithGroup implements slog.Handler. +func (p *plainTextHandler) WithGroup(name string) slog.Handler { + return &plainTextHandler{ + handler: p.handler.WithGroup(name), + writer: p.writer, + } +} + +var _ slog.Handler = (*plainTextHandler)(nil) + +// logToHandler logs directly to a handler to communicate logging-internal events. +func logToHandler(handler slog.Handler, level slog.Level, message string, args ...any) { + _ = handler.Handle(context.Background(), slog.NewRecord(time.Now(), level, fmt.Sprintf(message, args...), 0)) +} + var cleanModelNameForFileSystemReplacer = strings.NewReplacer( "/", "_", "\\", "_", diff --git a/log/logger_test.go b/log/logger_test.go index 4987d14e..1c1f6eda 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -4,7 +4,6 @@ import ( "os" "path/filepath" "sort" - "strings" "testing" "github.com/stretchr/testify/assert" @@ -13,21 +12,14 @@ import ( "github.com/zimmski/osutil/bytesutil" ) -func TestLoggerWith(t *testing.T) { +func TestLogger(t *testing.T) { type testCase struct { Name string Do func(logger *Logger, temporaryPath string) - ExpectedLogOutput string - ExpectedFiles map[string]string - } - - cleanOutput := func(data string, temporaryPath string) (newData string) { - newData = strings.ReplaceAll(data, temporaryPath, "$TEMPORARY_PATH") - newData = strings.ReplaceAll(newData, "\\", "/") - - return newData + ExpectedLogOutputContains string + ExpectedFilesContain map[string][]string } validate := func(t *testing.T, tc *testCase) { @@ -36,8 +28,12 @@ func TestLoggerWith(t *testing.T) { CloseOpenLogFiles() }() - logOutput := new(bytesutil.SynchronizedBuffer) - logger := newLoggerWithWriter(logOutput, FlagMessageOnly) + logOutput, logger := Buffer() + defer func() { + if t.Failed() { + t.Log(logOutput.String()) + } + }() temporaryPath := t.TempDir() @@ -51,171 +47,158 @@ func TestLoggerWith(t *testing.T) { } sort.Strings(actualResultFiles) var expectedResultFiles []string - for filePath, expectedData := range tc.ExpectedFiles { + for filePath, expectedData := range tc.ExpectedFilesContain { expectedResultFiles = append(expectedResultFiles, filePath) data, err := os.ReadFile(filepath.Join(temporaryPath, filePath)) require.NoError(t, err) actualData := string(data) - actualData = cleanOutput(actualData, temporaryPath) - expectedData = bytesutil.StringTrimIndentations(expectedData) - assert.Equal(t, expectedData, actualData) + for _, containsContent := range expectedData { + assert.Contains(t, actualData, containsContent) + } } sort.Strings(expectedResultFiles) assert.Equal(t, expectedResultFiles, actualResultFiles) - expectedLogOutput := bytesutil.StringTrimIndentations(tc.ExpectedLogOutput) - assert.Equal(t, expectedLogOutput, cleanOutput(logOutput.String(), temporaryPath)) + expectedLogOutput := bytesutil.StringTrimIndentations(tc.ExpectedLogOutputContains) + assert.Contains(t, logOutput.String(), expectedLogOutput) }) } - validate(t, &testCase{ - Name: "New log file for Result path", + t.Run("JSON", func(t *testing.T) { + validate(t, &testCase{ + Name: "New log file for Result path", - Do: func(logger *Logger, temporaryPath string) { - logger = logger.With(AttributeKeyResultPath, temporaryPath) + Do: func(logger *Logger, temporaryPath string) { + logger = logger.With(AttributeKeyResultPath, temporaryPath) - logger.Info("Every log file") - }, + logger.Info("log-file-content") + }, - ExpectedLogOutput: ` - Spawning new log file at $TEMPORARY_PATH/evaluation.log - `, - ExpectedFiles: map[string]string{ - "evaluation.log": ` - Every log file - `, - }, - }) - validate(t, &testCase{ - Name: "New log file for Language-Model-Repository-Task", - - Do: func(logger *Logger, temporaryPath string) { - logger = logger.With(AttributeKeyResultPath, temporaryPath) - logger = logger.With(AttributeKeyLanguage, "languageA") - logger = logger.With(AttributeKeyModel, "modelA") - logger = logger.With(AttributeKeyRepository, "repositoryA") - logger = logger.With(AttributeKeyTask, "taskA") - - logger.Info("Every log file") - }, - - ExpectedLogOutput: ` - Spawning new log file at $TEMPORARY_PATH/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Every log file - `, - ExpectedFiles: map[string]string{ - "evaluation.log": ` - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Every log file - `, - filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): ` - Every log file - `, - }, - }) + ExpectedFilesContain: map[string][]string{ + "evaluation.log": []string{ + "log-file-content", + }, + }, + }) + validate(t, &testCase{ + Name: "New log file for Language-Model-Repository-Task", - validate(t, &testCase{ - Name: "New log file for two tasks", - - Do: func(logger *Logger, temporaryPath string) { - logger = logger.With(AttributeKeyResultPath, temporaryPath) - logger = logger.With(AttributeKeyLanguage, "languageA") - logger = logger.With(AttributeKeyModel, "modelA") - logger = logger.With(AttributeKeyRepository, "repositoryA") - - loggerA := logger.With(AttributeKeyTask, "taskA") - _ = logger.With(AttributeKeyTask, "taskB") - - loggerA.Info("Only in A log files") - }, - - ExpectedLogOutput: ` - Spawning new log file at $TEMPORARY_PATH/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskB/modelA/languageA/repositoryA/evaluation.log - Only in A log files - `, - ExpectedFiles: map[string]string{ - "evaluation.log": ` - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskB/modelA/languageA/repositoryA/evaluation.log - Only in A log files - `, - filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): ` - Only in A log files - `, - filepath.Join("taskB", "modelA", "languageA", "repositoryA", "evaluation.log"): "", - }, - }) - validate(t, &testCase{ - Name: "New log file for two repositories", - - Do: func(logger *Logger, temporaryPath string) { - logger = logger.With(AttributeKeyResultPath, temporaryPath) - logger = logger.With(AttributeKeyLanguage, "languageA") - logger = logger.With(AttributeKeyModel, "modelA") - - loggerA := logger.With(AttributeKeyRepository, "repositoryA") - _ = loggerA.With(AttributeKeyTask, "taskA") - - loggerB := logger.With(AttributeKeyRepository, "repositoryB") - _ = loggerB.With(AttributeKeyTask, "taskA") - }, - - ExpectedLogOutput: ` - Spawning new log file at $TEMPORARY_PATH/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryB/evaluation.log - `, - ExpectedFiles: map[string]string{ - "evaluation.log": ` - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryB/evaluation.log - `, - filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): "", - filepath.Join("taskA", "modelA", "languageA", "repositoryB", "evaluation.log"): "", - }, - }) + Do: func(logger *Logger, temporaryPath string) { + logger = logger.With(AttributeKeyResultPath, temporaryPath) + logger = logger.With(AttributeKeyLanguage, "languageA") + logger = logger.With(AttributeKeyModel, "modelA") + logger = logger.With(AttributeKeyRepository, "repositoryA") + logger = logger.With(AttributeKeyTask, "taskA") + + logger.Info("log-file-content") + }, + + ExpectedFilesContain: map[string][]string{ + "evaluation.log": nil, + filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): []string{ + "log-file-content", + }, + }, + }) - t.Run("Artifacts", func(t *testing.T) { validate(t, &testCase{ - Name: "Response", + Name: "New log file for two tasks", Do: func(logger *Logger, temporaryPath string) { logger = logger.With(AttributeKeyResultPath, temporaryPath) logger = logger.With(AttributeKeyLanguage, "languageA") logger = logger.With(AttributeKeyModel, "modelA") logger = logger.With(AttributeKeyRepository, "repositoryA") - logger = logger.With(AttributeKeyTask, "taskA") - logger = logger.With(AttributeKeyRun, "1") - logger.PrintWith("Artifact content", Attribute(AttributeKeyArtifact, "response")) - logger.Print("No artifact content") + loggerA := logger.With(AttributeKeyTask, "taskA") + _ = logger.With(AttributeKeyTask, "taskB") + + loggerA.Info("log-file-content-A") + }, + + ExpectedFilesContain: map[string][]string{ + "evaluation.log": nil, + filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): []string{ + "log-file-content-A", + }, + filepath.Join("taskB", "modelA", "languageA", "repositoryA", "evaluation.log"): nil, + }, + }) + validate(t, &testCase{ + Name: "New log file for two repositories", + + Do: func(logger *Logger, temporaryPath string) { + logger = logger.With(AttributeKeyResultPath, temporaryPath) + logger = logger.With(AttributeKeyLanguage, "languageA") + logger = logger.With(AttributeKeyModel, "modelA") + + loggerA := logger.With(AttributeKeyRepository, "repositoryA") + _ = loggerA.With(AttributeKeyTask, "taskA") + + loggerB := logger.With(AttributeKeyRepository, "repositoryB") + _ = loggerB.With(AttributeKeyTask, "taskA") }, - ExpectedLogOutput: ` - Spawning new log file at $TEMPORARY_PATH/evaluation.log - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Artifact content - No artifact content + ExpectedFilesContain: map[string][]string{ + "evaluation.log": nil, + filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): nil, + filepath.Join("taskA", "modelA", "languageA", "repositoryB", "evaluation.log"): nil, + }, + }) + + t.Run("Artifacts", func(t *testing.T) { + validate(t, &testCase{ + Name: "Response", + + Do: func(logger *Logger, temporaryPath string) { + logger = logger.With(AttributeKeyResultPath, temporaryPath) + logger = logger.With(AttributeKeyLanguage, "languageA") + logger = logger.With(AttributeKeyModel, "modelA") + logger = logger.With(AttributeKeyRepository, "repositoryA") + logger = logger.With(AttributeKeyTask, "taskA") + logger = logger.With(AttributeKeyRun, "1") + + logger.PrintWith("artifact-content", Attribute(AttributeKeyArtifact, "response")) + logger.Print("no-artifact-content") + }, + + ExpectedFilesContain: map[string][]string{ + "evaluation.log": nil, + filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): []string{ + "no-artifact-content", + }, + filepath.Join("taskA", "modelA", "languageA", "repositoryA", "response-1.log"): []string{ + "artifact-content", + }, + }, + }) + }) + }) + + t.Run("Text", func(t *testing.T) { + validate(t, &testCase{ + Name: "Normal log", + + Do: func(logger *Logger, temporaryPath string) { + logger.Info("log-message") + }, + + ExpectedLogOutputContains: ` + level=INFO msg=log-message `, - ExpectedFiles: map[string]string{ - "evaluation.log": ` - Spawning new log file at $TEMPORARY_PATH/taskA/modelA/languageA/repositoryA/evaluation.log - Artifact content - No artifact content - `, - filepath.Join("taskA", "modelA", "languageA", "repositoryA", "evaluation.log"): ` - Artifact content - No artifact content - `, - filepath.Join("taskA", "modelA", "languageA", "repositoryA", "response-1.log"): ` - Artifact content - `, + }) + validate(t, &testCase{ + Name: "Without meta info", + + Do: func(logger *Logger, temporaryPath string) { + logger.PrintfWithoutMeta("log-message\n") }, + + ExpectedLogOutputContains: ` + log-message + `, }) }) } diff --git a/util/exec.go b/util/exec.go index 6025f4f3..1465c9fe 100644 --- a/util/exec.go +++ b/util/exec.go @@ -31,11 +31,9 @@ type Command struct { // CommandWithResult executes a command and returns its output, while printing the same output to the given logger. func CommandWithResult(ctx context.Context, logger *log.Logger, command *Command) (output string, err error) { - logger.Printf("$ %s", strings.Join(command.Command, " ")) - var writer bytesutil.SynchronizedBuffer defer func() { - logger.Info(writer.String()) + logger.Info("command execution", "command", strings.Join(command.Command, " "), "output", writer.String()) }() c := exec.CommandContext(ctx, command.Command[0], command.Command[1:]...)