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