package services import ( "bytes" "errors" "fmt" "log" "strings" "sync" "testing" "time" "pvfine/internal/buildmode" ) func TestDebugTimingLogsUseDebugLevel(t *testing.T) { before := applicationLogs.snapshot() lastID := uint64(0) if len(before) > 0 { lastID = before[len(before)-1].ID } finish := debugPhase("test-phase", "file=42") debugLockAcquired("test-phase", time.Now()) finish() var entries []appLogEntry for _, entry := range applicationLogs.snapshot() { if entry.ID > lastID { entries = append(entries, entry) } } if !buildmode.Development { if len(entries) != 0 { t.Fatalf("production emitted performance logs: %#v", entries) } return } if len(entries) != 3 { t.Fatalf("expected start, lock wait and finish logs, got %d", len(entries)) } for _, entry := range entries { if entry.Level != "DEBUG" || entry.Source != "performance" { t.Fatalf("unexpected entry: %#v", entry) } } for i, expected := range []string{"started file=42", "core-lock acquired wait=", "finished file=42 elapsed="} { if !strings.Contains(entries[i].Message, expected) { t.Fatalf("entry %d: %s", i, entries[i].Message) } } } func TestLogBufferBoundedAndSnapshotIndependent(t *testing.T) { var buffer logBuffer for i := 0; i < logCapacity+10; i++ { buffer.append("INFO", "test", fmt.Sprint(i)) } snapshot := buffer.snapshot() if len(snapshot) != logCapacity || snapshot[0].ID != 11 || snapshot[len(snapshot)-1].ID != logCapacity+10 { t.Fatalf("unexpected snapshot bounds: %d, %d, %d", len(snapshot), snapshot[0].ID, snapshot[len(snapshot)-1].ID) } snapshot[0].Message = "changed" if buffer.snapshot()[0].Message == "changed" { t.Fatal("snapshot aliases the buffer") } } func TestLogBufferConcurrent(t *testing.T) { var buffer logBuffer var workers sync.WaitGroup for i := 0; i < 8; i++ { workers.Go(func() { for j := 0; j < 100; j++ { buffer.append("INFO", "test", "entry") buffer.snapshot() } }) } workers.Wait() snapshot := buffer.snapshot() if len(snapshot) != 800 { t.Fatalf("entries = %d", len(snapshot)) } for i, entry := range snapshot { if entry.ID != uint64(i+1) { t.Fatalf("non-sequential ID at %d: %d", i, entry.ID) } } } func TestClassifyLogLevel(t *testing.T) { for _, test := range []struct{ message, level string }{ {"[ERR] broken", "ERROR"}, {"level=ERROR msg=broken", "ERROR"}, {"index failed: error=broken", "ERROR"}, {"打开失败", "ERROR"}, {"prepare finished elapsed=2ms error=", "INFO"}, {"level=WARN msg=warning", "WARN"}, {"cache publication unavailable", "WARN"}, {"level=DEBUG msg=trace", "DEBUG"}, {"index finished elapsed=100ms", "INFO"}, {"index finished skipped=0", "INFO"}, } { if got := classifyLogLevel(test.message); got != test.level { t.Errorf("%q: got %s, want %s", test.message, got, test.level) } } } func TestServiceErrorsAreLoggedWithoutChangingSerialization(t *testing.T) { var output bytes.Buffer original := log.Writer() log.SetOutput(CaptureLogs(&output)) t.Cleanup(func() { log.SetOutput(original) }) if result := LogServiceError(errors.New("service failure")); result != nil { t.Fatal("must use the default Wails serialization") } if !strings.Contains(output.String(), "[ERR] service failure") { t.Fatalf("missing error output: %s", output.String()) } snapshot := applicationLogs.snapshot() last := snapshot[len(snapshot)-1] if last.Level != "ERROR" || !strings.Contains(last.Message, "service failure") { t.Fatalf("error entry = %#v", last) } if result := LogServiceError(nil); result != nil { t.Fatal("nil errors must also use default serialization") } } func TestCaptureLogsPreservesOutput(t *testing.T) { var output bytes.Buffer writer := CaptureLogs(&output) line := "[ERR] 日志错误\n" n, err := writer.Write([]byte(line)) if err != nil || n != len(line) || output.String() != line { t.Fatalf("write = %d, %v, %q", n, err, output.String()) } } func TestDescribeArchiveAndIndexLogs(t *testing.T) { level, message, _, _ := describeLogEvent("archive:opened", ArchiveInfo{ Path: "test.pvf", FileCount: 20, Format: "paged110", Paged110: true, }) if level != "INFO" || !strings.Contains(message, "test.pvf") || !strings.Contains(message, "文件=20") || !strings.Contains(message, "变体=paged110") { t.Fatalf("archive log = %s, %s", level, message) } first := IndexStatus{State: "building", Stage: "strings", Done: 1, Total: 100} _, _, key, signature := describeLogEvent("archive:index-progress", first) first.Done++ _, _, nextKey, nextSignature := describeLogEvent("archive:index-progress", first) if key != nextKey || signature != nextSignature { t.Fatal("per-file progress must not produce a new stage signature") } first.State, first.Stage, first.BuildDurationMs, first.OpenDurationMs = "ready", "ready-cache", 42, 12 _, message, _, nextSignature = describeLogEvent("archive:index-ready", first) if signature == nextSignature || !strings.Contains(message, "42.00 ms") || !strings.Contains(message, "12.00 ms") { t.Fatalf("ready log missing timing: %s", message) } first.RefreshError = "refresh failed" level, message, _, _ = describeLogEvent("archive:index-ready", first) if level != "ERROR" || !strings.Contains(message, "refresh failed") { t.Fatalf("refresh error = %s, %s", level, message) } } func TestDescribeOtherEvents(t *testing.T) { for _, name := range []string{"archive:closed", "archive:file-index-ready", "archive:script-applied", "version:committed"} { if _, message, _, _ := describeLogEvent(name, nil); message == "" { t.Errorf("%s has no log", name) } } level, message, _, _ := describeLogEvent("script:log", map[string]any{"level": "warn", "message": "脚本警告"}) if level != "WARN" || message != "脚本警告" { t.Fatalf("script log = %s, %s", level, message) } level, message, _, _ = describeLogEvent("image:index-error", ImageIndexStatus{State: "error", Error: "broken", BuildDurationMs: 10}) if level != "ERROR" || !strings.Contains(message, "broken") || !strings.Contains(message, "10.00 ms") { t.Fatalf("image log = %s, %s", level, message) } } func TestLogForwardingWaitsForEventInitialization(t *testing.T) { var buffer logBuffer buffer.record("INFO", "Go", "Build Info:") var forwarded []appLogEntry buffer.setEmitter(func(entry appLogEntry) { // Reading history here must not deadlock with the recording lock. _ = buffer.snapshot() forwarded = append(forwarded, entry) }) buffer.record("ERROR", "Go", "service failure") if len(forwarded) != 1 || forwarded[0].Message != "service failure" { t.Fatalf("live logs = %#v", forwarded) } history := buffer.snapshot() if !buildmode.Development { if len(history) != 1 || history[0] != forwarded[0] { t.Fatalf("production history = %#v", history) } return } if len(history) != 2 || history[0].Message != "Build Info:" || history[1] != forwarded[0] { t.Fatalf("startup history = %#v", history) } } func TestLogForwardingConcurrentInitialization(t *testing.T) { var buffer logBuffer var workers sync.WaitGroup workers.Go(func() { for range 100 { buffer.setEmitter(func(appLogEntry) {}) } }) workers.Go(func() { for range 100 { buffer.record("INFO", "application", "startup") } }) workers.Wait() if got := len(buffer.snapshot()); got != 100 { t.Fatalf("history entries = %d, want 100", got) } } type logFormattingProbe struct{ formatted bool } func (p *logFormattingProbe) String() string { p.formatted = true return "formatting-probe" } func TestDevelopmentLogsRespectBuildModeBeforeFormatting(t *testing.T) { var output bytes.Buffer original := log.Writer() log.SetOutput(CaptureLogs(&output)) t.Cleanup(func() { log.SetOutput(original) }) probe := &logFormattingProbe{} developmentLog("[DEBUG] %s", probe) debugLog("%s", probe) developmentOrErrorLog(nil, "success %s", probe) if probe.formatted != buildmode.Development { t.Fatalf("formatted=%t development=%t", probe.formatted, buildmode.Development) } if !buildmode.Development && output.Len() != 0 { t.Fatalf("production wrote development logs: %s", output.String()) } developmentOrErrorLog(errors.New("failed"), "operation error=%v", errors.New("failed")) if !strings.Contains(output.String(), "operation error=failed") { t.Fatal("operation errors must remain visible") } } func TestCaptureLogsProductionPolicyPreservesErrorsAndContext(t *testing.T) { var output bytes.Buffer writer := CaptureLogs(&output) for _, message := range []string{ "[DEBUG] runtime details\n", "runtime startup\n", "level=WARN runtime warning\n", "[ERR] runtime error\n exception context\n", } { if n, err := writer.Write([]byte(message)); err != nil || n != len(message) { t.Fatalf("write = %d, %v", n, err) } } text := output.String() if strings.Contains(text, "runtime details") != buildmode.Development || strings.Contains(text, "runtime startup") != buildmode.Development { t.Fatalf("runtime output policy mismatch: %s", text) } if !strings.Contains(text, "runtime warning") || !strings.Contains(text, "runtime error\n exception context") { t.Fatalf("warning/error context lost: %s", text) } var buffer logBuffer buffer.record("DEBUG", "performance", "trace") buffer.record("INFO", "Go", "runtime startup") buffer.record("INFO", "archive:opened", "opened") buffer.record("WARN", "Go", "warning") buffer.record("ERROR", "Go", "error") want := 3 if buildmode.Development { want = 5 } if entries := buffer.snapshot(); len(entries) != want { t.Fatalf("retained %d entries, want %d", len(entries), want) } }