Browse Source

fix(xray): capture whole core crash reports instead of the first pipe chunk

LogWriter inspected each pipe chunk on its own. The Go runtime writes
"panic: " with a separate write before the message and traceback, so the
crash report was written from that first chunk alone and the panel left
7-byte core_crash_*.log files holding only "panic: ". Any ordinary log
line mentioning panic/exception/stack trace was also treated as a crash
and dropped from the panel log.

The writer now splits output into lines, starts a crash only on a line
beginning with the Go runtime's "panic: " / "fatal error: " header, keeps
everything after it, and writes one report from Flush, which
waitForCommand calls after cmd.Wait has delivered all output. The header
line becomes LastLine so GetResult shows the cause.

The report filename format "_000000000" is not a Go fractional-seconds
layout and always produced literal zeros, so reports from the same second
overwrote each other; os.CreateTemp now gives every report a unique name.
MHSanaei 12 hours ago
parent
commit
760f428c41

+ 107 - 68
internal/xray/log_writer.go

@@ -12,8 +12,8 @@ import (
 // Compiled once at package load: Write runs on every line Xray emits, so
 // Compiled once at package load: Write runs on every line Xray emits, so
 // recompiling these per write is wasted work.
 // recompiling these per write is wasted work.
 var (
 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.
 // NewLogWriter returns a new LogWriter for processing Xray log output.
@@ -21,9 +21,12 @@ func NewLogWriter() *LogWriter {
 	return &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 {
 type LogWriter struct {
 	mu       sync.RWMutex
 	mu       sync.RWMutex
+	pending  string
+	crash    strings.Builder
 	lastLine string
 	lastLine string
 }
 }
 
 
@@ -36,86 +39,122 @@ func (lw *LogWriter) LastLine() string {
 	return lw.lastLine
 	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) {
 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
 		return len(m), nil
 	}
 	}
+	lw.pending += string(m)
+	for {
+		i := strings.IndexByte(lw.pending, '\n')
+		if i < 0 {
+			break
+		}
+		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
+}
 
 
-	// 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)
+// 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)
 		}
 		}
-		return len(m), nil
 	}
 	}
+	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
+}
 
 
-	messages := strings.SplitSeq(message, "\n")
+func (lw *LogWriter) processLineLocked(line string) {
+	msg := strings.TrimSpace(line)
+	if msg == "" {
+		return
+	}
+	msgLower := strings.ToLower(msg)
 
 
-	for msg := range messages {
-		matches := logLineRegex.FindStringSubmatch(msg)
+	// Suppress noisy Windows process-kill signal that surfaces as exit status 1
+	if runtime.GOOS == "windows" && strings.Contains(msgLower, "exit status 1") {
+		return
+	}
 
 
-		if len(matches) > 3 {
-			level := matches[2]
-			msgBody := matches[3]
-			msgBodyLower := strings.ToLower(msgBody)
+	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, "tls handshake error") ||
-				strings.Contains(msgBodyLower, "connection ends") {
+		if strings.Contains(msgBodyLower, "failed") {
+			logger.Error("XRAY: " + msgBody)
+		} else {
+			switch level {
+			case "Debug":
 				logger.Debug("XRAY: " + msgBody)
 				logger.Debug("XRAY: " + msgBody)
-				lw.setLastLine("")
-				continue
-			}
-
-			if strings.Contains(msgBodyLower, "failed") {
+			case "Info":
+				logger.Info("XRAY: " + msgBody)
+			case "Warning":
+				logger.Warning("XRAY: " + msgBody)
+			case "Error":
 				logger.Error("XRAY: " + msgBody)
 				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 {
+			default:
 				logger.Debug("XRAY: " + msg)
 				logger.Debug("XRAY: " + msg)
 			}
 			}
-			lw.setLastLine(msg)
 		}
 		}
+		lw.lastLine = ""
+		return
 	}
 	}
 
 
-	return len(m), nil
+	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
 }
 }

+ 78 - 1
internal/xray/log_writer_race_test.go

@@ -1,6 +1,10 @@
 package xray
 package xray
 
 
 import (
 import (
+	"os"
+	"path/filepath"
+	"slices"
+	"strings"
 	"sync"
 	"sync"
 	"testing"
 	"testing"
 )
 )
@@ -20,7 +24,7 @@ func TestLogWriterLastLineConcurrent(t *testing.T) {
 		go func() {
 		go func() {
 			defer wg.Done()
 			defer wg.Done()
 			for range iterations {
 			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()
 	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)
+	}
+}

+ 31 - 0
internal/xray/mutation_audit_test.go

@@ -5,6 +5,7 @@ import (
 	"os/exec"
 	"os/exec"
 	"path/filepath"
 	"path/filepath"
 	"slices"
 	"slices"
+	"strings"
 	"testing"
 	"testing"
 	"time"
 	"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
 // TestStop_RemovesTempConfigFile pins process.go:579 — the
 // `if p.configPath != ""` guard that removes the per-run temp config file on
 // `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
 // 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)
 		os.Exit(2)
 	case "block":
 	case "block":
 		select {}
 		select {}
+	case "panic":
+		go func() { panic("xray helper panic") }()
+		select {}
 	}
 	}
 }
 }

+ 16 - 5
internal/xray/process.go

@@ -734,6 +734,7 @@ func (p *process) waitForCommand(cmd *exec.Cmd, done chan struct{}) {
 	defer close(done)
 	defer close(done)
 
 
 	err := cmd.Wait()
 	err := cmd.Wait()
+	p.logWriter.Flush()
 	if err == nil || p.intentionalStop.Load() {
 	if err == nil || p.intentionalStop.Load() {
 		return
 		return
 	}
 	}
@@ -830,17 +831,27 @@ const (
 	maxCrashReports   = 10
 	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 {
 func writeCrashReport(m []byte) error {
 	dir := config.GetLogFolder()
 	dir := config.GetLogFolder()
 	if err := os.MkdirAll(dir, 0o770); err != nil {
 	if err := os.MkdirAll(dir, 0o770); err != nil {
 		return err
 		return err
 	}
 	}
 	pruneOldCrashReports(dir, maxCrashReports-1)
 	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) {
 func pruneOldCrashReports(dir string, keep int) {