diff --git a/internal/xray/log_writer.go b/internal/xray/log_writer.go index edfe83052..743a600e7 100644 --- a/internal/xray/log_writer.go +++ b/internal/xray/log_writer.go @@ -12,8 +12,8 @@ import ( // Compiled once at package load: Write runs on every line Xray emits, so // recompiling these per write is wasted work. var ( - crashRegex = regexp.MustCompile(`(?i)(panic|exception|stack trace|fatal error)`) - logLineRegex = regexp.MustCompile(`^(\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}\.\d{6}) \[([^\]]+)\] (.+)$`) + crashStartRegex = regexp.MustCompile(`^(panic|fatal error): `) + logLineRegex = regexp.MustCompile(`^(\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}\.\d{6}) \[([^\]]+)\] (.+)$`) ) // NewLogWriter returns a new LogWriter for processing Xray log output. @@ -21,9 +21,12 @@ func NewLogWriter() *LogWriter { return &LogWriter{} } -// LogWriter processes and filters log output from the Xray process, handling crash detection and message filtering. +// LogWriter splits Xray's stdout/stderr into lines and forwards them to the +// panel log; once a Go panic or fatal error starts, all output is kept for one crash report. type LogWriter struct { mu sync.RWMutex + pending string + crash strings.Builder lastLine string } @@ -36,86 +39,122 @@ func (lw *LogWriter) LastLine() string { return lw.lastLine } -func (lw *LogWriter) setLastLine(line string) { - lw.mu.Lock() - lw.lastLine = line - lw.mu.Unlock() -} - -// Write processes and filters log output from the Xray process, handling crash detection and message filtering. +// Write buffers chunks into whole lines: the pipe splits output at arbitrary +// points, e.g. the Go runtime writes "panic: " on its own before the message. func (lw *LogWriter) Write(m []byte) (n int, err error) { - // Convert the data to a string - message := strings.TrimSpace(string(m)) - msgLowerAll := strings.ToLower(message) - - // Suppress noisy Windows process-kill signal that surfaces as exit status 1 - if runtime.GOOS == "windows" && strings.Contains(msgLowerAll, "exit status 1") { + lw.mu.Lock() + defer lw.mu.Unlock() + if lw.crash.Len() > 0 { + lw.crash.Write(m) return len(m), nil } - - // Check if the message contains a crash - if crashRegex.MatchString(message) { - logger.Debug("Core crash detected:\n", message) - lw.setLastLine(message) - err1 := writeCrashReport(m) - if err1 != nil { - logger.Error("Unable to write crash report:", err1) + lw.pending += string(m) + for { + i := strings.IndexByte(lw.pending, '\n') + if i < 0 { + break } - return len(m), nil - } - - messages := strings.SplitSeq(message, "\n") - - for msg := range messages { - matches := logLineRegex.FindStringSubmatch(msg) - - if len(matches) > 3 { - level := matches[2] - msgBody := matches[3] - msgBodyLower := strings.ToLower(msgBody) - - if strings.Contains(msgBodyLower, "tls handshake error") || - strings.Contains(msgBodyLower, "connection ends") { - logger.Debug("XRAY: " + msgBody) - lw.setLastLine("") - continue - } - - if strings.Contains(msgBodyLower, "failed") { - logger.Error("XRAY: " + msgBody) - } else { - switch level { - case "Debug": - logger.Debug("XRAY: " + msgBody) - case "Info": - logger.Info("XRAY: " + msgBody) - case "Warning": - logger.Warning("XRAY: " + msgBody) - case "Error": - logger.Error("XRAY: " + msgBody) - default: - logger.Debug("XRAY: " + msg) - } - } - lw.setLastLine("") - } else if msg != "" { - msgLower := strings.ToLower(msg) - - if strings.Contains(msgLower, "tls handshake error") || - strings.Contains(msgLower, "connection ends") { - logger.Debug("XRAY: " + msg) - lw.setLastLine(msg) - continue - } - - if strings.Contains(msgLower, "failed") { - logger.Error("XRAY: " + msg) - } else { - logger.Debug("XRAY: " + msg) - } - lw.setLastLine(msg) + line := lw.pending[:i] + lw.pending = lw.pending[i+1:] + if lw.startCrashLocked(line + "\n" + lw.pending) { + lw.pending = "" + break } + lw.processLineLocked(line) } - return len(m), nil } + +// Flush handles an unterminated final line and writes the crash report, if any; +// it must run after cmd.Wait, which guarantees every output chunk was delivered. +func (lw *LogWriter) Flush() { + lw.mu.Lock() + defer lw.mu.Unlock() + if rest := lw.pending; rest != "" { + lw.pending = "" + if !lw.startCrashLocked(rest) { + lw.processLineLocked(rest) + } + } + if lw.crash.Len() == 0 { + return + } + report := lw.crash.String() + lw.crash.Reset() + logger.Debug("Core crash detected:\n", report) + if err := writeCrashReport([]byte(report)); err != nil { + logger.Error("Unable to write crash report:", err) + } +} + +// startCrashLocked begins capturing a crash when output opens with a Go runtime +// crash header; the header line becomes LastLine so GetResult shows the cause. +func (lw *LogWriter) startCrashLocked(output string) bool { + if lw.crash.Len() > 0 || !crashStartRegex.MatchString(output) { + return false + } + header, _, _ := strings.Cut(output, "\n") + lw.lastLine = strings.TrimSpace(header) + lw.crash.WriteString(output) + return true +} + +func (lw *LogWriter) processLineLocked(line string) { + msg := strings.TrimSpace(line) + if msg == "" { + return + } + msgLower := strings.ToLower(msg) + + // Suppress noisy Windows process-kill signal that surfaces as exit status 1 + if runtime.GOOS == "windows" && strings.Contains(msgLower, "exit status 1") { + return + } + + matches := logLineRegex.FindStringSubmatch(msg) + if len(matches) > 3 { + level := matches[2] + msgBody := matches[3] + msgBodyLower := strings.ToLower(msgBody) + + if strings.Contains(msgBodyLower, "tls handshake error") || + strings.Contains(msgBodyLower, "connection ends") { + logger.Debug("XRAY: " + msgBody) + lw.lastLine = "" + return + } + + if strings.Contains(msgBodyLower, "failed") { + logger.Error("XRAY: " + msgBody) + } else { + switch level { + case "Debug": + logger.Debug("XRAY: " + msgBody) + case "Info": + logger.Info("XRAY: " + msgBody) + case "Warning": + logger.Warning("XRAY: " + msgBody) + case "Error": + logger.Error("XRAY: " + msgBody) + default: + logger.Debug("XRAY: " + msg) + } + } + lw.lastLine = "" + return + } + + if strings.Contains(msgLower, "tls handshake error") || + strings.Contains(msgLower, "connection ends") { + logger.Debug("XRAY: " + msg) + lw.lastLine = msg + return + } + + if strings.Contains(msgLower, "failed") { + logger.Error("XRAY: " + msg) + } else { + logger.Debug("XRAY: " + msg) + } + lw.lastLine = msg +} diff --git a/internal/xray/log_writer_race_test.go b/internal/xray/log_writer_race_test.go index 444d7c6b1..cc1054330 100644 --- a/internal/xray/log_writer_race_test.go +++ b/internal/xray/log_writer_race_test.go @@ -1,6 +1,10 @@ package xray import ( + "os" + "path/filepath" + "slices" + "strings" "sync" "testing" ) @@ -20,7 +24,7 @@ func TestLogWriterLastLineConcurrent(t *testing.T) { go func() { defer wg.Done() for range iterations { - _, _ = lw.Write([]byte("2024/01/01 00:00:00.000000 [Info] connection accepted")) + _, _ = lw.Write([]byte("2024/01/01 00:00:00.000000 [Info] connection accepted\n")) } }() } @@ -34,3 +38,76 @@ func TestLogWriterLastLineConcurrent(t *testing.T) { } wg.Wait() } + +func crashReportsIn(t *testing.T, dir string) []string { + t.Helper() + entries, err := os.ReadDir(dir) + if err != nil { + t.Fatal(err) + } + var contents []string + for _, e := range entries { + if strings.HasPrefix(e.Name(), crashReportPrefix) { + b, err := os.ReadFile(filepath.Join(dir, e.Name())) + if err != nil { + t.Fatal(err) + } + contents = append(contents, string(b)) + } + } + return contents +} + +// The Go runtime prints "panic: " with its own write(2), so the pipe hands it +// over as a chunk of its own; the report must still hold the whole traceback. +func TestLogWriterCrashReportHoldsWholePanic(t *testing.T) { + dir := t.TempDir() + t.Setenv("XUI_LOG_FOLDER", dir) + chunks := []string{ + "panic: ", + "runtime error: index out of range [3] with length 1\n", + "\ngoroutine 1 [running]:\nmain.main()\n\t/src/main.go:5 +0x1d\n", + "exit status 2", + } + lw := NewLogWriter() + for _, c := range chunks { + _, _ = lw.Write([]byte(c)) + } + lw.Flush() + + got := crashReportsIn(t, dir) + want := strings.Join(chunks, "") + if len(got) != 1 || got[0] != want { + t.Fatalf("crash reports = %q, want exactly [%q]", got, want) + } + if line := lw.LastLine(); line != "panic: runtime error: index out of range [3] with length 1" { + t.Fatalf("LastLine = %q", line) + } +} + +func TestLogWriterOrdinaryLineMentioningPanicIsNotACrash(t *testing.T) { + dir := t.TempDir() + t.Setenv("XUI_LOG_FOLDER", dir) + lw := NewLogWriter() + _, _ = lw.Write([]byte("2026/07/12 15:16:00.000000 [Info] [42] proxy/vless: sniffed domain panic.example.com\n")) + lw.Flush() + + if got := crashReportsIn(t, dir); len(got) != 0 { + t.Fatalf("ordinary log line produced crash reports %q", got) + } +} + +func TestWriteCrashReportKeepsReportsFromTheSameSecond(t *testing.T) { + dir := t.TempDir() + t.Setenv("XUI_LOG_FOLDER", dir) + for _, m := range []string{"panic: first", "panic: second"} { + if err := writeCrashReport([]byte(m)); err != nil { + t.Fatal(err) + } + } + got := crashReportsIn(t, dir) + slices.Sort(got) + if !slices.Equal(got, []string{"panic: first", "panic: second"}) { + t.Fatalf("crash reports = %q, want both", got) + } +} diff --git a/internal/xray/mutation_audit_test.go b/internal/xray/mutation_audit_test.go index 734798c3a..f497afee0 100644 --- a/internal/xray/mutation_audit_test.go +++ b/internal/xray/mutation_audit_test.go @@ -5,6 +5,7 @@ import ( "os/exec" "path/filepath" "slices" + "strings" "testing" "time" @@ -280,6 +281,33 @@ func TestWaitForCommand_CrashExitRecordsError(t *testing.T) { } } +// A real child panic reaches the LogWriter in several pipe chunks; the crash +// report is only whole if waitForCommand flushes the writer after cmd.Wait. +func TestWaitForCommand_PanicWritesWholeCrashReport(t *testing.T) { + dir := t.TempDir() + t.Setenv("XUI_LOG_FOLDER", dir) + cmd := exec.Command(os.Args[0], "-test.run=TestMutationAuditHelper", "--", "panic") + cmd.Env = append(os.Environ(), "XRAY_MUT_HELPER=1") + + p := newProcess(nil) + cmd.Stdout = p.logWriter + cmd.Stderr = p.logWriter + if err := p.startCommand(cmd); err != nil { + t.Fatalf("startCommand: %v", err) + } + if err := p.waitForExit(5 * time.Second); err != nil { + t.Fatalf("child did not exit: %v", err) + } + + reports := crashReportsIn(t, dir) + if len(reports) != 1 || !strings.HasPrefix(reports[0], "panic: xray helper panic\n\ngoroutine ") { + t.Fatalf("crash reports = %q, want one holding the whole panic traceback", reports) + } + if got := p.GetResult(); got != "panic: xray helper panic" { + t.Fatalf("GetResult = %q, want the panic header", got) + } +} + // TestStop_RemovesTempConfigFile pins process.go:579 — the // `if p.configPath != ""` guard that removes the per-run temp config file on // Stop (so test runs never disturb the main config.json). A mutated guard @@ -337,5 +365,8 @@ func TestMutationAuditHelper(t *testing.T) { os.Exit(2) case "block": select {} + case "panic": + go func() { panic("xray helper panic") }() + select {} } } diff --git a/internal/xray/process.go b/internal/xray/process.go index a7f0691e3..9821d486d 100644 --- a/internal/xray/process.go +++ b/internal/xray/process.go @@ -734,6 +734,7 @@ func (p *process) waitForCommand(cmd *exec.Cmd, done chan struct{}) { defer close(done) err := cmd.Wait() + p.logWriter.Flush() if err == nil || p.intentionalStop.Load() { return } @@ -830,17 +831,27 @@ const ( maxCrashReports = 10 ) -// writeCrashReport persists a captured xray crash chunk to the log folder -// with nanosecond-precision filename so restart-loop bursts don't overwrite -// each other, and prunes old reports to keep the folder bounded. +// writeCrashReport persists a captured xray crash to the log folder; CreateTemp's +// random suffix keeps restart-loop bursts within one second from overwriting each other. func writeCrashReport(m []byte) error { dir := config.GetLogFolder() if err := os.MkdirAll(dir, 0o770); err != nil { return err } pruneOldCrashReports(dir, maxCrashReports-1) - name := crashReportPrefix + time.Now().Format("20060102_150405_000000000") + crashReportSuffix - return os.WriteFile(filepath.Join(dir, name), m, 0o640) + pattern := crashReportPrefix + time.Now().Format("20060102_150405") + "_*" + crashReportSuffix + f, err := os.CreateTemp(dir, pattern) + if err != nil { + return err + } + _, err = f.Write(m) + if cerr := f.Close(); err == nil { + err = cerr + } + if err == nil { + err = os.Chmod(f.Name(), 0o640) + } + return err } func pruneOldCrashReports(dir string, keep int) {