From fb9e8ab419b5d71e39853a4752ae8e767b899fb4 Mon Sep 17 00:00:00 2001 From: Robin Olsen Date: Mon, 2 Mar 2026 23:08:40 +0100 Subject: [PATCH] define metrics logger --- pkg/task/metrics.go | 502 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 502 insertions(+) create mode 100644 pkg/task/metrics.go diff --git a/pkg/task/metrics.go b/pkg/task/metrics.go new file mode 100644 index 0000000..87f4a36 --- /dev/null +++ b/pkg/task/metrics.go @@ -0,0 +1,502 @@ +package task + +import ( + "encoding/json" + "fmt" + "log/slog" + "os" + "path/filepath" + "regexp" + "sort" + "strings" + "sync" + "time" + + "github.com/LazyBachelor/LazyPM/internal/models" +) + +type taskRunCollector struct { + mu sync.Mutex + run models.TaskRunMetrics + logger *slog.Logger +} + +var nonWord = regexp.MustCompile(`[^a-z0-9]+`) + +func newTaskRunCollector(taskName string, interfaceType InterfaceType, logger *slog.Logger) *taskRunCollector { + return &taskRunCollector{ + run: models.TaskRunMetrics{ + TaskName: taskName, + InterfaceType: interfaceType, + StartedAt: time.Now(), + Logs: make([]models.TaskLogEntry, 0, 8), + }, + logger: logger, + } +} + +func (c *taskRunCollector) log(level string, message string) { + action := normalizeAction(message) + result := "" + switch level { + case "error": + result = "failed" + case "warn": + result = "warning" + default: + result = "ok" + } + + c.mu.Lock() + defer c.mu.Unlock() + + c.run.Logs = append(c.run.Logs, models.TaskLogEntry{ + Timestamp: time.Now(), + Level: level, + Message: message, + Source: "system", + Action: action, + Result: result, + }) + + attrs := []any{"action", action, "result", result, "task", c.run.TaskName, "interface", c.run.InterfaceType} + c.logWithLogger(level, message, attrs...) +} + +func (c *taskRunCollector) recordUserAction(raw string) { + source, actionText, target, result := normalizeUserAction(raw) + + c.mu.Lock() + defer c.mu.Unlock() + + c.run.Logs = append(c.run.Logs, models.TaskLogEntry{ + Timestamp: time.Now(), + Level: "user_action", + Message: raw, + Source: source, + Action: normalizeAction(actionText), + Target: target, + Result: result, + }) + + c.logWithLogger("info", "user action recorded", + "task", c.run.TaskName, + "interface", c.run.InterfaceType, + "source", source, + "action", normalizeAction(actionText), + "target", target, + "result", result, + ) +} + +func (c *taskRunCollector) setCompleted(completed bool) { + c.mu.Lock() + defer c.mu.Unlock() + + c.run.Completed = completed +} + +func (c *taskRunCollector) setError(err error) { + if err == nil { + return + } + + c.mu.Lock() + defer c.mu.Unlock() + + c.run.Error = err.Error() +} + +func (c *taskRunCollector) recordQuestionnaire(completed bool, userQuit bool, answers map[string]any) { + c.mu.Lock() + defer c.mu.Unlock() + + c.run.QuestionnaireCompleted = completed + c.run.QuestionnaireUserQuit = userQuit + if len(answers) > 0 { + c.run.QuestionnaireAnswers = answers + } + + result := "completed" + if userQuit { + result = "user_quit" + } else if !completed { + result = "incomplete" + } + + c.run.Logs = append(c.run.Logs, models.TaskLogEntry{ + Timestamp: time.Now(), + Level: "questionnaire", + Message: "questionnaire finished", + Source: "system", + Action: "questionnaire_finish", + Result: result, + }) + + if len(answers) > 0 { + keys := make([]string, 0, len(answers)) + for key := range answers { + keys = append(keys, key) + } + sort.Strings(keys) + + for _, key := range keys { + value := answers[key] + if value == nil { + continue + } + + valueText := fmt.Sprintf("%v", value) + c.run.Logs = append(c.run.Logs, models.TaskLogEntry{ + Timestamp: time.Now(), + Level: "questionnaire", + Message: fmt.Sprintf("questionnaire answer: %s=%s", key, valueText), + Source: "system", + Action: "questionnaire_answer", + Target: key, + Result: valueText, + }) + } + } + + c.logWithLogger("info", "questionnaire recorded", + "task", c.run.TaskName, + "completed", completed, + "user_quit", userQuit, + "answers_count", len(answers), + ) +} + +func (c *taskRunCollector) recordValidation(feedback ValidationFeedback) { + c.mu.Lock() + defer c.mu.Unlock() + + c.run.ValidationAttempts++ + attempt := c.run.ValidationAttempts + if feedback.Success { + c.run.ValidationSuccesses++ + } else { + c.run.ValidationFailures++ + } + + c.run.Logs = append(c.run.Logs, models.TaskLogEntry{ + Timestamp: time.Now(), + Level: "validation", + Message: fmt.Sprintf("validation attempt %d success=%t", attempt, feedback.Success), + Source: "system", + Action: "validate_attempt", + Result: validationResult(feedback.Success), + Attempt: attempt, + }) + c.logWithLogger("info", "validation attempt", + "task", c.run.TaskName, + "interface", c.run.InterfaceType, + "attempt", attempt, + "result", validationResult(feedback.Success), + ) + + for _, check := range feedback.Checks { + if check.Valid { + c.run.ValidationChecksPassed++ + c.run.Logs = append(c.run.Logs, models.TaskLogEntry{ + Timestamp: time.Now(), + Level: "validation", + Message: fmt.Sprintf("validation check passed: %s", check.Message), + Source: "system", + Action: "validate_check", + Target: check.Message, + Result: "passed", + Attempt: attempt, + }) + c.logWithLogger("info", "validation check", + "task", c.run.TaskName, + "attempt", attempt, + "result", "passed", + "target", check.Message, + ) + continue + } + c.run.ValidationChecksFailed++ + c.run.Logs = append(c.run.Logs, models.TaskLogEntry{ + Timestamp: time.Now(), + Level: "validation", + Message: fmt.Sprintf("validation check failed: %s", check.Message), + Source: "system", + Action: "validate_check", + Target: check.Message, + Result: "failed", + Attempt: attempt, + }) + c.logWithLogger("warn", "validation check", + "task", c.run.TaskName, + "attempt", attempt, + "result", "failed", + "target", check.Message, + ) + } + + c.run.LastValidationMessage = feedback.Message +} + +func validationResult(success bool) string { + if success { + return "passed" + } + return "failed" +} + +func normalizeUserAction(raw string) (source string, actionText string, target string, result string) { + trimmed := strings.TrimSpace(raw) + if trimmed == "" { + return "unknown", "unknown_action", "", "unknown" + } + + if event, ok := models.DecodeActionEvent(trimmed); ok { + source = strings.TrimSpace(event.Source) + if source == "" { + source = "unknown" + } + actionText = strings.TrimSpace(event.Action) + if actionText == "" { + actionText = "unknown_action" + } + actionText = stripSourcePrefix(actionText, source) + target = strings.TrimSpace(event.Target) + result = strings.TrimSpace(event.Result) + if result == "" { + result = inferActionResult(actionText) + } + return source, actionText, target, result + } + + result = "ok" + lower := strings.ToLower(trimmed) + + if strings.HasPrefix(lower, "web request:") { + rest := strings.TrimSpace(trimmed[len("web request:"):]) + parts := strings.Fields(rest) + if len(parts) >= 2 { + return "web", "request", strings.ToUpper(parts[0]) + " " + parts[1], "ok" + } + return "web", "request", rest, "ok" + } + + if strings.HasPrefix(lower, "repl command:") { + command := strings.TrimSpace(trimmed[len("repl command:"):]) + return "repl", "run_command", command, "ok" + } + + words := strings.Fields(trimmed) + if len(words) > 1 { + head := strings.ToLower(words[0]) + if head == "tui" || head == "web" || head == "repl" { + source = head + actionText = strings.Join(words[1:], " ") + } else { + source = "unknown" + actionText = trimmed + } + } else { + source = "unknown" + actionText = trimmed + } + + result = inferActionResult(actionText) + + return source, actionText, "", result +} + +func stripSourcePrefix(actionText string, source string) string { + actionText = strings.TrimSpace(actionText) + if actionText == "" || source == "" { + return actionText + } + + lowerSource := strings.ToLower(source) + lowerAction := strings.ToLower(actionText) + + if strings.HasPrefix(lowerAction, lowerSource+" ") { + return strings.TrimSpace(actionText[len(source):]) + } + if strings.HasPrefix(lowerAction, lowerSource+"_") { + return strings.TrimSpace(actionText[len(source)+1:]) + } + + return actionText +} + +func inferActionResult(actionText string) string { + lower := strings.ToLower(actionText) + if strings.Contains(lower, "failed") { + return "failed" + } + if strings.Contains(lower, "canceled") { + return "canceled" + } + if strings.Contains(lower, "started") { + return "started" + } + if strings.Contains(lower, "submitted") { + return "submitted" + } + if strings.Contains(lower, "requested") { + return "requested" + } + return "ok" +} + +func normalizeAction(input string) string { + lower := strings.ToLower(strings.TrimSpace(input)) + if lower == "" { + return "unknown_action" + } + clean := nonWord.ReplaceAllString(lower, "_") + clean = strings.Trim(clean, "_") + if clean == "" { + return "unknown_action" + } + return clean +} + +func (c *taskRunCollector) finalize() models.TaskRunMetrics { + c.mu.Lock() + defer c.mu.Unlock() + + if c.run.EndedAt.IsZero() { + c.run.EndedAt = time.Now() + } + c.run.DurationMs = c.run.EndedAt.Sub(c.run.StartedAt).Milliseconds() + + finalLogs := make([]models.TaskLogEntry, len(c.run.Logs)) + copy(finalLogs, c.run.Logs) + + final := c.run + final.Logs = finalLogs + + return final +} + +func appendTaskMetrics(path string, taskName string, run models.TaskRunMetrics, logger *slog.Logger) error { + if path == "" { + return nil + } + + dir := filepath.Dir(path) + if dir != "." { + if err := os.MkdirAll(dir, 0o755); err != nil { + return fmt.Errorf("failed to create metrics directory: %w", err) + } + } + + metrics := models.TaskMetricsFile{ + TaskName: taskName, + Runs: []models.TaskRunMetrics{}, + } + + if bytes, err := os.ReadFile(path); err == nil { + if len(bytes) > 0 { + if err := json.Unmarshal(bytes, &metrics); err != nil { + return fmt.Errorf("failed to parse metrics file %q: %w", path, err) + } + } + } else if !os.IsNotExist(err) { + return fmt.Errorf("failed to read metrics file %q: %w", path, err) + } + + if metrics.TaskName == "" { + metrics.TaskName = taskName + } + + run.RunID = len(metrics.Runs) + 1 + metrics.Runs = append(metrics.Runs, run) + metrics.Summary = buildTaskStatsSummary(metrics.Runs) + metrics.UpdatedAt = time.Now() + + data, err := json.MarshalIndent(metrics, "", " ") + if err != nil { + return fmt.Errorf("failed to encode task metrics: %w", err) + } + + if err := os.WriteFile(path, data, 0o644); err != nil { + return fmt.Errorf("failed to write metrics file %q: %w", path, err) + } + + if logger != nil { + logger.Info("task metrics persisted", + "path", path, + "task", taskName, + "run_id", run.RunID, + "total_runs", metrics.Summary.TotalRuns, + "completed_runs", metrics.Summary.CompletedRuns, + ) + } + + return nil +} + +func (c *taskRunCollector) logWithLogger(level string, message string, attrs ...any) { + if c.logger == nil { + return + } + + switch level { + case "error": + c.logger.Error(message, attrs...) + case "warn": + c.logger.Warn(message, attrs...) + default: + c.logger.Info(message, attrs...) + } +} + +func buildTaskStatsSummary(runs []models.TaskRunMetrics) models.TaskStatsSummary { + summary := models.TaskStatsSummary{} + if len(runs) == 0 { + return summary + } + + summary.TotalRuns = len(runs) + summary.FirstRunStartedAt = runs[0].StartedAt + + for _, run := range runs { + summary.TotalDurationMs += run.DurationMs + summary.ValidationAttempts += run.ValidationAttempts + summary.ValidationSuccesses += run.ValidationSuccesses + summary.ValidationFailures += run.ValidationFailures + summary.ValidationChecksPassed += run.ValidationChecksPassed + summary.ValidationChecksFailed += run.ValidationChecksFailed + + if run.Completed { + summary.CompletedRuns++ + } else { + summary.IncompleteRuns++ + } + + if run.QuestionnaireCompleted { + summary.QuestionnairesCompleted++ + } + if run.QuestionnaireUserQuit { + summary.QuestionnairesAbandoned++ + } + + if run.StartedAt.Before(summary.FirstRunStartedAt) { + summary.FirstRunStartedAt = run.StartedAt + } + if run.StartedAt.After(summary.LastRunStartedAt) { + summary.LastRunStartedAt = run.StartedAt + } + if run.EndedAt.After(summary.LastRunEndedAt) { + summary.LastRunEndedAt = run.EndedAt + summary.LastInterfaceType = run.InterfaceType + } + + for _, log := range run.Logs { + if log.Level == "user_action" { + summary.TotalUserActions++ + } + } + } + + summary.AverageDurationMs = summary.TotalDurationMs / int64(summary.TotalRuns) + return summary +}