detached d476712

fix(logging): clean up startup warning, duplicate component fields and output placement logs (#125)

* fix(app): pass a nil input script when --input is absent

* fix(logging): emit a single component field per log entry

* fix(wayland): log the real output placement
commit
d476712b94e67b9d1dc0a05bc0079f7cf895931d
author
bnema · · 2026-10-04 03:28 UTC
committer
GitHub · · 2026-10-04 03:28 UTC
parent
ad3c741
signature
GPG UnverifiedB5690EEEBB952194 The key is unknown
26 files · +196 -72
Unified
UnifiedSplit
M Makefile +8 -2
@@ -1,4 +1,4 @@
1-.PHONY: build test vet race mocks mocks-check spv-check fakes-check arch check perf-check bin tty logs pkg install
1+.PHONY: build test vet race mocks mocks-check spv-check fakes-check log-check arch check perf-check bin tty logs pkg install
22
33 # 0 runs until quit; set e.g. TTY_TIMEOUT=60s for a safety net.
44 TTY_TIMEOUT ?= 0
@@ -50,12 +50,18 @@ FAKES := ^\s*type\s+\w*(fake|stub|spy|dummy|mock)\w*|^\s*\w*(fake|stub|spy|dummy
5050 fakes-check:
5151 @rc=0; grep -rniE '$(FAKES)' --include='*_test.go' --exclude='*_mock_test.go' internal cmd || rc=$$?; \
5252 [ $$rc -eq 1 ] || { [ $$rc -eq 0 ] && echo 'handwritten test double: add an interface and a Mockery entry (see AGENTS.md)' >&2; exit 1; }
53+# The component field comes from logging.For: a second one on a scoped logger
54+# duplicates the JSON key. grep exit 1 (no match) passes; 0 and 2 fail.
55+LOGCOMPONENT := "component"|FieldComponent
56+log-check:
57+ @rc=0; grep -rnE '$(LOGCOMPONENT)' --include='*.go' --exclude='*_test.go' --exclude-dir=logging internal cmd || rc=$$?; \
58+ [ $$rc -eq 1 ] || { [ $$rc -eq 0 ] && echo 'component log field: derive a logger with logging.For instead (see AGENTS.md)' >&2; exit 1; }
5359 arch:
5460 $(HOME)/go/bin/hexcheck -hexcheck.config .hexcheck.yaml -hexcheck.root . ./...
5561 # Fast, mandatory guards for tiled content publications and SHM copies.
5662 perf-check:
5763 CGO_ENABLED=0 go test ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestOutputRoutingAllocations|TestReportSeenAllocations|TestFrameLifecycleTransitionsAllocations|TestFullscreenShownAllocations|TestFrameDecisionAllocations|TestCommitFrameAllocations|TestColorPipelineAllocations|TestShownBySnapshotAllocations|TestDueFramesAllocations|TestRenderSteadyStateAllocations|TestAccountFlipAllocations|TestFlipDoneAllocations|TestSceneWalkUnchangedTiledSHM|TestTiledCommitPublishAllocations|TestCapturedCommitApplyAllocations|TestCapturedViewportApplyAllocations|TestEffectiveInputEmptyTreeAllocations|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1
58-check: vet test arch fakes-check perf-check
64+check: vet test arch fakes-check log-check perf-check
5965
6066 # Arch package of the committed HEAD (packaging/arch/PKGBUILD). Go modules
6167 # come from the module proxy in prepare(); the build itself runs offline.
@@ -1,4 +1,4 @@
1-.PHONY: build test vet race mocks mocks-check spv-check fakes-check arch check perf-check bin tty logs pkg install1+.PHONY: build test vet race mocks mocks-check spv-check fakes-check log-check arch check perf-check bin tty logs pkg install
2 2
3 # 0 runs until quit; set e.g. TTY_TIMEOUT=60s for a safety net.3 # 0 runs until quit; set e.g. TTY_TIMEOUT=60s for a safety net.
4 TTY_TIMEOUT ?= 04 TTY_TIMEOUT ?= 0
@@ -50,12 +50,18 @@ FAKES := ^\s*type\s+\w*(fake|stub|spy|dummy|mock)\w*|^\s*\w*(fake|stub|spy|dummy
50 fakes-check:50 fakes-check:
51 @rc=0; grep -rniE '$(FAKES)' --include='*_test.go' --exclude='*_mock_test.go' internal cmd || rc=$$?; \51 @rc=0; grep -rniE '$(FAKES)' --include='*_test.go' --exclude='*_mock_test.go' internal cmd || rc=$$?; \
52 [ $$rc -eq 1 ] || { [ $$rc -eq 0 ] && echo 'handwritten test double: add an interface and a Mockery entry (see AGENTS.md)' >&2; exit 1; }52 [ $$rc -eq 1 ] || { [ $$rc -eq 0 ] && echo 'handwritten test double: add an interface and a Mockery entry (see AGENTS.md)' >&2; exit 1; }
53+# The component field comes from logging.For: a second one on a scoped logger
54+# duplicates the JSON key. grep exit 1 (no match) passes; 0 and 2 fail.
55+LOGCOMPONENT := "component"|FieldComponent
56+log-check:
57+ @rc=0; grep -rnE '$(LOGCOMPONENT)' --include='*.go' --exclude='*_test.go' --exclude-dir=logging internal cmd || rc=$$?; \
58+ [ $$rc -eq 1 ] || { [ $$rc -eq 0 ] && echo 'component log field: derive a logger with logging.For instead (see AGENTS.md)' >&2; exit 1; }
53 arch:59 arch:
54 $(HOME)/go/bin/hexcheck -hexcheck.config .hexcheck.yaml -hexcheck.root . ./...60 $(HOME)/go/bin/hexcheck -hexcheck.config .hexcheck.yaml -hexcheck.root . ./...
55 # Fast, mandatory guards for tiled content publications and SHM copies.61 # Fast, mandatory guards for tiled content publications and SHM copies.
56 perf-check:62 perf-check:
57 CGO_ENABLED=0 go test ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestOutputRoutingAllocations|TestReportSeenAllocations|TestFrameLifecycleTransitionsAllocations|TestFullscreenShownAllocations|TestFrameDecisionAllocations|TestCommitFrameAllocations|TestColorPipelineAllocations|TestShownBySnapshotAllocations|TestDueFramesAllocations|TestRenderSteadyStateAllocations|TestAccountFlipAllocations|TestFlipDoneAllocations|TestSceneWalkUnchangedTiledSHM|TestTiledCommitPublishAllocations|TestCapturedCommitApplyAllocations|TestCapturedViewportApplyAllocations|TestEffectiveInputEmptyTreeAllocations|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=163 CGO_ENABLED=0 go test ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestOutputRoutingAllocations|TestReportSeenAllocations|TestFrameLifecycleTransitionsAllocations|TestFullscreenShownAllocations|TestFrameDecisionAllocations|TestCommitFrameAllocations|TestColorPipelineAllocations|TestShownBySnapshotAllocations|TestDueFramesAllocations|TestRenderSteadyStateAllocations|TestAccountFlipAllocations|TestFlipDoneAllocations|TestSceneWalkUnchangedTiledSHM|TestTiledCommitPublishAllocations|TestCapturedCommitApplyAllocations|TestCapturedViewportApplyAllocations|TestEffectiveInputEmptyTreeAllocations|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1
58-check: vet test arch fakes-check perf-check64+check: vet test arch fakes-check log-check perf-check
59 65
60 # Arch package of the committed HEAD (packaging/arch/PKGBUILD). Go modules66 # Arch package of the committed HEAD (packaging/arch/PKGBUILD). Go modules
61 # come from the module proxy in prepare(); the build itself runs offline.67 # come from the module proxy in prepare(); the build itself runs offline.
M cmd/neferwl/main.go +24 -12
@@ -6,6 +6,7 @@ import (
66 "errors"
77 "flag"
88 "fmt"
9+ "io"
910 "net"
1011 "net/http"
1112 "net/http/pprof"
@@ -26,6 +27,24 @@ import (
2627
2728 type usageError struct{ error }
2829
30+// openScript opens the --input script. It returns a nil interface, not a
31+// typed-nil *os.File, when no script was requested: app.Run tests the
32+// interface against nil to decide whether to read a script. closeScript
33+// closes what openScript opened; it does nothing for stdin and for no script.
34+func openScript(path string) (script io.ReadCloser, closeScript func(), err error) {
35+ switch path {
36+ case "":
37+ return nil, func() {}, nil
38+ case "-":
39+ return os.Stdin, func() {}, nil
40+ }
41+ f, err := os.Open(path)
42+ if err != nil {
43+ return nil, func() {}, err
44+ }
45+ return f, func() { _ = f.Close() }, nil
46+}
47+
2948 // version is set with -ldflags "-X main.version=..." by packaged builds.
3049 var version string
3150
@@ -215,19 +234,12 @@ func run() error {
215234 fmt.Fprintln(os.Stderr, cfgErr)
216235 return cfgErr
217236 }
218- var script *os.File
219- if *inputPath != "" {
220- if *inputPath == "-" {
221- script = os.Stdin
222- } else {
223- var err error
224- script, err = os.Open(*inputPath)
225- if err != nil {
226- return err
227- }
228- defer script.Close()
229- }
237+ script, closeScript, err := openScript(*inputPath)
238+ if err != nil {
239+ return err
230240 }
241+ // app.Run closes the script on shutdown; this covers the returns before it.
242+ defer closeScript()
231243 selected := mergeDebug(cfg.Log.Debug, *debugFlag)
232244 if _, err := logging.ParseDebug(selected); err != nil {
233245 fmt.Fprintln(os.Stderr, err)
@@ -6,6 +6,7 @@ import (
6 "errors"6 "errors"
7 "flag"7 "flag"
8 "fmt"8 "fmt"
9+ "io"
9 "net"10 "net"
10 "net/http"11 "net/http"
11 "net/http/pprof"12 "net/http/pprof"
@@ -26,6 +27,24 @@ import (
26 27
27 type usageError struct{ error }28 type usageError struct{ error }
28 29
30+// openScript opens the --input script. It returns a nil interface, not a
31+// typed-nil *os.File, when no script was requested: app.Run tests the
32+// interface against nil to decide whether to read a script. closeScript
33+// closes what openScript opened; it does nothing for stdin and for no script.
34+func openScript(path string) (script io.ReadCloser, closeScript func(), err error) {
35+ switch path {
36+ case "":
37+ return nil, func() {}, nil
38+ case "-":
39+ return os.Stdin, func() {}, nil
40+ }
41+ f, err := os.Open(path)
42+ if err != nil {
43+ return nil, func() {}, err
44+ }
45+ return f, func() { _ = f.Close() }, nil
46+}
47+
29 // version is set with -ldflags "-X main.version=..." by packaged builds.48 // version is set with -ldflags "-X main.version=..." by packaged builds.
30 var version string49 var version string
31 50
@@ -215,19 +234,12 @@ func run() error {
215 fmt.Fprintln(os.Stderr, cfgErr)234 fmt.Fprintln(os.Stderr, cfgErr)
216 return cfgErr235 return cfgErr
217 }236 }
218- var script *os.File237+ script, closeScript, err := openScript(*inputPath)
219- if *inputPath != "" {238+ if err != nil {
220- if *inputPath == "-" {239+ return err
221- script = os.Stdin
222- } else {
223- var err error
224- script, err = os.Open(*inputPath)
225- if err != nil {
226- return err
227- }
228- defer script.Close()
229- }
230 }240 }
241+ // app.Run closes the script on shutdown; this covers the returns before it.
242+ defer closeScript()
231 selected := mergeDebug(cfg.Log.Debug, *debugFlag)243 selected := mergeDebug(cfg.Log.Debug, *debugFlag)
232 if _, err := logging.ParseDebug(selected); err != nil {244 if _, err := logging.ParseDebug(selected); err != nil {
233 fmt.Fprintln(os.Stderr, err)245 fmt.Fprintln(os.Stderr, err)
M cmd/neferwl/main_test.go +55 -0
@@ -1,6 +1,7 @@
11 package main
22
33 import (
4+ "io"
45 "os"
56 "strings"
67 "testing"
@@ -39,3 +40,57 @@ func TestExitCodes(t *testing.T) {
3940 t.Fatal("union")
4041 }
4142 }
43+
44+func TestOpenScript(t *testing.T) {
45+ file := t.TempDir() + "/script"
46+ if err := os.WriteFile(file, []byte("quit\n"), 0o600); err != nil {
47+ t.Fatal(err)
48+ }
49+ for _, tc := range []struct {
50+ name, path string
51+ check func(t *testing.T, script io.ReadCloser, err error)
52+ }{
53+ {"none", "", func(t *testing.T, script io.ReadCloser, err error) {
54+ if err != nil || script != nil {
55+ t.Fatalf("got %#v, %v; want a nil interface", script, err)
56+ }
57+ }},
58+ {"stdin", "-", func(t *testing.T, script io.ReadCloser, err error) {
59+ if err != nil || script != io.ReadCloser(os.Stdin) {
60+ t.Fatalf("got %#v, %v; want os.Stdin", script, err)
61+ }
62+ }},
63+ {"missing", "/nonexistent/script", func(t *testing.T, script io.ReadCloser, err error) {
64+ if err == nil || script != nil {
65+ t.Fatalf("got %#v, %v; want a nil interface and an error", script, err)
66+ }
67+ }},
68+ {"file", file, func(t *testing.T, script io.ReadCloser, err error) {
69+ if err != nil || script == nil {
70+ t.Fatalf("got %#v, %v", script, err)
71+ }
72+ if got, err := io.ReadAll(script); err != nil || string(got) != "quit\n" {
73+ t.Fatalf("read %q, %v", got, err)
74+ }
75+ }},
76+ } {
77+ t.Run(tc.name, func(t *testing.T) {
78+ script, closeScript, err := openScript(tc.path)
79+ if closeScript == nil {
80+ t.Fatal("nil close func")
81+ }
82+ tc.check(t, script, err)
83+ closeScript()
84+ if tc.path == "-" {
85+ if _, err := os.Stdin.Stat(); err != nil {
86+ t.Fatalf("stdin closed: %v", err)
87+ }
88+ }
89+ if tc.name == "file" {
90+ if _, err := script.Read(make([]byte, 1)); err == nil || err == io.EOF {
91+ t.Fatalf("file left open: %v", err)
92+ }
93+ }
94+ })
95+ }
96+}
@@ -1,6 +1,7 @@
1 package main1 package main
2 2
3 import (3 import (
4+ "io"
4 "os"5 "os"
5 "strings"6 "strings"
6 "testing"7 "testing"
@@ -39,3 +40,57 @@ func TestExitCodes(t *testing.T) {
39 t.Fatal("union")40 t.Fatal("union")
40 }41 }
41 }42 }
43+
44+func TestOpenScript(t *testing.T) {
45+ file := t.TempDir() + "/script"
46+ if err := os.WriteFile(file, []byte("quit\n"), 0o600); err != nil {
47+ t.Fatal(err)
48+ }
49+ for _, tc := range []struct {
50+ name, path string
51+ check func(t *testing.T, script io.ReadCloser, err error)
52+ }{
53+ {"none", "", func(t *testing.T, script io.ReadCloser, err error) {
54+ if err != nil || script != nil {
55+ t.Fatalf("got %#v, %v; want a nil interface", script, err)
56+ }
57+ }},
58+ {"stdin", "-", func(t *testing.T, script io.ReadCloser, err error) {
59+ if err != nil || script != io.ReadCloser(os.Stdin) {
60+ t.Fatalf("got %#v, %v; want os.Stdin", script, err)
61+ }
62+ }},
63+ {"missing", "/nonexistent/script", func(t *testing.T, script io.ReadCloser, err error) {
64+ if err == nil || script != nil {
65+ t.Fatalf("got %#v, %v; want a nil interface and an error", script, err)
66+ }
67+ }},
68+ {"file", file, func(t *testing.T, script io.ReadCloser, err error) {
69+ if err != nil || script == nil {
70+ t.Fatalf("got %#v, %v", script, err)
71+ }
72+ if got, err := io.ReadAll(script); err != nil || string(got) != "quit\n" {
73+ t.Fatalf("read %q, %v", got, err)
74+ }
75+ }},
76+ } {
77+ t.Run(tc.name, func(t *testing.T) {
78+ script, closeScript, err := openScript(tc.path)
79+ if closeScript == nil {
80+ t.Fatal("nil close func")
81+ }
82+ tc.check(t, script, err)
83+ closeScript()
84+ if tc.path == "-" {
85+ if _, err := os.Stdin.Stat(); err != nil {
86+ t.Fatalf("stdin closed: %v", err)
87+ }
88+ }
89+ if tc.name == "file" {
90+ if _, err := script.Read(make([]byte, 1)); err == nil || err == io.EOF {
91+ t.Fatalf("file left open: %v", err)
92+ }
93+ }
94+ })
95+ }
96+}
M internal/adapters/drm/card.go +13 -9
@@ -18,11 +18,14 @@ import (
1818 // goroutine. One reader goroutine reads commit events for all of them
1919 // and hands each to its output by CRTC.
2020 type Card struct {
21- fd int
22- path string
23- want Want
24- log zerowrap.Logger
25- crtcs []uint32
21+ fd int
22+ path string
23+ want Want
24+ log zerowrap.Logger
25+ // renderLog carries the render component: direct scanout and overlay
26+ // decisions belong to the render path, not to KMS bookkeeping.
27+ renderLog zerowrap.Logger
28+ crtcs []uint32
2629 // outputs by connector name; owned by the goroutine that calls Scan.
2730 outputs map[string]*Output
2831 leasable map[string]connector
@@ -42,14 +45,15 @@ type Card struct {
4245 }
4346
4447 // OpenCard turns on atomic modesetting and reads the card's CRTCs. fd
45-// stays owned by the caller. A card without atomic KMS is refused.
46-func OpenCard(fd int, path string, want Want, log zerowrap.Logger) (*Card, error) {
48+// stays owned by the caller. A card without atomic KMS is refused. log
49+// carries the drm component and renderLog the render component.
50+func OpenCard(fd int, path string, want Want, log, renderLog zerowrap.Logger) (*Card, error) {
4751 if err := enableAtomic(fd); err != nil {
4852 return nil, fmt.Errorf("drm: atomic modesetting unsupported by %s: %w", path, err)
4953 }
5054 // Before any plane or property read: the property set depends on it.
5155 if err := enableColorPipeline(fd); err != nil {
52- log.Info().Str("component", "drm").Err(err).Str("card", path).Msg("plane colour pipelines unavailable")
56+ log.Info().Err(err).Str("card", path).Msg("plane colour pipelines unavailable")
5357 }
5458 crtcs, _, err := resources(fd)
5559 if err != nil {
@@ -60,7 +64,7 @@ func OpenCard(fd int, path string, want Want, log zerowrap.Logger) (*Card, error
6064 flips[c] = make(chan flipEvent, 4)
6165 }
6266 k := kmsDevice{fd: fd, gemMu: &sync.Mutex{}, modifiers: hasCap(fd, capAddFB2Modifiers)}
63- return &Card{fd: fd, path: path, want: want, log: log, crtcs: crtcs, outputs: map[string]*Output{}, leasable: map[string]connector{}, leases: map[uint32]leaseRecord{}, flips: flips, k: k, taken: map[uint32]bool{}, async: hasCap(fd, capAtomicAsync)}, nil
67+ return &Card{fd: fd, path: path, want: want, log: log, renderLog: renderLog, crtcs: crtcs, outputs: map[string]*Output{}, leasable: map[string]connector{}, leases: map[uint32]leaseRecord{}, flips: flips, k: k, taken: map[uint32]bool{}, async: hasCap(fd, capAtomicAsync)}, nil
6468 }
6569
6670 // Path is the device path, e.g. /dev/dri/card1.
@@ -18,11 +18,14 @@ import (
18 // goroutine. One reader goroutine reads commit events for all of them18 // goroutine. One reader goroutine reads commit events for all of them
19 // and hands each to its output by CRTC.19 // and hands each to its output by CRTC.
20 type Card struct {20 type Card struct {
21- fd int21+ fd int
22- path string22+ path string
23- want Want23+ want Want
24- log zerowrap.Logger24+ log zerowrap.Logger
25- crtcs []uint3225+ // renderLog carries the render component: direct scanout and overlay
26+ // decisions belong to the render path, not to KMS bookkeeping.
27+ renderLog zerowrap.Logger
28+ crtcs []uint32
26 // outputs by connector name; owned by the goroutine that calls Scan.29 // outputs by connector name; owned by the goroutine that calls Scan.
27 outputs map[string]*Output30 outputs map[string]*Output
28 leasable map[string]connector31 leasable map[string]connector
@@ -42,14 +45,15 @@ type Card struct {
42 }45 }
43 46
44 // OpenCard turns on atomic modesetting and reads the card's CRTCs. fd47 // OpenCard turns on atomic modesetting and reads the card's CRTCs. fd
45-// stays owned by the caller. A card without atomic KMS is refused.48+// stays owned by the caller. A card without atomic KMS is refused. log
46-func OpenCard(fd int, path string, want Want, log zerowrap.Logger) (*Card, error) {49+// carries the drm component and renderLog the render component.
50+func OpenCard(fd int, path string, want Want, log, renderLog zerowrap.Logger) (*Card, error) {
47 if err := enableAtomic(fd); err != nil {51 if err := enableAtomic(fd); err != nil {
48 return nil, fmt.Errorf("drm: atomic modesetting unsupported by %s: %w", path, err)52 return nil, fmt.Errorf("drm: atomic modesetting unsupported by %s: %w", path, err)
49 }53 }
50 // Before any plane or property read: the property set depends on it.54 // Before any plane or property read: the property set depends on it.
51 if err := enableColorPipeline(fd); err != nil {55 if err := enableColorPipeline(fd); err != nil {
52- log.Info().Str("component", "drm").Err(err).Str("card", path).Msg("plane colour pipelines unavailable")56+ log.Info().Err(err).Str("card", path).Msg("plane colour pipelines unavailable")
53 }57 }
54 crtcs, _, err := resources(fd)58 crtcs, _, err := resources(fd)
55 if err != nil {59 if err != nil {
@@ -60,7 +64,7 @@ func OpenCard(fd int, path string, want Want, log zerowrap.Logger) (*Card, error
60 flips[c] = make(chan flipEvent, 4)64 flips[c] = make(chan flipEvent, 4)
61 }65 }
62 k := kmsDevice{fd: fd, gemMu: &sync.Mutex{}, modifiers: hasCap(fd, capAddFB2Modifiers)}66 k := kmsDevice{fd: fd, gemMu: &sync.Mutex{}, modifiers: hasCap(fd, capAddFB2Modifiers)}
63- return &Card{fd: fd, path: path, want: want, log: log, crtcs: crtcs, outputs: map[string]*Output{}, leasable: map[string]connector{}, leases: map[uint32]leaseRecord{}, flips: flips, k: k, taken: map[uint32]bool{}, async: hasCap(fd, capAtomicAsync)}, nil67+ return &Card{fd: fd, path: path, want: want, log: log, renderLog: renderLog, crtcs: crtcs, outputs: map[string]*Output{}, leasable: map[string]connector{}, leases: map[uint32]leaseRecord{}, flips: flips, k: k, taken: map[uint32]bool{}, async: hasCap(fd, capAtomicAsync)}, nil
64 }68 }
65 69
66 // Path is the device path, e.g. /dev/dri/card1.70 // Path is the device path, e.g. /dev/dri/card1.
M internal/adapters/drm/colorop.go +5 -5
@@ -176,7 +176,7 @@ func (o *Output) colorRefused(err error, fb uint32, fence *os.File, vrr bool, cu
176176 if ov.buf != 0 && ov.color.mode != colorBypass {
177177 o.overlay.setVerdict(ov.color.format, cur.on, false)
178178 }
179- o.log.Info().Str("component", "render").Err(err).Str("connector", o.conn.name).Bool("cursor", cur.on).Msg("plane colour pipeline refused")
179+ o.renderLog.Info().Err(err).Str("connector", o.conn.name).Bool("cursor", cur.on).Msg("plane colour pipeline refused")
180180 return true
181181 }
182182
@@ -197,7 +197,7 @@ func (o *Output) colorConflict(err error, cursorOn bool) bool {
197197 }
198198 }
199199 if hit {
200- o.log.Info().Str("component", "render").Err(err).Str("connector", o.conn.name).Msg("plane colour pipeline refused with the cursor")
200+ o.renderLog.Info().Err(err).Str("connector", o.conn.name).Msg("plane colour pipeline refused with the cursor")
201201 }
202202 return hit
203203 }
@@ -225,7 +225,7 @@ func (o *Output) colorAllowed(p *plane, format uint32, test func(req *atomicReq)
225225 }
226226 p.setVerdict(format, cursor, err == nil)
227227 if err != nil {
228- o.log.Info().Str("component", "render").Err(err).Uint32("format", format).Uint32("plane", p.id).Bool("cursor", cursor).Str("connector", o.conn.name).Msg("plane colour pipeline refused")
228+ o.renderLog.Info().Err(err).Uint32("format", format).Uint32("plane", p.id).Bool("cursor", cursor).Str("connector", o.conn.name).Msg("plane colour pipeline refused")
229229 }
230230 return err == nil
231231 }
@@ -244,7 +244,7 @@ func (o *Output) setupColor() {
244244 }
245245 blob, err := o.k.createBlob(ctmBytes(bt709ToBT2020))
246246 if err != nil {
247- o.log.Warn().Str("component", "drm").Err(err).Str("connector", o.conn.name).Msg("colour matrix blob; plane colour pipelines off")
247+ o.log.Warn().Err(err).Str("connector", o.conn.name).Msg("colour matrix blob; plane colour pipelines off")
248248 o.dropPipelines()
249249 return
250250 }
@@ -270,7 +270,7 @@ func (o *Output) readColor() {
270270 }
271271 cp, why := readColorPipeline(o.k, p)
272272 p.pipeline = cp
273- o.log.Info().Str("component", "drm").Str("connector", o.conn.name).Uint32("plane", p.id).Bool("matched", cp != nil).Str("reason", why).Msg("plane colour pipeline")
273+ o.log.Info().Str("connector", o.conn.name).Uint32("plane", p.id).Bool("matched", cp != nil).Str("reason", why).Msg("plane colour pipeline")
274274 }
275275 }
276276
@@ -176,7 +176,7 @@ func (o *Output) colorRefused(err error, fb uint32, fence *os.File, vrr bool, cu
176 if ov.buf != 0 && ov.color.mode != colorBypass {176 if ov.buf != 0 && ov.color.mode != colorBypass {
177 o.overlay.setVerdict(ov.color.format, cur.on, false)177 o.overlay.setVerdict(ov.color.format, cur.on, false)
178 }178 }
179- o.log.Info().Str("component", "render").Err(err).Str("connector", o.conn.name).Bool("cursor", cur.on).Msg("plane colour pipeline refused")179+ o.renderLog.Info().Err(err).Str("connector", o.conn.name).Bool("cursor", cur.on).Msg("plane colour pipeline refused")
180 return true180 return true
181 }181 }
182 182
@@ -197,7 +197,7 @@ func (o *Output) colorConflict(err error, cursorOn bool) bool {
197 }197 }
198 }198 }
199 if hit {199 if hit {
200- o.log.Info().Str("component", "render").Err(err).Str("connector", o.conn.name).Msg("plane colour pipeline refused with the cursor")200+ o.renderLog.Info().Err(err).Str("connector", o.conn.name).Msg("plane colour pipeline refused with the cursor")
201 }201 }
202 return hit202 return hit
203 }203 }
@@ -225,7 +225,7 @@ func (o *Output) colorAllowed(p *plane, format uint32, test func(req *atomicReq)
225 }225 }
226 p.setVerdict(format, cursor, err == nil)226 p.setVerdict(format, cursor, err == nil)
227 if err != nil {227 if err != nil {
228- o.log.Info().Str("component", "render").Err(err).Uint32("format", format).Uint32("plane", p.id).Bool("cursor", cursor).Str("connector", o.conn.name).Msg("plane colour pipeline refused")228+ o.renderLog.Info().Err(err).Uint32("format", format).Uint32("plane", p.id).Bool("cursor", cursor).Str("connector", o.conn.name).Msg("plane colour pipeline refused")
229 }229 }
230 return err == nil230 return err == nil
231 }231 }
@@ -244,7 +244,7 @@ func (o *Output) setupColor() {
244 }244 }
245 blob, err := o.k.createBlob(ctmBytes(bt709ToBT2020))245 blob, err := o.k.createBlob(ctmBytes(bt709ToBT2020))
246 if err != nil {246 if err != nil {
247- o.log.Warn().Str("component", "drm").Err(err).Str("connector", o.conn.name).Msg("colour matrix blob; plane colour pipelines off")247+ o.log.Warn().Err(err).Str("connector", o.conn.name).Msg("colour matrix blob; plane colour pipelines off")
248 o.dropPipelines()248 o.dropPipelines()
249 return249 return
250 }250 }
@@ -270,7 +270,7 @@ func (o *Output) readColor() {
270 }270 }
271 cp, why := readColorPipeline(o.k, p)271 cp, why := readColorPipeline(o.k, p)
272 p.pipeline = cp272 p.pipeline = cp
273- o.log.Info().Str("component", "drm").Str("connector", o.conn.name).Uint32("plane", p.id).Bool("matched", cp != nil).Str("reason", why).Msg("plane colour pipeline")273+ o.log.Info().Str("connector", o.conn.name).Uint32("plane", p.id).Bool("matched", cp != nil).Str("reason", why).Msg("plane colour pipeline")
274 }274 }
275 }275 }
276 276
M internal/adapters/drm/game_performance_test.go +15 -1
@@ -18,7 +18,7 @@ func TestScaledScanoutRectAndCachedRefusal(t *testing.T) {
1818 s := ports.Scene{OutputWidth: 200, OutputHeight: 100, Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 200, H: 100}, Fullscreen: true}}}
1919 c := ports.SurfaceContent{ID: 1, Width: 100, Height: 50, LogicalW: 200, LogicalH: 100, Source: [4]float32{5, 2, 90, 46}, DMABuf: &ports.DMABuf{ID: 9, Format: fourccXRGB}}
2020 var log bytes.Buffer
21- o.log = zerowrap.New(zerowrap.Config{Output: &log})
21+ o.renderLog = zerowrap.New(zerowrap.Config{Output: &log})
2222 surfaces := map[ports.WindowID]ports.SurfaceContent{1: c}
2323 if fb, _, _ := o.scanoutFrame(s, surfaces); fb != 0 || o.reason != "scale_refused" {
2424 t.Fatalf("fb %d reason %s", fb, o.reason)
@@ -101,3 +101,17 @@ func TestContentTypeFrameAndReset(t *testing.T) {
101101 t.Fatal("absent property set")
102102 }
103103 }
104+
105+// A scanout decision is logged once, under the render component only.
106+func TestScanoutReasonLogsOneComponent(t *testing.T) {
107+ o, _, _ := testOutput(t)
108+ var log bytes.Buffer
109+ o.renderLog = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &log}).WithField("component", "render")
110+ o.setScanoutReason("test")
111+ o.setOverlayReason("test")
112+ for _, line := range bytes.Split(bytes.TrimSpace(log.Bytes()), []byte("\n")) {
113+ if n := bytes.Count(line, []byte(`"component"`)); n != 1 {
114+ t.Fatalf("%d component fields in %s", n, line)
115+ }
116+ }
117+}
@@ -18,7 +18,7 @@ func TestScaledScanoutRectAndCachedRefusal(t *testing.T) {
18 s := ports.Scene{OutputWidth: 200, OutputHeight: 100, Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 200, H: 100}, Fullscreen: true}}}18 s := ports.Scene{OutputWidth: 200, OutputHeight: 100, Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 200, H: 100}, Fullscreen: true}}}
19 c := ports.SurfaceContent{ID: 1, Width: 100, Height: 50, LogicalW: 200, LogicalH: 100, Source: [4]float32{5, 2, 90, 46}, DMABuf: &ports.DMABuf{ID: 9, Format: fourccXRGB}}19 c := ports.SurfaceContent{ID: 1, Width: 100, Height: 50, LogicalW: 200, LogicalH: 100, Source: [4]float32{5, 2, 90, 46}, DMABuf: &ports.DMABuf{ID: 9, Format: fourccXRGB}}
20 var log bytes.Buffer20 var log bytes.Buffer
21- o.log = zerowrap.New(zerowrap.Config{Output: &log})21+ o.renderLog = zerowrap.New(zerowrap.Config{Output: &log})
22 surfaces := map[ports.WindowID]ports.SurfaceContent{1: c}22 surfaces := map[ports.WindowID]ports.SurfaceContent{1: c}
23 if fb, _, _ := o.scanoutFrame(s, surfaces); fb != 0 || o.reason != "scale_refused" {23 if fb, _, _ := o.scanoutFrame(s, surfaces); fb != 0 || o.reason != "scale_refused" {
24 t.Fatalf("fb %d reason %s", fb, o.reason)24 t.Fatalf("fb %d reason %s", fb, o.reason)
@@ -101,3 +101,17 @@ func TestContentTypeFrameAndReset(t *testing.T) {
101 t.Fatal("absent property set")101 t.Fatal("absent property set")
102 }102 }
103 }103 }
104+
105+// A scanout decision is logged once, under the render component only.
106+func TestScanoutReasonLogsOneComponent(t *testing.T) {
107+ o, _, _ := testOutput(t)
108+ var log bytes.Buffer
109+ o.renderLog = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &log}).WithField("component", "render")
110+ o.setScanoutReason("test")
111+ o.setOverlayReason("test")
112+ for _, line := range bytes.Split(bytes.TrimSpace(log.Bytes()), []byte("\n")) {
113+ if n := bytes.Count(line, []byte(`"component"`)); n != 1 {
114+ t.Fatalf("%d component fields in %s", n, line)
115+ }
116+ }
117+}
M internal/adapters/drm/output.go +6 -4
@@ -45,6 +45,8 @@ type Output struct {
4545 monitor Monitor
4646 hdr hdrState
4747 log zerowrap.Logger
48+ // renderLog is the render-component logger (see Card.renderLog).
49+ renderLog zerowrap.Logger
4850 // clock paces the periodic stats and renderer trim (nil: system).
4951 clock ports.Clock
5052 // Properties: CRTC and connector property IDs by name.
@@ -195,7 +197,7 @@ type CursorLoader func(c ports.CursorChange, scale float64, t ports.BufferTransf
195197 func newOutput(card *Card, c connector, mode modeInfo, crtc uint32) (*Output, error) {
196198 log := card.log
197199 pipe := slices.Index(card.crtcs, crtc)
198- o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap}
200+ o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, renderLog: card.renderLog, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap}
199201 var err error
200202 if o.saved, err = getCrtc(card.fd, crtc); err != nil {
201203 log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit")
@@ -649,7 +651,7 @@ func (o *Output) commitWithRect(fb uint32, fence *os.File, async bool, vrr bool,
649651 // The same frame without the connector hint tells whether the hint
650652 // is the cause.
651653 if o.contentProp != 0 && o.contentWanted != o.contentValue && errors.Is(err, unix.EINVAL) && o.frameTest(fb, fence, vrr, cur, ov, rect, pc, false) {
652- o.log.Warn().Str("component", "drm").Err(err).Msg("content type refused; disabled")
654+ o.log.Warn().Err(err).Msg("content type refused; disabled")
653655 o.contentProp = 0
654656 return o.commitWithRect(fb, fence, false, vrr, f, ov, rect, pc)
655657 }
@@ -786,7 +788,7 @@ func (o *Output) commitState(vrr bool) error {
786788 }
787789 if len(without.objs) == 0 || o.k.commit(without, atomicTestOnly, 0) == nil {
788790 o.contentProp = 0
789- o.log.Warn().Str("component", "drm").Err(err).Msg("content type refused; disabled")
791+ o.log.Warn().Err(err).Msg("content type refused; disabled")
790792 return o.commitState(vrr)
791793 }
792794 }
@@ -861,7 +863,7 @@ func (o *Output) commitScanoutRect(fb uint32, c ports.SurfaceContent, f pendingF
861863 }
862864 if err != nil && (errors.Is(err, unix.EINVAL) || errors.Is(err, unix.ERANGE)) {
863865 // KMS refuses this buffer on the plane: compose it instead.
864- o.log.Info().Str("component", "render").Err(err).Uint32("format", c.DMABuf.Format).Uint64("modifier", c.DMABuf.Modifier).Msg("scanout flip refused")
866+ o.renderLog.Info().Err(err).Uint32("format", c.DMABuf.Format).Uint64("modifier", c.DMABuf.Modifier).Msg("scanout flip refused")
865867 cfb.failed = "flip_refused"
866868 o.setScanoutReason("flip_refused")
867869 return false, nil
@@ -45,6 +45,8 @@ type Output struct {
45 monitor Monitor45 monitor Monitor
46 hdr hdrState46 hdr hdrState
47 log zerowrap.Logger47 log zerowrap.Logger
48+ // renderLog is the render-component logger (see Card.renderLog).
49+ renderLog zerowrap.Logger
48 // clock paces the periodic stats and renderer trim (nil: system).50 // clock paces the periodic stats and renderer trim (nil: system).
49 clock ports.Clock51 clock ports.Clock
50 // Properties: CRTC and connector property IDs by name.52 // Properties: CRTC and connector property IDs by name.
@@ -195,7 +197,7 @@ type CursorLoader func(c ports.CursorChange, scale float64, t ports.BufferTransf
195 func newOutput(card *Card, c connector, mode modeInfo, crtc uint32) (*Output, error) {197 func newOutput(card *Card, c connector, mode modeInfo, crtc uint32) (*Output, error) {
196 log := card.log198 log := card.log
197 pipe := slices.Index(card.crtcs, crtc)199 pipe := slices.Index(card.crtcs, crtc)
198- o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap}200+ o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, renderLog: card.renderLog, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap}
199 var err error201 var err error
200 if o.saved, err = getCrtc(card.fd, crtc); err != nil {202 if o.saved, err = getCrtc(card.fd, crtc); err != nil {
201 log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit")203 log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit")
@@ -649,7 +651,7 @@ func (o *Output) commitWithRect(fb uint32, fence *os.File, async bool, vrr bool,
649 // The same frame without the connector hint tells whether the hint651 // The same frame without the connector hint tells whether the hint
650 // is the cause.652 // is the cause.
651 if o.contentProp != 0 && o.contentWanted != o.contentValue && errors.Is(err, unix.EINVAL) && o.frameTest(fb, fence, vrr, cur, ov, rect, pc, false) {653 if o.contentProp != 0 && o.contentWanted != o.contentValue && errors.Is(err, unix.EINVAL) && o.frameTest(fb, fence, vrr, cur, ov, rect, pc, false) {
652- o.log.Warn().Str("component", "drm").Err(err).Msg("content type refused; disabled")654+ o.log.Warn().Err(err).Msg("content type refused; disabled")
653 o.contentProp = 0655 o.contentProp = 0
654 return o.commitWithRect(fb, fence, false, vrr, f, ov, rect, pc)656 return o.commitWithRect(fb, fence, false, vrr, f, ov, rect, pc)
655 }657 }
@@ -786,7 +788,7 @@ func (o *Output) commitState(vrr bool) error {
786 }788 }
787 if len(without.objs) == 0 || o.k.commit(without, atomicTestOnly, 0) == nil {789 if len(without.objs) == 0 || o.k.commit(without, atomicTestOnly, 0) == nil {
788 o.contentProp = 0790 o.contentProp = 0
789- o.log.Warn().Str("component", "drm").Err(err).Msg("content type refused; disabled")791+ o.log.Warn().Err(err).Msg("content type refused; disabled")
790 return o.commitState(vrr)792 return o.commitState(vrr)
791 }793 }
792 }794 }
@@ -861,7 +863,7 @@ func (o *Output) commitScanoutRect(fb uint32, c ports.SurfaceContent, f pendingF
861 }863 }
862 if err != nil && (errors.Is(err, unix.EINVAL) || errors.Is(err, unix.ERANGE)) {864 if err != nil && (errors.Is(err, unix.EINVAL) || errors.Is(err, unix.ERANGE)) {
863 // KMS refuses this buffer on the plane: compose it instead.865 // KMS refuses this buffer on the plane: compose it instead.
864- o.log.Info().Str("component", "render").Err(err).Uint32("format", c.DMABuf.Format).Uint64("modifier", c.DMABuf.Modifier).Msg("scanout flip refused")866+ o.renderLog.Info().Err(err).Uint32("format", c.DMABuf.Format).Uint64("modifier", c.DMABuf.Modifier).Msg("scanout flip refused")
865 cfb.failed = "flip_refused"867 cfb.failed = "flip_refused"
866 o.setScanoutReason("flip_refused")868 o.setScanoutReason("flip_refused")
867 return false, nil869 return false, nil
M internal/adapters/drm/output_test.go +1 -1
@@ -80,7 +80,7 @@ func testOutputRules(t *testing.T, rule func(*atomicReq, uint32) error, errs ...
8080 primary := &plane{id: tPrimary, typ: planePrimary, props: planeProps}
8181 cur := newCursor(&plane{id: tCursor, typ: planeCursor, props: planeProps}, 64)
8282 cur.fbs = [2]uint32{90, 91}
83- o := &Output{k: k, frame: frameLifecycle{serials: &atomic.Uint64{}}, crtc: tCrtc, conn: connector{id: tConn, name: "DP-1"}, mode: modeInfo{HDisplay: 200, VDisplay: 100, VRefresh: 60}, log: zerowrap.Default(),
83+ o := &Output{k: k, frame: frameLifecycle{serials: &atomic.Uint64{}}, crtc: tCrtc, conn: connector{id: tConn, name: "DP-1"}, mode: modeInfo{HDisplay: 200, VDisplay: 100, VRefresh: 60}, log: zerowrap.Default(), renderLog: zerowrap.Default(),
8484 crtcProps: map[string]uint32{"MODE_ID": pMode, "ACTIVE": pActive, "VRR_ENABLED": pVRR}, connCrtc: pConnCrtc, vrrProp: pVRR,
8585 primary: primary, cursor: cur, fbs: [2]uint32{70, 71}, clientFBs: map[uint64]*clientFB{}, scanout: true, tearing: true, asyncFence: true, planeRect: fullPlaneRect(200, 100), seatDisable: make(chan chan struct{})}
8686 return o, k, &commits, commitMu
@@ -80,7 +80,7 @@ func testOutputRules(t *testing.T, rule func(*atomicReq, uint32) error, errs ...
80 primary := &plane{id: tPrimary, typ: planePrimary, props: planeProps}80 primary := &plane{id: tPrimary, typ: planePrimary, props: planeProps}
81 cur := newCursor(&plane{id: tCursor, typ: planeCursor, props: planeProps}, 64)81 cur := newCursor(&plane{id: tCursor, typ: planeCursor, props: planeProps}, 64)
82 cur.fbs = [2]uint32{90, 91}82 cur.fbs = [2]uint32{90, 91}
83- o := &Output{k: k, frame: frameLifecycle{serials: &atomic.Uint64{}}, crtc: tCrtc, conn: connector{id: tConn, name: "DP-1"}, mode: modeInfo{HDisplay: 200, VDisplay: 100, VRefresh: 60}, log: zerowrap.Default(),83+ o := &Output{k: k, frame: frameLifecycle{serials: &atomic.Uint64{}}, crtc: tCrtc, conn: connector{id: tConn, name: "DP-1"}, mode: modeInfo{HDisplay: 200, VDisplay: 100, VRefresh: 60}, log: zerowrap.Default(), renderLog: zerowrap.Default(),
84 crtcProps: map[string]uint32{"MODE_ID": pMode, "ACTIVE": pActive, "VRR_ENABLED": pVRR}, connCrtc: pConnCrtc, vrrProp: pVRR,84 crtcProps: map[string]uint32{"MODE_ID": pMode, "ACTIVE": pActive, "VRR_ENABLED": pVRR}, connCrtc: pConnCrtc, vrrProp: pVRR,
85 primary: primary, cursor: cur, fbs: [2]uint32{70, 71}, clientFBs: map[uint64]*clientFB{}, scanout: true, tearing: true, asyncFence: true, planeRect: fullPlaneRect(200, 100), seatDisable: make(chan chan struct{})}85 primary: primary, cursor: cur, fbs: [2]uint32{70, 71}, clientFBs: map[uint64]*clientFB{}, scanout: true, tearing: true, asyncFence: true, planeRect: fullPlaneRect(200, 100), seatDisable: make(chan chan struct{})}
86 return o, k, &commits, commitMu86 return o, k, &commits, commitMu
M internal/adapters/drm/overlay.go +2 -2
@@ -183,14 +183,14 @@ func (o *Output) testOverlay(fb uint32, ov overlayWin) bool {
183183 if ov.color.mode != colorBypass && refused(err) && o.probeOverlay(fb, ov, colorBypass) == nil {
184184 o.overlay.setVerdict(ov.color.format, o.cursorShown(), false)
185185 o.setOverlayReason("color_refused")
186- o.log.Info().Str("component", "render").Err(err).Uint32("format", ov.color.format).Str("connector", o.conn.name).Msg("overlay colour pipeline refused")
186+ o.renderLog.Info().Err(err).Uint32("format", ov.color.format).Str("connector", o.conn.name).Msg("overlay colour pipeline refused")
187187 return false
188188 }
189189 if cfb := o.clientFBs[ov.buf]; cfb != nil && refused(err) {
190190 cfb.overlayFailed = "overlay_refused"
191191 }
192192 o.setOverlayReason("overlay_refused")
193- o.log.Info().Str("component", "render").Err(err).Str("connector", o.conn.name).Msg("overlay refused")
193+ o.renderLog.Info().Err(err).Str("connector", o.conn.name).Msg("overlay refused")
194194 return false
195195 }
196196
@@ -183,14 +183,14 @@ func (o *Output) testOverlay(fb uint32, ov overlayWin) bool {
183 if ov.color.mode != colorBypass && refused(err) && o.probeOverlay(fb, ov, colorBypass) == nil {183 if ov.color.mode != colorBypass && refused(err) && o.probeOverlay(fb, ov, colorBypass) == nil {
184 o.overlay.setVerdict(ov.color.format, o.cursorShown(), false)184 o.overlay.setVerdict(ov.color.format, o.cursorShown(), false)
185 o.setOverlayReason("color_refused")185 o.setOverlayReason("color_refused")
186- o.log.Info().Str("component", "render").Err(err).Uint32("format", ov.color.format).Str("connector", o.conn.name).Msg("overlay colour pipeline refused")186+ o.renderLog.Info().Err(err).Uint32("format", ov.color.format).Str("connector", o.conn.name).Msg("overlay colour pipeline refused")
187 return false187 return false
188 }188 }
189 if cfb := o.clientFBs[ov.buf]; cfb != nil && refused(err) {189 if cfb := o.clientFBs[ov.buf]; cfb != nil && refused(err) {
190 cfb.overlayFailed = "overlay_refused"190 cfb.overlayFailed = "overlay_refused"
191 }191 }
192 o.setOverlayReason("overlay_refused")192 o.setOverlayReason("overlay_refused")
193- o.log.Info().Str("component", "render").Err(err).Str("connector", o.conn.name).Msg("overlay refused")193+ o.renderLog.Info().Err(err).Str("connector", o.conn.name).Msg("overlay refused")
194 return false194 return false
195 }195 }
196 196
M internal/adapters/drm/scanout.go +4 -4
@@ -220,7 +220,7 @@ func (o *Output) scanoutFrame(scene ports.Scene, surfaces map[ports.WindowID]por
220220 cfb.scaleFailed = rect
221221 cfb.scaleRefused = true
222222 reason = "scale_refused"
223- o.log.Info().Str("component", "render").Err(err).Str("reason", reason).Str("connector", o.conn.name).Msg("scanout scaling refused")
223+ o.renderLog.Info().Err(err).Str("reason", reason).Str("connector", o.conn.name).Msg("scanout scaling refused")
224224 } else {
225225 cfb.scaleTested = rect
226226 cfb.scaleTestedOK = true
@@ -328,7 +328,7 @@ func (o *Output) decideFrame(s ports.Scene, surfaces map[ports.WindowID]ports.Su
328328 // setScanoutReason logs a direct-scanout transition once.
329329 func (o *Output) setScanoutReason(reason string) {
330330 if reason != o.reason {
331- o.log.Info().Str("component", "render").Bool("direct_scanout", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("scanout")
331+ o.renderLog.Info().Bool("direct_scanout", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("scanout")
332332 o.reason = reason
333333 }
334334 }
@@ -336,7 +336,7 @@ func (o *Output) setScanoutReason(reason string) {
336336 // setOverlayReason logs an overlay transition once.
337337 func (o *Output) setOverlayReason(reason string) {
338338 if reason != o.overlayReason {
339- o.log.Info().Str("component", "render").Bool("overlay", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("overlay")
339+ o.renderLog.Info().Bool("overlay", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("overlay")
340340 o.overlayReason = reason
341341 }
342342 }
@@ -395,7 +395,7 @@ func (o *Output) planeFB(p *plane, b *ports.DMABuf, now time.Time, reason func(*
395395 }
396396 id, err := o.k.addFB(b, format)
397397 if err != nil {
398- o.log.Info().Str("component", "render").Err(err).Uint32("format", b.Format).Uint64("modifier", b.Modifier).Msg("scanout import failed")
398+ o.renderLog.Info().Err(err).Uint32("format", b.Format).Uint64("modifier", b.Modifier).Msg("scanout import failed")
399399 fb.importErr, *why = true, "import_failed"
400400 return 0, *why
401401 }
@@ -220,7 +220,7 @@ func (o *Output) scanoutFrame(scene ports.Scene, surfaces map[ports.WindowID]por
220 cfb.scaleFailed = rect220 cfb.scaleFailed = rect
221 cfb.scaleRefused = true221 cfb.scaleRefused = true
222 reason = "scale_refused"222 reason = "scale_refused"
223- o.log.Info().Str("component", "render").Err(err).Str("reason", reason).Str("connector", o.conn.name).Msg("scanout scaling refused")223+ o.renderLog.Info().Err(err).Str("reason", reason).Str("connector", o.conn.name).Msg("scanout scaling refused")
224 } else {224 } else {
225 cfb.scaleTested = rect225 cfb.scaleTested = rect
226 cfb.scaleTestedOK = true226 cfb.scaleTestedOK = true
@@ -328,7 +328,7 @@ func (o *Output) decideFrame(s ports.Scene, surfaces map[ports.WindowID]ports.Su
328 // setScanoutReason logs a direct-scanout transition once.328 // setScanoutReason logs a direct-scanout transition once.
329 func (o *Output) setScanoutReason(reason string) {329 func (o *Output) setScanoutReason(reason string) {
330 if reason != o.reason {330 if reason != o.reason {
331- o.log.Info().Str("component", "render").Bool("direct_scanout", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("scanout")331+ o.renderLog.Info().Bool("direct_scanout", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("scanout")
332 o.reason = reason332 o.reason = reason
333 }333 }
334 }334 }
@@ -336,7 +336,7 @@ func (o *Output) setScanoutReason(reason string) {
336 // setOverlayReason logs an overlay transition once.336 // setOverlayReason logs an overlay transition once.
337 func (o *Output) setOverlayReason(reason string) {337 func (o *Output) setOverlayReason(reason string) {
338 if reason != o.overlayReason {338 if reason != o.overlayReason {
339- o.log.Info().Str("component", "render").Bool("overlay", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("overlay")339+ o.renderLog.Info().Bool("overlay", reason == "").Str("reason", reason).Str("connector", o.conn.name).Msg("overlay")
340 o.overlayReason = reason340 o.overlayReason = reason
341 }341 }
342 }342 }
@@ -395,7 +395,7 @@ func (o *Output) planeFB(p *plane, b *ports.DMABuf, now time.Time, reason func(*
395 }395 }
396 id, err := o.k.addFB(b, format)396 id, err := o.k.addFB(b, format)
397 if err != nil {397 if err != nil {
398- o.log.Info().Str("component", "render").Err(err).Uint32("format", b.Format).Uint64("modifier", b.Modifier).Msg("scanout import failed")398+ o.renderLog.Info().Err(err).Uint32("format", b.Format).Uint64("modifier", b.Modifier).Msg("scanout import failed")
399 fb.importErr, *why = true, "import_failed"399 fb.importErr, *why = true, "import_failed"
400 return 0, *why400 return 0, *why
401 }401 }
M internal/adapters/drm/seat_disable.go +2 -2
@@ -53,9 +53,9 @@ func (o *Output) bypassForSeatDisable() {
5353 req.reset()
5454 o.forceBypass(req)
5555 if err := o.k.commit(req, 0, 0); err != nil {
56- o.log.Warn().Str("component", "drm").Err(err).Str("connector", o.conn.name).Msg("colour pipeline not reset before seat disable")
56+ o.log.Warn().Err(err).Str("connector", o.conn.name).Msg("colour pipeline not reset before seat disable")
5757 return
5858 }
5959 o.colorBypassed()
60- o.log.Info().Str("component", "drm").Str("connector", o.conn.name).Msg("colour pipeline reset before seat disable")
60+ o.log.Info().Str("connector", o.conn.name).Msg("colour pipeline reset before seat disable")
6161 }
@@ -53,9 +53,9 @@ func (o *Output) bypassForSeatDisable() {
53 req.reset()53 req.reset()
54 o.forceBypass(req)54 o.forceBypass(req)
55 if err := o.k.commit(req, 0, 0); err != nil {55 if err := o.k.commit(req, 0, 0); err != nil {
56- o.log.Warn().Str("component", "drm").Err(err).Str("connector", o.conn.name).Msg("colour pipeline not reset before seat disable")56+ o.log.Warn().Err(err).Str("connector", o.conn.name).Msg("colour pipeline not reset before seat disable")
57 return57 return
58 }58 }
59 o.colorBypassed()59 o.colorBypassed()
60- o.log.Info().Str("component", "drm").Str("connector", o.conn.name).Msg("colour pipeline reset before seat disable")60+ o.log.Info().Str("connector", o.conn.name).Msg("colour pipeline reset before seat disable")
61 }61 }
M internal/adapters/headless/output.go +3 -3
@@ -579,7 +579,7 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
579579 continue
580580 }
581581 if shot == nil {
582- opts.Log.Debug().Str("component", "headless").Str("output", opts.Name).Int("frame", frame).Msg("screenshot readback unavailable; frame skipped")
582+ opts.Log.Debug().Str("output", opts.Name).Int("frame", frame).Msg("screenshot readback unavailable; frame skipped")
583583 continue
584584 }
585585 if opts.Cursor != nil {
@@ -595,7 +595,7 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
595595 return fmt.Errorf("latest screenshot: %w", err)
596596 }
597597 }
598- opts.Log.Debug().Str("component", "render").Int("frame", frame).Uint64("seq", scene.Seq).Int("windows", len(scene.Windows)).Dur("ms", time.Since(start)).Msg("frame")
598+ opts.Log.Debug().Int("frame", frame).Uint64("seq", scene.Seq).Int("windows", len(scene.Windows)).Dur("ms", time.Since(start)).Msg("frame")
599599 }
600600 }
601601
@@ -632,7 +632,7 @@ func (opts Options) report(q *presented.Queue, flip *ports.FlipInfo, seen map[po
632632 return
633633 }
634634 if q.Push(ports.OutputPresented{Output: opts.Name, Flip: flip, Seen: seen}) {
635- opts.Log.Warn().Str("component", "render").Str("output", opts.Name).Msg("wayland is not reading output reports; flips merged")
635+ opts.Log.Warn().Str("output", opts.Name).Msg("wayland is not reading output reports; flips merged")
636636 }
637637 q.Flush(opts.Presented)
638638 }
@@ -579,7 +579,7 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
579 continue579 continue
580 }580 }
581 if shot == nil {581 if shot == nil {
582- opts.Log.Debug().Str("component", "headless").Str("output", opts.Name).Int("frame", frame).Msg("screenshot readback unavailable; frame skipped")582+ opts.Log.Debug().Str("output", opts.Name).Int("frame", frame).Msg("screenshot readback unavailable; frame skipped")
583 continue583 continue
584 }584 }
585 if opts.Cursor != nil {585 if opts.Cursor != nil {
@@ -595,7 +595,7 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
595 return fmt.Errorf("latest screenshot: %w", err)595 return fmt.Errorf("latest screenshot: %w", err)
596 }596 }
597 }597 }
598- opts.Log.Debug().Str("component", "render").Int("frame", frame).Uint64("seq", scene.Seq).Int("windows", len(scene.Windows)).Dur("ms", time.Since(start)).Msg("frame")598+ opts.Log.Debug().Int("frame", frame).Uint64("seq", scene.Seq).Int("windows", len(scene.Windows)).Dur("ms", time.Since(start)).Msg("frame")
599 }599 }
600 }600 }
601 601
@@ -632,7 +632,7 @@ func (opts Options) report(q *presented.Queue, flip *ports.FlipInfo, seen map[po
632 return632 return
633 }633 }
634 if q.Push(ports.OutputPresented{Output: opts.Name, Flip: flip, Seen: seen}) {634 if q.Push(ports.OutputPresented{Output: opts.Name, Flip: flip, Seen: seen}) {
635- opts.Log.Warn().Str("component", "render").Str("output", opts.Name).Msg("wayland is not reading output reports; flips merged")635+ opts.Log.Warn().Str("output", opts.Name).Msg("wayland is not reading output reports; flips merged")
636 }636 }
637 q.Flush(opts.Presented)637 q.Flush(opts.Presented)
638 }638 }
M internal/adapters/libinput/forward.go +2 -2
@@ -65,7 +65,7 @@ func (f *forwarder) push(ev ports.InputEvent) {
6565 f.queue = append(f.queue, ev)
6666 if len(f.queue) > forwardWarn && !f.long {
6767 f.long = true
68- f.log.Warn().Str("component", "input").Int("queued", len(f.queue)).Msg("core is not reading input; events queue up")
68+ f.log.Warn().Int("queued", len(f.queue)).Msg("core is not reading input; events queue up")
6969 }
7070 f.mu.Unlock()
7171 select {
@@ -97,7 +97,7 @@ func (f *forwarder) pop() (ports.InputEvent, bool) {
9797 f.queue = f.queue[1:]
9898 if f.long && len(f.queue) < forwardWarn {
9999 f.long = false
100- f.log.Warn().Str("component", "input").Int("queued", len(f.queue)).Msg("input queue drained")
100+ f.log.Warn().Int("queued", len(f.queue)).Msg("input queue drained")
101101 }
102102 return ev, true
103103 }
@@ -65,7 +65,7 @@ func (f *forwarder) push(ev ports.InputEvent) {
65 f.queue = append(f.queue, ev)65 f.queue = append(f.queue, ev)
66 if len(f.queue) > forwardWarn && !f.long {66 if len(f.queue) > forwardWarn && !f.long {
67 f.long = true67 f.long = true
68- f.log.Warn().Str("component", "input").Int("queued", len(f.queue)).Msg("core is not reading input; events queue up")68+ f.log.Warn().Int("queued", len(f.queue)).Msg("core is not reading input; events queue up")
69 }69 }
70 f.mu.Unlock()70 f.mu.Unlock()
71 select {71 select {
@@ -97,7 +97,7 @@ func (f *forwarder) pop() (ports.InputEvent, bool) {
97 f.queue = f.queue[1:]97 f.queue = f.queue[1:]
98 if f.long && len(f.queue) < forwardWarn {98 if f.long && len(f.queue) < forwardWarn {
99 f.long = false99 f.long = false
100- f.log.Warn().Str("component", "input").Int("queued", len(f.queue)).Msg("input queue drained")100+ f.log.Warn().Int("queued", len(f.queue)).Msg("input queue drained")
101 }101 }
102 return ev, true102 return ev, true
103 }103 }
M internal/adapters/libinput/libinput.go +2 -2
@@ -642,11 +642,11 @@ func translateKeyboard(code uint32, pressed bool, t time.Duration, opts Options,
642642 // to core for the locker. VT switching is allowed and does not release the lock.
643643 func translateKey(ke ports.KeyEvent, opts Options, security ports.SecurityState) (ports.InputEvent, error) {
644644 if opts.LogKeys && !security.Protected {
645- opts.Log.Debug().Str("component", "input").Uint32("code", ke.Keycode).Str("keysym", ke.Keysym).Bool("pressed", ke.Pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")
645+ opts.Log.Debug().Uint32("code", ke.Keycode).Str("keysym", ke.Keysym).Bool("pressed", ke.Pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")
646646 }
647647 switch action, vt := hotkey(ke, security.Protected); action {
648648 case hotkeyQuit:
649- opts.Log.Warn().Str("component", "input").Str("reason", "emergency-key").Msg("quit")
649+ opts.Log.Warn().Str("reason", "emergency-key").Msg("quit")
650650 return nil, ErrEmergencyQuit
651651 case hotkeyVT:
652652 opts.Seat.SwitchVT(vt)
@@ -642,11 +642,11 @@ func translateKeyboard(code uint32, pressed bool, t time.Duration, opts Options,
642 // to core for the locker. VT switching is allowed and does not release the lock.642 // to core for the locker. VT switching is allowed and does not release the lock.
643 func translateKey(ke ports.KeyEvent, opts Options, security ports.SecurityState) (ports.InputEvent, error) {643 func translateKey(ke ports.KeyEvent, opts Options, security ports.SecurityState) (ports.InputEvent, error) {
644 if opts.LogKeys && !security.Protected {644 if opts.LogKeys && !security.Protected {
645- opts.Log.Debug().Str("component", "input").Uint32("code", ke.Keycode).Str("keysym", ke.Keysym).Bool("pressed", ke.Pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")645+ opts.Log.Debug().Uint32("code", ke.Keycode).Str("keysym", ke.Keysym).Bool("pressed", ke.Pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")
646 }646 }
647 switch action, vt := hotkey(ke, security.Protected); action {647 switch action, vt := hotkey(ke, security.Protected); action {
648 case hotkeyQuit:648 case hotkeyQuit:
649- opts.Log.Warn().Str("component", "input").Str("reason", "emergency-key").Msg("quit")649+ opts.Log.Warn().Str("reason", "emergency-key").Msg("quit")
650 return nil, ErrEmergencyQuit650 return nil, ErrEmergencyQuit
651 case hotkeyVT:651 case hotkeyVT:
652 opts.Seat.SwitchVT(vt)652 opts.Seat.SwitchVT(vt)
M internal/adapters/sched/sched.go +1 -1
@@ -20,7 +20,7 @@ func Realtime(log zerowrap.Logger) error {
2020 }, 0)
2121 if errors.Is(err, unix.EPERM) {
2222 unavailable.Do(func() {
23- log.Info().Str("component", "sched").Msg("realtime scheduling unavailable, grant CAP_SYS_NICE")
23+ log.Info().Msg("realtime scheduling unavailable, grant CAP_SYS_NICE")
2424 })
2525 return nil
2626 }
@@ -20,7 +20,7 @@ func Realtime(log zerowrap.Logger) error {
20 }, 0)20 }, 0)
21 if errors.Is(err, unix.EPERM) {21 if errors.Is(err, unix.EPERM) {
22 unavailable.Do(func() {22 unavailable.Do(func() {
23- log.Info().Str("component", "sched").Msg("realtime scheduling unavailable, grant CAP_SYS_NICE")23+ log.Info().Msg("realtime scheduling unavailable, grant CAP_SYS_NICE")
24 })24 })
25 return nil25 return nil
26 }26 }
M internal/adapters/wayland/colormanagement.go +2 -2
@@ -196,7 +196,7 @@ func (h *colorSurface) SetImageDescription(r *cm.WpColorManagementSurfaceV1, des
196196 return
197197 }
198198 h.surf.next.color = d.SurfaceColor
199- h.surf.server.log.Debug().Str("component", "wayland").Uint32("tf", d.TF).Uint32("primaries", d.Primaries).Msg("surface color description set")
199+ h.surf.server.log.Debug().Uint32("tf", d.TF).Uint32("primaries", d.Primaries).Msg("surface color description set")
200200 }
201201 func (h *colorSurface) UnsetImageDescription(r *cm.WpColorManagementSurfaceV1) {
202202 if h.surf == nil || h.surf.destroyed {
@@ -204,7 +204,7 @@ func (h *colorSurface) UnsetImageDescription(r *cm.WpColorManagementSurfaceV1) {
204204 return
205205 }
206206 h.surf.next.color = SurfaceColor{}
207- h.surf.server.log.Debug().Str("component", "wayland").Msg("surface color description unset")
207+ h.surf.server.log.Debug().Msg("surface color description unset")
208208 }
209209
210210 type colorFeedback struct {
@@ -196,7 +196,7 @@ func (h *colorSurface) SetImageDescription(r *cm.WpColorManagementSurfaceV1, des
196 return196 return
197 }197 }
198 h.surf.next.color = d.SurfaceColor198 h.surf.next.color = d.SurfaceColor
199- h.surf.server.log.Debug().Str("component", "wayland").Uint32("tf", d.TF).Uint32("primaries", d.Primaries).Msg("surface color description set")199+ h.surf.server.log.Debug().Uint32("tf", d.TF).Uint32("primaries", d.Primaries).Msg("surface color description set")
200 }200 }
201 func (h *colorSurface) UnsetImageDescription(r *cm.WpColorManagementSurfaceV1) {201 func (h *colorSurface) UnsetImageDescription(r *cm.WpColorManagementSurfaceV1) {
202 if h.surf == nil || h.surf.destroyed {202 if h.surf == nil || h.surf.destroyed {
@@ -204,7 +204,7 @@ func (h *colorSurface) UnsetImageDescription(r *cm.WpColorManagementSurfaceV1) {
204 return204 return
205 }205 }
206 h.surf.next.color = SurfaceColor{}206 h.surf.next.color = SurfaceColor{}
207- h.surf.server.log.Debug().Str("component", "wayland").Msg("surface color description unset")207+ h.surf.server.log.Debug().Msg("surface color description unset")
208 }208 }
209 209
210 type colorFeedback struct {210 type colorFeedback struct {
M internal/adapters/wayland/fifo.go +1 -1
@@ -356,7 +356,7 @@ func (s *surface) queueUpdate() {
356356 if err != nil {
357357 // Partial registrations were cancelled; discard this update.
358358 u.failed = true
359- s.server.log.Warn().Str("component", "wayland").Err(err).Msg("implicit buffer wait")
359+ s.server.log.Warn().Err(err).Msg("implicit buffer wait")
360360 }
361361 }
362362 }
@@ -356,7 +356,7 @@ func (s *surface) queueUpdate() {
356 if err != nil {356 if err != nil {
357 // Partial registrations were cancelled; discard this update.357 // Partial registrations were cancelled; discard this update.
358 u.failed = true358 u.failed = true
359- s.server.log.Warn().Str("component", "wayland").Err(err).Msg("implicit buffer wait")359+ s.server.log.Warn().Err(err).Msg("implicit buffer wait")
360 }360 }
361 }361 }
362 }362 }
M internal/adapters/wayland/outputs.go +4 -5
@@ -152,7 +152,7 @@ func (s *Server) addOutput(p ports.OutputPlacement) {
152152 }
153153 o.global = g
154154 s.outputs = append(s.outputs, o)
155- s.log.Info().Str("output", p.Info.Name).Int("x", p.X).Int("w", p.Width).Int("h", p.Height).Float64("scale", p.Scale).Msg("output added")
155+ s.log.Info().Str("output", p.Info.Name).Int("x", p.X).Int("y", p.Y).Int("w", p.Width).Int("h", p.Height).Float64("scale", p.Scale).Msg("output added")
156156 }
157157
158158 // setOutputs applies the global layout from core: new outputs are
@@ -208,10 +208,12 @@ func (s *Server) setOutputs(c ports.SetOutputs) {
208208 if o.place == p {
209209 continue
210210 }
211- scaleChanged := o.place.Scale != p.Scale
212211 // A 90° to 270° change keeps the logical size: lock surfaces are
213212 // logical-sized and need no reconfigure then.
214213 logicalChanged := o.place.Width != p.Width || o.place.Height != p.Height
214+ // The first layout from core moves an output off the placement it was
215+ // added with, so this line carries the real position.
216+ s.log.Info().Str("output", p.Info.Name).Int("x", p.X).Int("y", p.Y).Int("w", p.Width).Int("h", p.Height).Float64("scale", p.Scale).Int("transform", int(p.Transform)).Bool("primary", p.Primary).Msg("output changed")
215217 o.place = p
216218 if logicalChanged {
217219 for _, l := range s.lockSurfaces {
@@ -233,9 +235,6 @@ func (s *Server) setOutputs(c ports.SetOutputs) {
233235 x.SendDone()
234236 }
235237 }
236- if scaleChanged {
237- s.log.Info().Str("output", p.Info.Name).Float64("scale", p.Scale).Int("w", p.Width).Int("h", p.Height).Msg("output scale")
238- }
239238 }
240239 // Surfaces follow the scale of their output.
241240 for _, surf := range s.surfaces {
@@ -152,7 +152,7 @@ func (s *Server) addOutput(p ports.OutputPlacement) {
152 }152 }
153 o.global = g153 o.global = g
154 s.outputs = append(s.outputs, o)154 s.outputs = append(s.outputs, o)
155- s.log.Info().Str("output", p.Info.Name).Int("x", p.X).Int("w", p.Width).Int("h", p.Height).Float64("scale", p.Scale).Msg("output added")155+ s.log.Info().Str("output", p.Info.Name).Int("x", p.X).Int("y", p.Y).Int("w", p.Width).Int("h", p.Height).Float64("scale", p.Scale).Msg("output added")
156 }156 }
157 157
158 // setOutputs applies the global layout from core: new outputs are158 // setOutputs applies the global layout from core: new outputs are
@@ -208,10 +208,12 @@ func (s *Server) setOutputs(c ports.SetOutputs) {
208 if o.place == p {208 if o.place == p {
209 continue209 continue
210 }210 }
211- scaleChanged := o.place.Scale != p.Scale
212 // A 90° to 270° change keeps the logical size: lock surfaces are211 // A 90° to 270° change keeps the logical size: lock surfaces are
213 // logical-sized and need no reconfigure then.212 // logical-sized and need no reconfigure then.
214 logicalChanged := o.place.Width != p.Width || o.place.Height != p.Height213 logicalChanged := o.place.Width != p.Width || o.place.Height != p.Height
214+ // The first layout from core moves an output off the placement it was
215+ // added with, so this line carries the real position.
216+ s.log.Info().Str("output", p.Info.Name).Int("x", p.X).Int("y", p.Y).Int("w", p.Width).Int("h", p.Height).Float64("scale", p.Scale).Int("transform", int(p.Transform)).Bool("primary", p.Primary).Msg("output changed")
215 o.place = p217 o.place = p
216 if logicalChanged {218 if logicalChanged {
217 for _, l := range s.lockSurfaces {219 for _, l := range s.lockSurfaces {
@@ -233,9 +235,6 @@ func (s *Server) setOutputs(c ports.SetOutputs) {
233 x.SendDone()235 x.SendDone()
234 }236 }
235 }237 }
236- if scaleChanged {
237- s.log.Info().Str("output", p.Info.Name).Float64("scale", p.Scale).Int("w", p.Width).Int("h", p.Height).Msg("output scale")
238- }
239 }238 }
240 // Surfaces follow the scale of their output.239 // Surfaces follow the scale of their output.
241 for _, surf := range s.surfaces {240 for _, surf := range s.surfaces {
A internal/adapters/wayland/outputs_log_test.go +30 -0
@@ -0,0 +1,30 @@
1+package wayland
2+
3+import (
4+ "strings"
5+ "testing"
6+
7+ "github.com/bnema/neferwl/internal/ports"
8+ "github.com/bnema/zerowrap"
9+)
10+
11+// The layout from core moves outputs after they were added at the startup
12+// placement: the log must show the real position.
13+func TestSetOutputsLogsPlacementChange(t *testing.T) {
14+ var out lockedBuffer
15+ log := zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &out}).WithField("component", "wayland")
16+ h := newAdmissionHarnessWith(t, 1, Options{}, log)
17+ if added := out.String(); !strings.Contains(added, `"message":"output added"`) || !strings.Contains(added, `"x":0,"y":0`) {
18+ t.Fatalf("output added: %s", added)
19+ }
20+ placed := ports.Layout{{Info: ports.OutputInfo{Name: "HEADLESS-1", Width: 2, Height: 2}, X: 3200, Y: 40, Width: 2, Height: 2, Scale: 1, Primary: true}}
21+ h.s.display.Do(func() { h.s.setOutputs(ports.SetOutputs{Outputs: placed}) })
22+ if got := out.String(); !strings.Contains(got, `"message":"output changed"`) || !strings.Contains(got, `"x":3200,"y":40`) || !strings.Contains(got, `"primary":true`) || !strings.Contains(got, `"transform":0`) {
23+ t.Fatalf("placement change not logged: %s", got)
24+ }
25+ n := strings.Count(out.String(), `"output changed"`)
26+ h.s.display.Do(func() { h.s.setOutputs(ports.SetOutputs{Outputs: placed}) })
27+ if strings.Count(out.String(), `"output changed"`) != n {
28+ t.Fatalf("unchanged layout logged: %s", out.String())
29+ }
30+}
@@ -0,0 +1,30 @@
1+package wayland
2+
3+import (
4+ "strings"
5+ "testing"
6+
7+ "github.com/bnema/neferwl/internal/ports"
8+ "github.com/bnema/zerowrap"
9+)
10+
11+// The layout from core moves outputs after they were added at the startup
12+// placement: the log must show the real position.
13+func TestSetOutputsLogsPlacementChange(t *testing.T) {
14+ var out lockedBuffer
15+ log := zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &out}).WithField("component", "wayland")
16+ h := newAdmissionHarnessWith(t, 1, Options{}, log)
17+ if added := out.String(); !strings.Contains(added, `"message":"output added"`) || !strings.Contains(added, `"x":0,"y":0`) {
18+ t.Fatalf("output added: %s", added)
19+ }
20+ placed := ports.Layout{{Info: ports.OutputInfo{Name: "HEADLESS-1", Width: 2, Height: 2}, X: 3200, Y: 40, Width: 2, Height: 2, Scale: 1, Primary: true}}
21+ h.s.display.Do(func() { h.s.setOutputs(ports.SetOutputs{Outputs: placed}) })
22+ if got := out.String(); !strings.Contains(got, `"message":"output changed"`) || !strings.Contains(got, `"x":3200,"y":40`) || !strings.Contains(got, `"primary":true`) || !strings.Contains(got, `"transform":0`) {
23+ t.Fatalf("placement change not logged: %s", got)
24+ }
25+ n := strings.Count(out.String(), `"output changed"`)
26+ h.s.display.Do(func() { h.s.setOutputs(ports.SetOutputs{Outputs: placed}) })
27+ if strings.Count(out.String(), `"output changed"`) != n {
28+ t.Fatalf("unchanged layout logged: %s", out.String())
29+ }
30+}
M internal/adapters/wayland/scale.go +1 -1
@@ -285,7 +285,7 @@ func (s *surface) validateViewport(bw, bh int) bool {
285285 if s.current != nil {
286286 bufferID = s.current.ID()
287287 }
288- s.server.log.Warn().Str("component", "wayland").Uint32("surface", surfaceID).Uint32("viewport", viewportID).
288+ s.server.log.Warn().Uint32("surface", surfaceID).Uint32("viewport", viewportID).
289289 Bool("fresh", s.commitFresh).Bool("retained", !s.commitFresh).Bool("skipped_destroyed", s.commitSkipped).
290290 Uint32("buffer", bufferID).Uint32("queued_buffer", s.queuedBuffer).Int("buffer_width", bw).Int("buffer_height", bh).
291291 Int("committed_scale", s.bufferScale).Int("queued_scale", s.queuedScale).
@@ -285,7 +285,7 @@ func (s *surface) validateViewport(bw, bh int) bool {
285 if s.current != nil {285 if s.current != nil {
286 bufferID = s.current.ID()286 bufferID = s.current.ID()
287 }287 }
288- s.server.log.Warn().Str("component", "wayland").Uint32("surface", surfaceID).Uint32("viewport", viewportID).288+ s.server.log.Warn().Uint32("surface", surfaceID).Uint32("viewport", viewportID).
289 Bool("fresh", s.commitFresh).Bool("retained", !s.commitFresh).Bool("skipped_destroyed", s.commitSkipped).289 Bool("fresh", s.commitFresh).Bool("retained", !s.commitFresh).Bool("skipped_destroyed", s.commitSkipped).
290 Uint32("buffer", bufferID).Uint32("queued_buffer", s.queuedBuffer).Int("buffer_width", bw).Int("buffer_height", bh).290 Uint32("buffer", bufferID).Uint32("queued_buffer", s.queuedBuffer).Int("buffer_width", bw).Int("buffer_height", bh).
291 Int("committed_scale", s.bufferScale).Int("queued_scale", s.queuedScale).291 Int("committed_scale", s.bufferScale).Int("queued_scale", s.queuedScale).
M internal/adapters/wayland/server.go +1 -1
@@ -373,7 +373,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) {
373373 }
374374 } else if opts.SyncobjNode != "" {
375375 if node, err = openSyncobj(opts.SyncobjNode); err != nil {
376- log.Info().Str("component", "wayland").Err(err).Msg("explicit sync off")
376+ log.Info().Err(err).Msg("explicit sync off")
377377 node = nil
378378 } else if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil {
379379 node.close()
@@ -373,7 +373,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) {
373 }373 }
374 } else if opts.SyncobjNode != "" {374 } else if opts.SyncobjNode != "" {
375 if node, err = openSyncobj(opts.SyncobjNode); err != nil {375 if node, err = openSyncobj(opts.SyncobjNode); err != nil {
376- log.Info().Str("component", "wayland").Err(err).Msg("explicit sync off")376+ log.Info().Err(err).Msg("explicit sync off")
377 node = nil377 node = nil
378 } else if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil {378 } else if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil {
379 node.close()379 node.close()
M internal/adapters/wayland/surface.go +1 -1
@@ -387,7 +387,7 @@ func (s *surface) applyCommit(u *update) {
387387 }
388388 if s.contentKind != u.kind {
389389 s.contentKind = u.kind
390- s.server.log.Info().Str("component", "wayland").Uint64("id", uint64(s.root().windowID())).Uint32("content_type", s.contentKind).Msg("content type")
390+ s.server.log.Info().Uint64("id", uint64(s.root().windowID())).Uint32("content_type", s.contentKind).Msg("content type")
391391 }
392392 if u.scale > 0 {
393393 s.bufferScale = u.scale
@@ -387,7 +387,7 @@ func (s *surface) applyCommit(u *update) {
387 }387 }
388 if s.contentKind != u.kind {388 if s.contentKind != u.kind {
389 s.contentKind = u.kind389 s.contentKind = u.kind
390- s.server.log.Info().Str("component", "wayland").Uint64("id", uint64(s.root().windowID())).Uint32("content_type", s.contentKind).Msg("content type")390+ s.server.log.Info().Uint64("id", uint64(s.root().windowID())).Uint32("content_type", s.contentKind).Msg("content type")
391 }391 }
392 if u.scale > 0 {392 if u.scale > 0 {
393 s.bufferScale = u.scale393 s.bufferScale = u.scale
M internal/adapters/wayland/syncobj.go +4 -4
@@ -308,7 +308,7 @@ func (sw *syncWaiter) watchImplicit(b *ports.DMABuf, waits *[4]*syncWait) error
308308
309309 func (sw *syncWaiter) warnPollError() {
310310 sw.pollError.Do(func() {
311- sw.log.Warn().Str("component", "wayland").Msg("implicit fence poll error")
311+ sw.log.Warn().Msg("implicit fence poll error")
312312 })
313313 }
314314
@@ -464,7 +464,7 @@ func (s *Server) releaseSync(h syncHold) {
464464 }
465465 if h.release.set() {
466466 if err := h.release.tl.dev.signal(h.release.tl.handle, h.release.point); err != nil {
467- s.log.Warn().Str("component", "wayland").Err(err).Msg("release point")
467+ s.log.Warn().Err(err).Msg("release point")
468468 }
469469 h.release.tl.uses--
470470 s.dropTimeline(h.release.tl)
@@ -495,7 +495,7 @@ func (s *surface) takeSyncPoints() {
495495 if err != nil {
496496 // Keep points owned by the captured commit for safe discard. An
497497 // unobservable acquire must never reach native rendering.
498- s.server.log.Warn().Str("component", "wayland").Err(err).Msg("acquire point")
498+ s.server.log.Warn().Err(err).Msg("acquire point")
499499 }
500500 cs.wait = w
501501 s.next.sync = cs
@@ -542,7 +542,7 @@ func (s *surface) prepareSync(cs *commitSync) bool {
542542 if f != nil {
543543 f.Close()
544544 }
545- s.server.log.Warn().Str("component", "wayland").Err(err).Msg("acquire fence export rejected")
545+ s.server.log.Warn().Err(err).Msg("acquire fence export rejected")
546546 return false
547547 }
548548 cs.fence = f
@@ -308,7 +308,7 @@ func (sw *syncWaiter) watchImplicit(b *ports.DMABuf, waits *[4]*syncWait) error
308 308
309 func (sw *syncWaiter) warnPollError() {309 func (sw *syncWaiter) warnPollError() {
310 sw.pollError.Do(func() {310 sw.pollError.Do(func() {
311- sw.log.Warn().Str("component", "wayland").Msg("implicit fence poll error")311+ sw.log.Warn().Msg("implicit fence poll error")
312 })312 })
313 }313 }
314 314
@@ -464,7 +464,7 @@ func (s *Server) releaseSync(h syncHold) {
464 }464 }
465 if h.release.set() {465 if h.release.set() {
466 if err := h.release.tl.dev.signal(h.release.tl.handle, h.release.point); err != nil {466 if err := h.release.tl.dev.signal(h.release.tl.handle, h.release.point); err != nil {
467- s.log.Warn().Str("component", "wayland").Err(err).Msg("release point")467+ s.log.Warn().Err(err).Msg("release point")
468 }468 }
469 h.release.tl.uses--469 h.release.tl.uses--
470 s.dropTimeline(h.release.tl)470 s.dropTimeline(h.release.tl)
@@ -495,7 +495,7 @@ func (s *surface) takeSyncPoints() {
495 if err != nil {495 if err != nil {
496 // Keep points owned by the captured commit for safe discard. An496 // Keep points owned by the captured commit for safe discard. An
497 // unobservable acquire must never reach native rendering.497 // unobservable acquire must never reach native rendering.
498- s.server.log.Warn().Str("component", "wayland").Err(err).Msg("acquire point")498+ s.server.log.Warn().Err(err).Msg("acquire point")
499 }499 }
500 cs.wait = w500 cs.wait = w
501 s.next.sync = cs501 s.next.sync = cs
@@ -542,7 +542,7 @@ func (s *surface) prepareSync(cs *commitSync) bool {
542 if f != nil {542 if f != nil {
543 f.Close()543 f.Close()
544 }544 }
545- s.server.log.Warn().Str("component", "wayland").Err(err).Msg("acquire fence export rejected")545+ s.server.log.Warn().Err(err).Msg("acquire fence export rejected")
546 return false546 return false
547 }547 }
548 cs.fence = f548 cs.fence = f
M internal/app/app.go +3 -2
@@ -198,8 +198,9 @@ func run(ctx context.Context, opts Options, inject func(chan<- ports.InputEvent)
198198 if opts.Config.Performance.Realtime {
199199 runtime.LockOSThread()
200200 // Let this dedicated thread exit with its scheduling policy.
201- if err := sched.Realtime(logging.For(ctx, "sched")); err != nil {
202- log.Warn().Str("component", "sched").Err(err).Msg("input scheduling")
201+ schedLog := logging.For(ctx, "sched")
202+ if err := sched.Realtime(schedLog); err != nil {
203+ schedLog.Warn().Err(err).Msg("input scheduling")
203204 }
204205 }
205206 return libinput.Run(ctx, libinput.Options{
@@ -198,8 +198,9 @@ func run(ctx context.Context, opts Options, inject func(chan<- ports.InputEvent)
198 if opts.Config.Performance.Realtime {198 if opts.Config.Performance.Realtime {
199 runtime.LockOSThread()199 runtime.LockOSThread()
200 // Let this dedicated thread exit with its scheduling policy.200 // Let this dedicated thread exit with its scheduling policy.
201- if err := sched.Realtime(logging.For(ctx, "sched")); err != nil {201+ schedLog := logging.For(ctx, "sched")
202- log.Warn().Str("component", "sched").Err(err).Msg("input scheduling")202+ if err := sched.Realtime(schedLog); err != nil {
203+ schedLog.Warn().Err(err).Msg("input scheduling")
203 }204 }
204 }205 }
205 return libinput.Run(ctx, libinput.Options{206 return libinput.Run(ctx, libinput.Options{
M internal/app/drm.go +5 -4
@@ -170,7 +170,7 @@ func (b *drmBackend) prepareSeatDisable() {
170170 }
171171 wg.Wait()
172172 if n := late.Load(); n > 0 {
173- b.log.Warn().Str("component", "drm").Int("outputs", int(n)).Dur("timeout", seatDisableTimeout).Msg("outputs did not prepare for the seat disable in time; disabling anyway")
173+ b.log.Warn().Int("outputs", int(n)).Dur("timeout", seatDisableTimeout).Msg("outputs did not prepare for the seat disable in time; disabling anyway")
174174 }
175175 }
176176
@@ -231,7 +231,7 @@ func openDRM(ctx context.Context, cfg ports.Config) (*drmBackend, error) {
231231 errs = append(errs, err)
232232 continue
233233 }
234- card, err := drm.OpenCard(fd, path, want, log)
234+ card, err := drm.OpenCard(fd, path, want, log, logging.For(ctx, "render"))
235235 if err != nil {
236236 log.Warn().Err(err).Str("card", path).Msg("card unusable")
237237 errs = append(errs, err)
@@ -547,8 +547,9 @@ func (b *drmBackend) runOutputs(ctx context.Context, want func(ports.Config) drm
547547 runtime.LockOSThread()
548548 // Keep the thread locked until this goroutine exits: an RT
549549 // thread must not return to Go's general-purpose pool.
550- if err := sched.Realtime(log); err != nil {
551- log.Warn().Str("component", "sched").Err(err).Msg("output scheduling")
550+ schedLog := logging.For(ctx, "sched")
551+ if err := sched.Realtime(schedLog); err != nil {
552+ schedLog.Warn().Err(err).Msg("output scheduling")
552553 }
553554 }
554555 return o.Run(octx, newRenderer, loadCursor, active, sc, cc, cu, ch.presented, cap, ch.captured)
@@ -170,7 +170,7 @@ func (b *drmBackend) prepareSeatDisable() {
170 }170 }
171 wg.Wait()171 wg.Wait()
172 if n := late.Load(); n > 0 {172 if n := late.Load(); n > 0 {
173- b.log.Warn().Str("component", "drm").Int("outputs", int(n)).Dur("timeout", seatDisableTimeout).Msg("outputs did not prepare for the seat disable in time; disabling anyway")173+ b.log.Warn().Int("outputs", int(n)).Dur("timeout", seatDisableTimeout).Msg("outputs did not prepare for the seat disable in time; disabling anyway")
174 }174 }
175 }175 }
176 176
@@ -231,7 +231,7 @@ func openDRM(ctx context.Context, cfg ports.Config) (*drmBackend, error) {
231 errs = append(errs, err)231 errs = append(errs, err)
232 continue232 continue
233 }233 }
234- card, err := drm.OpenCard(fd, path, want, log)234+ card, err := drm.OpenCard(fd, path, want, log, logging.For(ctx, "render"))
235 if err != nil {235 if err != nil {
236 log.Warn().Err(err).Str("card", path).Msg("card unusable")236 log.Warn().Err(err).Str("card", path).Msg("card unusable")
237 errs = append(errs, err)237 errs = append(errs, err)
@@ -547,8 +547,9 @@ func (b *drmBackend) runOutputs(ctx context.Context, want func(ports.Config) drm
547 runtime.LockOSThread()547 runtime.LockOSThread()
548 // Keep the thread locked until this goroutine exits: an RT548 // Keep the thread locked until this goroutine exits: an RT
549 // thread must not return to Go's general-purpose pool.549 // thread must not return to Go's general-purpose pool.
550- if err := sched.Realtime(log); err != nil {550+ schedLog := logging.For(ctx, "sched")
551- log.Warn().Str("component", "sched").Err(err).Msg("output scheduling")551+ if err := sched.Realtime(schedLog); err != nil {
552+ schedLog.Warn().Err(err).Msg("output scheduling")
552 }553 }
553 }554 }
554 return o.Run(octx, newRenderer, loadCursor, active, sc, cc, cu, ch.presented, cap, ch.captured)555 return o.Run(octx, newRenderer, loadCursor, active, sc, cc, cu, ch.presented, cap, ch.captured)
M internal/logging/logging.go +1 -1
@@ -18,7 +18,7 @@ import (
1818 var components = map[string]bool{
1919 "core": true, "wayland": true, "input": true, "drm": true, "seat": true,
2020 "render": true, "sync": true, "config": true, "app": true,
21- "screensaver": true,
21+ "screensaver": true, "sched": true,
2222 }
2323
2424 // categories are debug switches narrower than a component, only on when
@@ -18,7 +18,7 @@ import (
18 var components = map[string]bool{18 var components = map[string]bool{
19 "core": true, "wayland": true, "input": true, "drm": true, "seat": true,19 "core": true, "wayland": true, "input": true, "drm": true, "seat": true,
20 "render": true, "sync": true, "config": true, "app": true,20 "render": true, "sync": true, "config": true, "app": true,
21- "screensaver": true,21+ "screensaver": true, "sched": true,
22 }22 }
23 23
24 // categories are debug switches narrower than a component, only on when24 // categories are debug switches narrower than a component, only on when

Keyboard shortcuts

Single-key shortcuts are on. ctrl k and esc work whatever this says.

ctrl k :
go to a section, branch, tag, file or repository
?
this list
j k
move the row cursor down / up
enter
open the row under the cursor; on Files, a directory opens or closes in place
↑ ↓ ← → home end
in the file tree (focus on a row): previous / next row, close / open a directory or go to its parent / first entry, first / last row. They never open a file
l h
on Files: open a directory or a file / close a directory or go up to its parent, then to the parent page. Elsewhere: into the side panel (on a merge request, its files) / back to the content; there j k move between its controls
g g G
first / last row
/
filter the list; on Files, find a file anywhere in the repository (esc clears, enter opens the best match)
b
switch branch or tag
g s g f g c g b g m g i g r g a
tabs: summary, files, commits, branches & tags, merge requests, issues, releases, actions (when available)
g h
home
w
wide mode: use the whole width of the screen, or not (remembered)
y
copy a permalink pinned to the commit
d u x
diff: split / unified / collapse or expand all
e E
diff: the whole file in view / every file, with the lines the hunks hide
n
merge request: next note in the diff
esc
close a dialog, leave a field

Branches 25

Tags 10

↑↓ moveenter openesc close