fix(logging): keep the crash file for a re-raised panic and close once
The close function takes crashed: the panic path keeps the crash output so the runtime report of the re-panic reaches the crash file. Close is idempotent, and the slow-disk test hides Close from the diode like Open.
- commit
- 26d812f6718eb895e03bfdfb077b171b7ed80ec9
- author
- brice · · 2026-10-10 15:28 UTC
- committer
- brice · · 2026-10-10 15:39 UTC
- parent
- 72285c7
- signature
- GPG Verified
CD88F9E564E0102646FB6077A1A07C7C7C3E349D· arch-gpg Verified for the committer email
3 files · +39 -19
M internal/adapters/logging/logging.go +32 -13
| @@ -10,6 +10,7 @@ import ( | |||
| 10 | 10 | runtimedebug "runtime/debug" | |
| 11 | 11 | "sort" | |
| 12 | 12 | "strings" | |
| 13 | + | "sync" | |
| 13 | 14 | "time" | |
| 14 | 15 | ||
| 15 | 16 | "github.com/bnema/zerowrap" | |
| @@ -60,8 +61,9 @@ const keepRuns = 20 | |||
| 60 | 61 | // directory at it, prunes old runs of that backend and attaches the logger | |
| 61 | 62 | // to ctx. Each backend keeps its own runs: headless test runs never rotate | |
| 62 | 63 | // a DRM session's log away. | |
| 63 | - | // The caller must invoke close after all logging is complete. | |
| 64 | - | func Open(ctx context.Context, backend, level, debug string) (context.Context, func() error, error) { | |
| 64 | + | // The caller must invoke close after all logging is complete; crashed | |
| 65 | + | // keeps the crash file for a panic about to be re-raised. | |
| 66 | + | func Open(ctx context.Context, backend, level, debug string) (context.Context, func(crashed bool) error, error) { | |
| 65 | 67 | selected, err := ParseDebug(debug) | |
| 66 | 68 | if err != nil { | |
| 67 | 69 | return nil, nil, err | |
| @@ -111,7 +113,12 @@ func Open(ctx context.Context, backend, level, debug string) (context.Context, f | |||
| 111 | 113 | ctx = context.WithValue(ctx, debugKey{}, debugSet(selected)) | |
| 112 | 114 | ctx = context.WithValue(ctx, levelKey{}, level) | |
| 113 | 115 | ctx = context.WithValue(ctx, dirKey{}, dir) | |
| 114 | - | return ctx, w.Close, nil | |
| 116 | + | return ctx, func(crashed bool) error { | |
| 117 | + | if !crashed { | |
| 118 | + | w.Clean() | |
| 119 | + | } | |
| 120 | + | return w.Close() | |
| 121 | + | }, nil | |
| 115 | 122 | } | |
| 116 | 123 | ||
| 117 | 124 | // logQueue is how many entries may wait for the disk. Past it, entries are | |
| @@ -121,28 +128,40 @@ const logQueue = 8192 | |||
| 121 | 128 | ||
| 122 | 129 | // newAsyncWriter writes entries to w from its own goroutine. Close drains | |
| 123 | 130 | // what is queued, then closes c. | |
| 124 | - | func newAsyncWriter(w io.Writer, c io.Closer, crashPath string) io.WriteCloser { | |
| 131 | + | func newAsyncWriter(w io.Writer, c io.Closer, crashPath string) *asyncWriter { | |
| 125 | 132 | d := diode.NewWriter(w, logQueue, 0, func(missed int) { | |
| 126 | 133 | fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed) | |
| 127 | 134 | }) | |
| 128 | - | return asyncWriter{Writer: d, closer: c, crashPath: crashPath} | |
| 135 | + | return &asyncWriter{Writer: d, closer: c, crashPath: crashPath} | |
| 129 | 136 | } | |
| 130 | 137 | ||
| 131 | 138 | type asyncWriter struct { | |
| 132 | 139 | diode.Writer | |
| 133 | 140 | closer io.Closer | |
| 134 | 141 | crashPath string | |
| 142 | + | once sync.Once | |
| 143 | + | err error | |
| 135 | 144 | } | |
| 136 | 145 | ||
| 137 | - | func (a asyncWriter) Close() error { | |
| 138 | - | _ = a.Writer.Close() // drains the queue | |
| 139 | - | if a.crashPath != "" { | |
| 140 | - | _ = runtimedebug.SetCrashOutput(nil, runtimedebug.CrashOptions{}) | |
| 141 | - | if fi, err := os.Stat(a.crashPath); err == nil && fi.Size() == 0 { | |
| 142 | - | _ = os.Remove(a.crashPath) | |
| 143 | - | } | |
| 146 | + | // Close drains the queue and closes the file once. | |
| 147 | + | func (a *asyncWriter) Close() error { | |
| 148 | + | a.once.Do(func() { | |
| 149 | + | _ = a.Writer.Close() // drains the queue | |
| 150 | + | a.err = a.closer.Close() | |
| 151 | + | }) | |
| 152 | + | return a.err | |
| 153 | + | } | |
| 154 | + | ||
| 155 | + | // Clean ends a run that did not crash: the crash output is released and | |
| 156 | + | // the crash file removed while still empty. | |
| 157 | + | func (a *asyncWriter) Clean() { | |
| 158 | + | if a.crashPath == "" { | |
| 159 | + | return | |
| 160 | + | } | |
| 161 | + | _ = runtimedebug.SetCrashOutput(nil, runtimedebug.CrashOptions{}) | |
| 162 | + | if fi, err := os.Stat(a.crashPath); err == nil && fi.Size() == 0 { | |
| 163 | + | _ = os.Remove(a.crashPath) | |
| 144 | 164 | } | |
| 145 | - | return a.closer.Close() | |
| 146 | 165 | } | |
| 147 | 166 | ||
| 148 | 167 | func pruneRuns(dir string) { | |
| @@ -10,6 +10,7 @@ import ( | |||||
| 10 | runtimedebug "runtime/debug" | 10 | runtimedebug "runtime/debug" | ||
| 11 | "sort" | 11 | "sort" | ||
| 12 | "strings" | 12 | "strings" | ||
| 13 | + | "sync" | |||
| 13 | "time" | 14 | "time" | ||
| 14 | 15 | ||||
| 15 | "github.com/bnema/zerowrap" | 16 | "github.com/bnema/zerowrap" | ||
| @@ -60,8 +61,9 @@ const keepRuns = 20 | |||||
| 60 | // directory at it, prunes old runs of that backend and attaches the logger | 61 | // directory at it, prunes old runs of that backend and attaches the logger | ||
| 61 | // to ctx. Each backend keeps its own runs: headless test runs never rotate | 62 | // to ctx. Each backend keeps its own runs: headless test runs never rotate | ||
| 62 | // a DRM session's log away. | 63 | // a DRM session's log away. | ||
| 63 | - | // The caller must invoke close after all logging is complete. | 64 | + | // The caller must invoke close after all logging is complete; crashed |
| 64 | - | func Open(ctx context.Context, backend, level, debug string) (context.Context, func() error, error) { | 65 | + | // keeps the crash file for a panic about to be re-raised. |
| 66 | + | func Open(ctx context.Context, backend, level, debug string) (context.Context, func(crashed bool) error, error) { | |||
| 65 | selected, err := ParseDebug(debug) | 67 | selected, err := ParseDebug(debug) | ||
| 66 | if err != nil { | 68 | if err != nil { | ||
| 67 | return nil, nil, err | 69 | return nil, nil, err | ||
| @@ -111,7 +113,12 @@ func Open(ctx context.Context, backend, level, debug string) (context.Context, f | |||||
| 111 | ctx = context.WithValue(ctx, debugKey{}, debugSet(selected)) | 113 | ctx = context.WithValue(ctx, debugKey{}, debugSet(selected)) | ||
| 112 | ctx = context.WithValue(ctx, levelKey{}, level) | 114 | ctx = context.WithValue(ctx, levelKey{}, level) | ||
| 113 | ctx = context.WithValue(ctx, dirKey{}, dir) | 115 | ctx = context.WithValue(ctx, dirKey{}, dir) | ||
| 114 | - | return ctx, w.Close, nil | 116 | + | return ctx, func(crashed bool) error { |
| 117 | + | if !crashed { | |||
| 118 | + | w.Clean() | |||
| 119 | + | } | |||
| 120 | + | return w.Close() | |||
| 121 | + | }, nil | |||
| 115 | } | 122 | } | ||
| 116 | 123 | ||||
| 117 | // logQueue is how many entries may wait for the disk. Past it, entries are | 124 | // logQueue is how many entries may wait for the disk. Past it, entries are | ||
| @@ -121,28 +128,40 @@ const logQueue = 8192 | |||||
| 121 | 128 | ||||
| 122 | // newAsyncWriter writes entries to w from its own goroutine. Close drains | 129 | // newAsyncWriter writes entries to w from its own goroutine. Close drains | ||
| 123 | // what is queued, then closes c. | 130 | // what is queued, then closes c. | ||
| 124 | - | func newAsyncWriter(w io.Writer, c io.Closer, crashPath string) io.WriteCloser { | 131 | + | func newAsyncWriter(w io.Writer, c io.Closer, crashPath string) *asyncWriter { |
| 125 | d := diode.NewWriter(w, logQueue, 0, func(missed int) { | 132 | d := diode.NewWriter(w, logQueue, 0, func(missed int) { | ||
| 126 | fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed) | 133 | fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed) | ||
| 127 | }) | 134 | }) | ||
| 128 | - | return asyncWriter{Writer: d, closer: c, crashPath: crashPath} | 135 | + | return &asyncWriter{Writer: d, closer: c, crashPath: crashPath} |
| 129 | } | 136 | } | ||
| 130 | 137 | ||||
| 131 | type asyncWriter struct { | 138 | type asyncWriter struct { | ||
| 132 | diode.Writer | 139 | diode.Writer | ||
| 133 | closer io.Closer | 140 | closer io.Closer | ||
| 134 | crashPath string | 141 | crashPath string | ||
| 142 | + | once sync.Once | |||
| 143 | + | err error | |||
| 135 | } | 144 | } | ||
| 136 | 145 | ||||
| 137 | - | func (a asyncWriter) Close() error { | 146 | + | // Close drains the queue and closes the file once. |
| 138 | - | _ = a.Writer.Close() // drains the queue | 147 | + | func (a *asyncWriter) Close() error { |
| 139 | - | if a.crashPath != "" { | 148 | + | a.once.Do(func() { |
| 140 | - | _ = runtimedebug.SetCrashOutput(nil, runtimedebug.CrashOptions{}) | 149 | + | _ = a.Writer.Close() // drains the queue |
| 141 | - | if fi, err := os.Stat(a.crashPath); err == nil && fi.Size() == 0 { | 150 | + | a.err = a.closer.Close() |
| 142 | - | _ = os.Remove(a.crashPath) | 151 | + | }) |
| 143 | - | } | 152 | + | return a.err |
| 153 | + | } | |||
| 154 | + | ||||
| 155 | + | // Clean ends a run that did not crash: the crash output is released and | |||
| 156 | + | // the crash file removed while still empty. | |||
| 157 | + | func (a *asyncWriter) Clean() { | |||
| 158 | + | if a.crashPath == "" { | |||
| 159 | + | return | |||
| 160 | + | } | |||
| 161 | + | _ = runtimedebug.SetCrashOutput(nil, runtimedebug.CrashOptions{}) | |||
| 162 | + | if fi, err := os.Stat(a.crashPath); err == nil && fi.Size() == 0 { | |||
| 163 | + | _ = os.Remove(a.crashPath) | |||
| 144 | } | 164 | } | ||
| 145 | - | return a.closer.Close() | |||
| 146 | } | 165 | } | ||
| 147 | 166 | ||||
| 148 | func pruneRuns(dir string) { | 167 | func pruneRuns(dir string) { | ||
M internal/adapters/logging/logging_test.go +5 -4
| @@ -4,6 +4,7 @@ import ( | |||
| 4 | 4 | "bytes" | |
| 5 | 5 | "context" | |
| 6 | 6 | "encoding/json" | |
| 7 | + | "io" | |
| 7 | 8 | "os" | |
| 8 | 9 | "path/filepath" | |
| 9 | 10 | "testing" | |
| @@ -47,7 +48,7 @@ func TestComponentLevelsAndRotation(t *testing.T) { | |||
| 47 | 48 | core.Debug().Msg("visible") | |
| 48 | 49 | app.Debug().Msg("hidden") | |
| 49 | 50 | app.Info().Msg("startup") | |
| 50 | - | if err := closeLog(); err != nil { | |
| 51 | + | if err := closeLog(false); err != nil { | |
| 51 | 52 | t.Fatal(err) | |
| 52 | 53 | } | |
| 53 | 54 | data, err := os.ReadFile(path) | |
| @@ -98,7 +99,7 @@ func TestBackendsRotateSeparately(t *testing.T) { | |||
| 98 | 99 | if err != nil { | |
| 99 | 100 | t.Fatal(err) | |
| 100 | 101 | } | |
| 101 | - | if err := closeLog(); err != nil { | |
| 102 | + | if err := closeLog(false); err != nil { | |
| 102 | 103 | t.Fatal(err) | |
| 103 | 104 | } | |
| 104 | 105 | } | |
| @@ -127,7 +128,7 @@ func TestCategoryEnablesComponentDebug(t *testing.T) { | |||
| 127 | 128 | input, core := For(ctx, "input"), For(ctx, "core") | |
| 128 | 129 | input.Debug().Msg("motion") | |
| 129 | 130 | core.Debug().Msg("hidden") | |
| 130 | - | if err := closeLog(); err != nil { | |
| 131 | + | if err := closeLog(false); err != nil { | |
| 131 | 132 | t.Fatal(err) | |
| 132 | 133 | } | |
| 133 | 134 | data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log")) | |
| @@ -147,7 +148,7 @@ func TestLogWriteNeverBlocksOnSlowDisk(t *testing.T) { | |||
| 147 | 148 | t.Fatal(err) | |
| 148 | 149 | } | |
| 149 | 150 | defer r.Close() | |
| 150 | - | w := newAsyncWriter(pw, pw, "") | |
| 151 | + | w := newAsyncWriter(struct{ io.Writer }{pw}, pw, "") | |
| 151 | 152 | line := bytes.Repeat([]byte{'x'}, 1024) | |
| 152 | 153 | done := make(chan struct{}) | |
| 153 | 154 | go func() { | |
| @@ -4,6 +4,7 @@ import ( | |||||
| 4 | "bytes" | 4 | "bytes" | ||
| 5 | "context" | 5 | "context" | ||
| 6 | "encoding/json" | 6 | "encoding/json" | ||
| 7 | + | "io" | |||
| 7 | "os" | 8 | "os" | ||
| 8 | "path/filepath" | 9 | "path/filepath" | ||
| 9 | "testing" | 10 | "testing" | ||
| @@ -47,7 +48,7 @@ func TestComponentLevelsAndRotation(t *testing.T) { | |||||
| 47 | core.Debug().Msg("visible") | 48 | core.Debug().Msg("visible") | ||
| 48 | app.Debug().Msg("hidden") | 49 | app.Debug().Msg("hidden") | ||
| 49 | app.Info().Msg("startup") | 50 | app.Info().Msg("startup") | ||
| 50 | - | if err := closeLog(); err != nil { | 51 | + | if err := closeLog(false); err != nil { |
| 51 | t.Fatal(err) | 52 | t.Fatal(err) | ||
| 52 | } | 53 | } | ||
| 53 | data, err := os.ReadFile(path) | 54 | data, err := os.ReadFile(path) | ||
| @@ -98,7 +99,7 @@ func TestBackendsRotateSeparately(t *testing.T) { | |||||
| 98 | if err != nil { | 99 | if err != nil { | ||
| 99 | t.Fatal(err) | 100 | t.Fatal(err) | ||
| 100 | } | 101 | } | ||
| 101 | - | if err := closeLog(); err != nil { | 102 | + | if err := closeLog(false); err != nil { |
| 102 | t.Fatal(err) | 103 | t.Fatal(err) | ||
| 103 | } | 104 | } | ||
| 104 | } | 105 | } | ||
| @@ -127,7 +128,7 @@ func TestCategoryEnablesComponentDebug(t *testing.T) { | |||||
| 127 | input, core := For(ctx, "input"), For(ctx, "core") | 128 | input, core := For(ctx, "input"), For(ctx, "core") | ||
| 128 | input.Debug().Msg("motion") | 129 | input.Debug().Msg("motion") | ||
| 129 | core.Debug().Msg("hidden") | 130 | core.Debug().Msg("hidden") | ||
| 130 | - | if err := closeLog(); err != nil { | 131 | + | if err := closeLog(false); err != nil { |
| 131 | t.Fatal(err) | 132 | t.Fatal(err) | ||
| 132 | } | 133 | } | ||
| 133 | data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log")) | 134 | data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log")) | ||
| @@ -147,7 +148,7 @@ func TestLogWriteNeverBlocksOnSlowDisk(t *testing.T) { | |||||
| 147 | t.Fatal(err) | 148 | t.Fatal(err) | ||
| 148 | } | 149 | } | ||
| 149 | defer r.Close() | 150 | defer r.Close() | ||
| 150 | - | w := newAsyncWriter(pw, pw, "") | 151 | + | w := newAsyncWriter(struct{ io.Writer }{pw}, pw, "") |
| 151 | line := bytes.Repeat([]byte{'x'}, 1024) | 152 | line := bytes.Repeat([]byte{'x'}, 1024) | ||
| 152 | done := make(chan struct{}) | 153 | done := make(chan struct{}) | ||
| 153 | go func() { | 154 | go func() { | ||
M internal/cli/run.go +2 -2
| @@ -123,12 +123,12 @@ func (f *runFlags) run(ctx context.Context, sizes [][2]int) error { | |||
| 123 | 123 | if err != nil { | |
| 124 | 124 | return err | |
| 125 | 125 | } | |
| 126 | - | defer closeLog() | |
| 126 | + | defer closeLog(false) // no-op after the panic path closed it | |
| 127 | 127 | log := logging.For(ctx, "app") | |
| 128 | 128 | defer func() { | |
| 129 | 129 | if p := recover(); p != nil { | |
| 130 | 130 | log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit") | |
| 131 | - | _ = closeLog() | |
| 131 | + | _ = closeLog(true) // keep the crash file for the re-panic | |
| 132 | 132 | panic(p) | |
| 133 | 133 | } | |
| 134 | 134 | }() | |
| @@ -123,12 +123,12 @@ func (f *runFlags) run(ctx context.Context, sizes [][2]int) error { | |||||
| 123 | if err != nil { | 123 | if err != nil { | ||
| 124 | return err | 124 | return err | ||
| 125 | } | 125 | } | ||
| 126 | - | defer closeLog() | 126 | + | defer closeLog(false) // no-op after the panic path closed it |
| 127 | log := logging.For(ctx, "app") | 127 | log := logging.For(ctx, "app") | ||
| 128 | defer func() { | 128 | defer func() { | ||
| 129 | if p := recover(); p != nil { | 129 | if p := recover(); p != nil { | ||
| 130 | log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit") | 130 | log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit") | ||
| 131 | - | _ = closeLog() | 131 | + | _ = closeLog(true) // keep the crash file for the re-panic |
| 132 | panic(p) | 132 | panic(p) | ||
| 133 | } | 133 | } | ||
| 134 | }() | 134 | }() | ||