fix(logger): 保留日志文件以便程序退出后调试并完善日志输出功能

This commit is contained in:
dnslin
2025-12-01 17:55:39 +08:00
parent 246674c388
commit 595fa8da96
4 changed files with 135 additions and 24 deletions

View File

@@ -70,7 +70,8 @@ func (l *Logger) Debug(msg string) { l.log("DEBUG", msg) }
// Error logs at ERROR level.
func (l *Logger) Error(msg string) { l.log("ERROR", msg) }
// Close stops the worker, syncs and removes the log file.
// Close stops the worker and syncs the log file.
// The log file is NOT removed, allowing inspection after program exit.
// It is safe to call multiple times.
func (l *Logger) Close() error {
if l == nil {
@@ -94,9 +95,8 @@ func (l *Logger) Close() error {
closeErr = err
}
if err := os.Remove(l.path); err != nil && !os.IsNotExist(err) && closeErr == nil {
closeErr = err
}
// Log file is kept for debugging - NOT removed
// Users can manually clean up /tmp/codex-wrapper-*.log files
})
return closeErr

View File

@@ -75,14 +75,20 @@ func TestLoggerCloseRemovesFileAndStopsWorker(t *testing.T) {
logger.Info("before close")
logger.Flush()
logPath := logger.Path()
if err := logger.Close(); err != nil {
t.Fatalf("Close() returned error: %v", err)
}
if _, err := os.Stat(logger.Path()); !os.IsNotExist(err) {
t.Fatalf("log file still exists after Close, err=%v", err)
// After recent changes, log file is kept for debugging - NOT removed
if _, err := os.Stat(logPath); os.IsNotExist(err) {
t.Fatalf("log file should exist after Close for debugging, but got IsNotExist")
}
// Clean up manually for test
defer os.Remove(logPath)
done := make(chan struct{})
go func() {
logger.workerWG.Wait()

View File

@@ -19,10 +19,11 @@ import (
)
const (
version = "1.0.0"
defaultWorkdir = "."
defaultTimeout = 7200 // seconds
forceKillDelay = 5 // seconds
version = "1.0.0"
defaultWorkdir = "."
defaultTimeout = 7200 // seconds
forceKillDelay = 5 // seconds
codexLogLineLimit = 1000
)
// Test hooks for dependency injection
@@ -72,6 +73,10 @@ func run() int {
setLogger(logger)
defer func() {
// Ensure all pending logs are written before closing
if logger := activeLogger(); logger != nil {
logger.Flush()
}
if err := closeLogger(); err != nil {
fmt.Fprintf(os.Stderr, "ERROR: failed to close logger: %v\n", err)
}
@@ -284,7 +289,15 @@ func runCodexProcess(parentCtx context.Context, codexArgs []string, taskText str
defer cancel()
cmd := exec.Command(codexCommand, codexArgs...)
cmd.Stderr = os.Stderr
// Create log writers for stdout and stderr
stdoutLogger := newLogWriter("CODEX_STDOUT: ", codexLogLineLimit)
stderrLogger := newLogWriter("CODEX_STDERR: ", codexLogLineLimit)
defer stdoutLogger.Flush()
defer stderrLogger.Flush()
// Stderr goes to both os.Stderr and logger
cmd.Stderr = io.MultiWriter(os.Stderr, stderrLogger)
// Setup stdin if needed
var stdinPipe io.WriteCloser
@@ -304,6 +317,9 @@ func runCodexProcess(parentCtx context.Context, codexArgs []string, taskText str
return "", "", 1
}
// Tee stdout to logger while parsing JSON
stdoutReader := io.TeeReader(stdout, stdoutLogger)
logInfo(fmt.Sprintf("Starting codex with args: codex %s...", strings.Join(codexArgs[:min(5, len(codexArgs))], " ")))
// Start process
@@ -336,7 +352,7 @@ func runCodexProcess(parentCtx context.Context, codexArgs []string, taskText str
parseCh := make(chan parseResult, 1)
go func() {
msg, tid := parseJSONStream(stdout)
msg, tid := parseJSONStream(stdoutReader)
parseCh <- parseResult{message: msg, threadID: tid}
}()
@@ -411,8 +427,10 @@ func terminateProcess(cmd *exec.Cmd) *time.Timer {
}
func parseJSONStream(r io.Reader) (message, threadID string) {
logInfo("parseJSONStream: starting to decode stdout stream")
reader := bufio.NewReaderSize(r, 64*1024)
decoder := json.NewDecoder(reader)
totalEvents := 0
for {
var event JSONEvent
@@ -437,18 +455,39 @@ func parseJSONStream(r io.Reader) (message, threadID string) {
continue
}
totalEvents++
var details []string
if event.ThreadID != "" {
details = append(details, fmt.Sprintf("thread_id=%s", event.ThreadID))
}
if event.Item != nil && event.Item.Type != "" {
details = append(details, fmt.Sprintf("item_type=%s", event.Item.Type))
}
if len(details) > 0 {
logInfo(fmt.Sprintf("Parsed event #%d type=%s (%s)", totalEvents, event.Type, strings.Join(details, ", ")))
} else {
logInfo(fmt.Sprintf("Parsed event #%d type=%s", totalEvents, event.Type))
}
switch event.Type {
case "thread.started":
threadID = event.ThreadID
logInfo(fmt.Sprintf("thread.started event thread_id=%s", threadID))
case "item.completed":
if event.Item != nil && event.Item.Type == "agent_message" {
if text := normalizeText(event.Item.Text); text != "" {
message = text
}
var itemType string
var normalized string
if event.Item != nil {
itemType = event.Item.Type
normalized = normalizeText(event.Item.Text)
}
logInfo(fmt.Sprintf("item.completed event item_type=%s message_len=%d", itemType, len(normalized)))
if event.Item != nil && event.Item.Type == "agent_message" && normalized != "" {
message = normalized
}
}
}
logInfo(fmt.Sprintf("parseJSONStream completed: events=%d, message_len=%d, thread_id_found=%t", totalEvents, len(message), threadID != ""))
return message, threadID
}
@@ -533,6 +572,64 @@ func getEnv(key, defaultValue string) string {
return defaultValue
}
type logWriter struct {
prefix string
maxLen int
buf bytes.Buffer
}
func newLogWriter(prefix string, maxLen int) *logWriter {
if maxLen <= 0 {
maxLen = codexLogLineLimit
}
return &logWriter{prefix: prefix, maxLen: maxLen}
}
func (lw *logWriter) Write(p []byte) (int, error) {
if lw == nil {
return len(p), nil
}
total := len(p)
for len(p) > 0 {
if idx := bytes.IndexByte(p, '\n'); idx >= 0 {
lw.buf.Write(p[:idx])
lw.logLine(true)
p = p[idx+1:]
continue
}
lw.buf.Write(p)
break
}
return total, nil
}
func (lw *logWriter) Flush() {
if lw == nil || lw.buf.Len() == 0 {
return
}
lw.logLine(false)
}
func (lw *logWriter) logLine(force bool) {
if lw == nil {
return
}
line := lw.buf.String()
lw.buf.Reset()
if line == "" && !force {
return
}
if lw.maxLen > 0 && len(line) > lw.maxLen {
cutoff := lw.maxLen
if cutoff > 3 {
line = line[:cutoff-3] + "..."
} else {
line = line[:cutoff]
}
}
logInfo(lw.prefix + line)
}
func truncate(s string, maxLen int) string {
if len(s) <= maxLen {
return s

View File

@@ -960,9 +960,11 @@ func TestRun_ExplicitStdinReadError(t *testing.T) {
if !strings.Contains(logOutput, "Failed to read stdin: broken stdin") {
t.Fatalf("log missing read error entry, got %q", logOutput)
}
if _, err := os.Stat(logPath); !os.IsNotExist(err) {
t.Fatalf("log file still exists after run, err=%v", err)
// Log file is kept for debugging after run completes
if _, err := os.Stat(logPath); os.IsNotExist(err) {
t.Fatalf("log file should exist after run for debugging")
}
defer os.Remove(logPath)
}
func TestRun_CommandFails(t *testing.T) {
@@ -1057,9 +1059,11 @@ func TestRun_PipedTaskReadError(t *testing.T) {
if !strings.Contains(logOutput, "Failed to read piped stdin: read stdin: pipe failure") {
t.Fatalf("log missing piped read error entry, got %q", logOutput)
}
if _, err := os.Stat(logPath); !os.IsNotExist(err) {
t.Fatalf("log file still exists after run, err=%v", err)
// Log file is kept for debugging after run completes
if _, err := os.Stat(logPath); os.IsNotExist(err) {
t.Fatalf("log file should exist after run for debugging")
}
defer os.Remove(logPath)
}
func TestRun_PipedTaskSuccess(t *testing.T) {
@@ -1117,9 +1121,11 @@ func TestRun_LoggerLifecycle(t *testing.T) {
if !fileExisted {
t.Fatalf("log file was not present during run")
}
if _, err := os.Stat(logPath); !os.IsNotExist(err) {
t.Fatalf("log file still exists after run, err=%v", err)
// Log file is kept for debugging after run completes
if _, err := os.Stat(logPath); os.IsNotExist(err) {
t.Fatalf("log file should exist after run for debugging")
}
defer os.Remove(logPath)
}
func TestRun_LoggerRemovedOnSignal(t *testing.T) {
@@ -1169,9 +1175,11 @@ printf '%s\n' '{"type":"item.completed","item":{"type":"agent_message","text":"l
if exitCode != 130 {
t.Fatalf("run() exit code = %d, want 130 on signal", exitCode)
}
if _, err := os.Stat(logPath); !os.IsNotExist(err) {
t.Fatalf("log file still exists after signal exit, err=%v", err)
// Log file is kept for debugging even after signal exit
if _, err := os.Stat(logPath); os.IsNotExist(err) {
t.Fatalf("log file should exist after signal exit for debugging")
}
defer os.Remove(logPath)
}
func TestRun_CleanupHookAlwaysCalled(t *testing.T) {