1// Package logging configures component-scoped zerowrap logging.
2package logging
3
4import (
5 "context"
6 "fmt"
7 "io"
8 "os"
9 "path/filepath"
10 runtimedebug "runtime/debug"
11 "sort"
12 "strings"
13 "sync"
14 "time"
15
16 "github.com/bnema/zerowrap"
17 "github.com/rs/zerolog"
18 "github.com/rs/zerolog/diode"
19 "golang.org/x/term"
20)
21
22var components = map[string]bool{
23 "core": true, "wayland": true, "input": true, "drm": true, "seat": true,
24 "render": true, "sync": true, "config": true, "app": true,
25 "screensaver": true, "powerkey": true, "sched": true,
26}
27
28// categories are debug switches narrower than a component, only on when
29// named: "all" leaves them off. input-motion logs every pointer motion,
30// input-keys every key (typed text), drm-flip every frame and commit
31// completion with its timing. Naming one turns on debug for its component.
32var categories = map[string]string{"input-motion": "input", "input-keys": "input", "drm-flip": "drm"}
33
34type debugKey struct{}
35type levelKey struct{}
36type dirKey struct{}
37type debugSet map[string]bool
38
39func ParseDebug(value string) (map[string]bool, error) {
40 selected := make(debugSet)
41 if value == "" {
42 return selected, nil
43 }
44 for _, name := range strings.Split(value, ",") {
45 if name == "all" {
46 selected[name] = true
47 continue
48 }
49 if _, ok := categories[name]; !components[name] && !ok {
50 return nil, fmt.Errorf("invalid debug component %q", name)
51 }
52 selected[name] = true
53 }
54 return selected, nil
55}
56
57// keepRuns is how many per-run log files Open retains.
58const keepRuns = 20
59
60// Open creates runs/<backend>/<timestamp>.log, points latest.log in that
61// directory at it, prunes old runs of that backend and attaches the logger
62// to ctx. Each backend keeps its own runs: headless test runs never rotate
63// a DRM session's log away.
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.
66func Open(ctx context.Context, backend, level, debug string) (context.Context, func(crashed bool) error, error) {
67 selected, err := ParseDebug(debug)
68 if err != nil {
69 return nil, nil, err
70 }
71 state := os.Getenv("XDG_STATE_HOME")
72 if state == "" {
73 home, err := os.UserHomeDir()
74 if err != nil {
75 return nil, nil, err
76 }
77 state = filepath.Join(home, ".local", "state")
78 }
79 dir := filepath.Join(state, "neferwl", "runs", backend)
80 if err := os.MkdirAll(dir, 0o700); err != nil {
81 return nil, nil, err
82 }
83 name := time.Now().Format("20060102-150405.000") + ".log"
84 file, err := os.OpenFile(filepath.Join(dir, name), os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0o600)
85 if err != nil {
86 return nil, nil, err
87 }
88 latest := filepath.Join(dir, "latest.log")
89 _ = os.Remove(latest)
90 if err := os.Symlink(name, latest); err != nil {
91 _ = file.Close()
92 return nil, nil, err
93 }
94 // Queued entries are lost on a fatal crash: the runtime's own report
95 // (panic and every stack) goes to its own file, besides stderr. A clean
96 // Close removes it while still empty. Created before pruneRuns so
97 // crash files rotate like logs.
98 crashPath := filepath.Join(dir, strings.TrimSuffix(name, ".log")+".crash")
99 if crash, err := os.OpenFile(crashPath, os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0o600); err == nil {
100 _ = runtimedebug.SetCrashOutput(crash, runtimedebug.CrashOptions{})
101 _ = crash.Close() // SetCrashOutput keeps its own duplicate
102 } else {
103 crashPath = ""
104 }
105 pruneRuns(dir)
106 // Hide Close from the diode: asyncWriter closes the file once.
107 var sink io.Writer = struct{ io.Writer }{file}
108 if term.IsTerminal(int(os.Stderr.Fd())) {
109 sink = &consoleAndFile{file: file}
110 }
111 w := newAsyncWriter(sink, file, crashPath)
112 ctx = zerowrap.WithCtx(ctx, zerowrap.New(zerowrap.Config{Level: level, Format: "json", Output: w}))
113 ctx = context.WithValue(ctx, debugKey{}, debugSet(selected))
114 ctx = context.WithValue(ctx, levelKey{}, level)
115 ctx = context.WithValue(ctx, dirKey{}, dir)
116 return ctx, func(crashed bool) error {
117 if !crashed {
118 w.Clean()
119 }
120 return w.Close()
121 }, nil
122}
123
124// logQueue is how many entries may wait for the disk. Past it, entries are
125// dropped (and counted on stderr) rather than blocking the logging
126// goroutine: input, outputs and the display must never wait on a slow disk.
127const logQueue = 8192
128
129// newAsyncWriter writes entries to w from its own goroutine. Close drains
130// what is queued, then closes c.
131func newAsyncWriter(w io.Writer, c io.Closer, crashPath string) *asyncWriter {
132 d := diode.NewWriter(w, logQueue, 0, func(missed int) {
133 fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed)
134 })
135 return &asyncWriter{Writer: d, closer: c, crashPath: crashPath}
136}
137
138type asyncWriter struct {
139 diode.Writer
140 closer io.Closer
141 crashPath string
142 once sync.Once
143 err error
144}
145
146// Close drains the queue and closes the file once.
147func (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.
157func (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)
164 }
165}
166
167func pruneRuns(dir string) {
168 // Watchdog stall dumps (stall-<time>-<loop>.txt) rotate like runs.
169 for _, pattern := range []string{"2*.log", "2*.crash", "stall-*.txt"} {
170 runs, _ := filepath.Glob(filepath.Join(dir, pattern))
171 sort.Strings(runs)
172 for len(runs) > keepRuns {
173 _ = os.Remove(runs[0])
174 runs = runs[1:]
175 }
176 }
177}
178
179type consoleAndFile struct{ file *os.File }
180
181func (w *consoleAndFile) Write(p []byte) (int, error) {
182 // JSON remains the canonical output; terminal users also see each entry.
183 _, _ = os.Stderr.Write(p)
184 return w.file.Write(p)
185}
186
187// Dir is the directory of the run log Open created, or "" without one.
188func Dir(ctx context.Context) string {
189 dir, _ := ctx.Value(dirKey{}).(string)
190 return dir
191}
192
193// Enabled reports whether a debug category was named in --debug.
194func Enabled(ctx context.Context, category string) bool {
195 selected, _ := ctx.Value(debugKey{}).(debugSet)
196 return selected[category]
197}
198
199// For returns a component logger with debug enabled only for selected components.
200func For(ctx context.Context, component string) zerowrap.Logger {
201 log := zerowrap.FromCtxWithField(ctx, zerowrap.FieldComponent, component)
202 selected, _ := ctx.Value(debugKey{}).(debugSet)
203 level := zerolog.InfoLevel
204 switch ctx.Value(levelKey{}) {
205 case "debug":
206 level = zerolog.DebugLevel
207 case "warn":
208 level = zerolog.WarnLevel
209 case "error":
210 level = zerolog.ErrorLevel
211 }
212 if selected["all"] || selected[component] {
213 level = zerolog.DebugLevel
214 }
215 for name, owner := range categories {
216 if selected[name] && owner == component {
217 level = zerolog.DebugLevel
218 }
219 }
220 log = zerowrap.Logger{Logger: log.Level(level)}
221 return log
222}