Merge remote-tracking branch 'origin/main' into fix/bracketed-paste-marker-splits
# Conflicts: # internal/app/run.go # internal/app/run_test.go # internal/usecase/client/client.go # internal/usecase/client/client_test.go
26 files · +1111 -130
M AGENTS.md +1 -0
| @@ -19,6 +19,7 @@ go test ./pkg/renderer ./pkg/vt ./internal/adapters/ipc -bench=. -benchmem # m | |||
| 19 | 19 | ||
| 20 | 20 | - Format with **goimports**, not gofmt — lint enforces it. | |
| 21 | 21 | - Daemon pprof is opt-in via `VEV_PPROF_ADDR=127.0.0.1:6060 vev --daemon` (see `docs/performance.md`). | |
| 22 | + | - Live logs are under `$XDG_STATE_HOME/vev` (or `~/.local/state/vev` when `XDG_STATE_HOME` is unset): `vev-daemon.log`, `vev-client.log`, `vev-stdio.log`, plus matching `*-crash.log` files. | |
| 22 | 23 | - Feature branches live in git worktrees under `.worktrees/<branch-name>`. | |
| 23 | 24 | ||
| 24 | 25 | ## Architecture | |
| @@ -19,6 +19,7 @@ go test ./pkg/renderer ./pkg/vt ./internal/adapters/ipc -bench=. -benchmem # m | |||||
| 19 | 19 | ||||
| 20 | - Format with **goimports**, not gofmt — lint enforces it. | 20 | - Format with **goimports**, not gofmt — lint enforces it. | ||
| 21 | - Daemon pprof is opt-in via `VEV_PPROF_ADDR=127.0.0.1:6060 vev --daemon` (see `docs/performance.md`). | 21 | - Daemon pprof is opt-in via `VEV_PPROF_ADDR=127.0.0.1:6060 vev --daemon` (see `docs/performance.md`). | ||
| 22 | + | - Live logs are under `$XDG_STATE_HOME/vev` (or `~/.local/state/vev` when `XDG_STATE_HOME` is unset): `vev-daemon.log`, `vev-client.log`, `vev-stdio.log`, plus matching `*-crash.log` files. | |||
| 22 | - Feature branches live in git worktrees under `.worktrees/<branch-name>`. | 23 | - Feature branches live in git worktrees under `.worktrees/<branch-name>`. | ||
| 23 | 24 | ||||
| 24 | ## Architecture | 25 | ## Architecture | ||
M internal/adapters/dgram/ssh_dialer.go +7 -1
| @@ -2,6 +2,7 @@ package dgram | |||
| 2 | 2 | ||
| 3 | 3 | import ( | |
| 4 | 4 | "context" | |
| 5 | + | "log/slog" | |
| 5 | 6 | "net" | |
| 6 | 7 | "strings" | |
| 7 | 8 | "time" | |
| @@ -35,12 +36,17 @@ type RemoteDialer struct { | |||
| 35 | 36 | Target string | |
| 36 | 37 | Session string | |
| 37 | 38 | ProbeTimeout time.Duration | |
| 39 | + | Log *slog.Logger | |
| 38 | 40 | } | |
| 39 | 41 | ||
| 40 | 42 | func NewRemoteDialer(target, session string) RemoteDialer { | |
| 41 | 43 | return RemoteDialer{Target: target, Session: session, ProbeTimeout: defaultProbeTimeout} | |
| 42 | 44 | } | |
| 43 | 45 | ||
| 46 | + | func NewRemoteDialerWithLogger(target, session string, log *slog.Logger) RemoteDialer { | |
| 47 | + | return RemoteDialer{Target: target, Session: session, ProbeTimeout: defaultProbeTimeout, Log: log} | |
| 48 | + | } | |
| 49 | + | ||
| 44 | 50 | func (d RemoteDialer) Dial(ctx context.Context) (ports.Transport, error) { | |
| 45 | 51 | // The UDP bootstrap currently requires a long-lived remote proxy process. Do | |
| 46 | 52 | // not select it as the app's remote attach path until that process can detach | |
| @@ -50,7 +56,7 @@ func (d RemoteDialer) Dial(ctx context.Context) (ports.Transport, error) { | |||
| 50 | 56 | return nil, ctx.Err() | |
| 51 | 57 | default: | |
| 52 | 58 | } | |
| 53 | - | return sshstdio.DialContext(ctx, d.Target, d.Session) | |
| 59 | + | return sshstdio.DialContext(ctx, d.Target, d.Session, d.Log) | |
| 54 | 60 | } | |
| 55 | 61 | ||
| 56 | 62 | func sshTargetHost(target string) string { | |
| @@ -2,6 +2,7 @@ package dgram | |||||
| 2 | 2 | ||||
| 3 | import ( | 3 | import ( | ||
| 4 | "context" | 4 | "context" | ||
| 5 | + | "log/slog" | |||
| 5 | "net" | 6 | "net" | ||
| 6 | "strings" | 7 | "strings" | ||
| 7 | "time" | 8 | "time" | ||
| @@ -35,12 +36,17 @@ type RemoteDialer struct { | |||||
| 35 | Target string | 36 | Target string | ||
| 36 | Session string | 37 | Session string | ||
| 37 | ProbeTimeout time.Duration | 38 | ProbeTimeout time.Duration | ||
| 39 | + | Log *slog.Logger | |||
| 38 | } | 40 | } | ||
| 39 | 41 | ||||
| 40 | func NewRemoteDialer(target, session string) RemoteDialer { | 42 | func NewRemoteDialer(target, session string) RemoteDialer { | ||
| 41 | return RemoteDialer{Target: target, Session: session, ProbeTimeout: defaultProbeTimeout} | 43 | return RemoteDialer{Target: target, Session: session, ProbeTimeout: defaultProbeTimeout} | ||
| 42 | } | 44 | } | ||
| 43 | 45 | ||||
| 46 | + | func NewRemoteDialerWithLogger(target, session string, log *slog.Logger) RemoteDialer { | |||
| 47 | + | return RemoteDialer{Target: target, Session: session, ProbeTimeout: defaultProbeTimeout, Log: log} | |||
| 48 | + | } | |||
| 49 | + | ||||
| 44 | func (d RemoteDialer) Dial(ctx context.Context) (ports.Transport, error) { | 50 | func (d RemoteDialer) Dial(ctx context.Context) (ports.Transport, error) { | ||
| 45 | // The UDP bootstrap currently requires a long-lived remote proxy process. Do | 51 | // The UDP bootstrap currently requires a long-lived remote proxy process. Do | ||
| 46 | // not select it as the app's remote attach path until that process can detach | 52 | // not select it as the app's remote attach path until that process can detach | ||
| @@ -50,7 +56,7 @@ func (d RemoteDialer) Dial(ctx context.Context) (ports.Transport, error) { | |||||
| 50 | return nil, ctx.Err() | 56 | return nil, ctx.Err() | ||
| 51 | default: | 57 | default: | ||
| 52 | } | 58 | } | ||
| 53 | - | return sshstdio.DialContext(ctx, d.Target, d.Session) | 59 | + | return sshstdio.DialContext(ctx, d.Target, d.Session, d.Log) |
| 54 | } | 60 | } | ||
| 55 | 61 | ||||
| 56 | func sshTargetHost(target string) string { | 62 | func sshTargetHost(target string) string { | ||
M internal/adapters/dgram/transport_test.go +2 -3
| @@ -59,9 +59,8 @@ func (p *fakePC) WriteTo(b []byte, addr net.Addr) (int, error) { | |||
| 59 | 59 | } | |
| 60 | 60 | peer := p.peers[addr.String()] | |
| 61 | 61 | peer.mu.Lock() | |
| 62 | - | peerClosed := peer.closed | |
| 63 | - | peer.mu.Unlock() | |
| 64 | - | if peerClosed { | |
| 62 | + | defer peer.mu.Unlock() | |
| 63 | + | if peer.closed { | |
| 65 | 64 | return 0, errors.New("peer closed") | |
| 66 | 65 | } | |
| 67 | 66 | peer.in <- packet{append([]byte(nil), b...), p.addr} | |
| @@ -59,9 +59,8 @@ func (p *fakePC) WriteTo(b []byte, addr net.Addr) (int, error) { | |||||
| 59 | } | 59 | } | ||
| 60 | peer := p.peers[addr.String()] | 60 | peer := p.peers[addr.String()] | ||
| 61 | peer.mu.Lock() | 61 | peer.mu.Lock() | ||
| 62 | - | peerClosed := peer.closed | 62 | + | defer peer.mu.Unlock() |
| 63 | - | peer.mu.Unlock() | 63 | + | if peer.closed { |
| 64 | - | if peerClosed { | |||
| 65 | return 0, errors.New("peer closed") | 64 | return 0, errors.New("peer closed") | ||
| 66 | } | 65 | } | ||
| 67 | peer.in <- packet{append([]byte(nil), b...), p.addr} | 66 | peer.in <- packet{append([]byte(nil), b...), p.addr} | ||
M internal/adapters/sshstdio/transport.go +21 -4
| @@ -11,6 +11,7 @@ import ( | |||
| 11 | 11 | "errors" | |
| 12 | 12 | "fmt" | |
| 13 | 13 | "io" | |
| 14 | + | "log/slog" | |
| 14 | 15 | "os/exec" | |
| 15 | 16 | "strings" | |
| 16 | 17 | "sync" | |
| @@ -95,7 +96,7 @@ func (t *transport) Recv() (ports.Frame, error) { | |||
| 95 | 96 | ||
| 96 | 97 | func (t *transport) Close() error { return t.close() } | |
| 97 | 98 | ||
| 98 | - | func newProcessCloser(cmd *exec.Cmd, stdin io.Closer, stderr *bytes.Buffer, timeout time.Duration) closeFunc { | |
| 99 | + | func newProcessCloser(cmd *exec.Cmd, stdin io.Closer, stderr *bytes.Buffer, timeout time.Duration, log *slog.Logger, target, session string) closeFunc { | |
| 99 | 100 | return func() error { | |
| 100 | 101 | _ = stdin.Close() | |
| 101 | 102 | ||
| @@ -114,6 +115,13 @@ func newProcessCloser(cmd *exec.Cmd, stdin io.Closer, stderr *bytes.Buffer, time | |||
| 114 | 115 | } | |
| 115 | 116 | ||
| 116 | 117 | stderrText := strings.TrimSpace(stderr.String()) | |
| 118 | + | if log != nil { | |
| 119 | + | attrs := []any{"target", target, "session", session, "err", err} | |
| 120 | + | if stderrText != "" { | |
| 121 | + | attrs = append(attrs, "stderr", stderrText) | |
| 122 | + | } | |
| 123 | + | log.Warn("ssh exited non-cleanly", attrs...) | |
| 124 | + | } | |
| 117 | 125 | if stderrText != "" { | |
| 118 | 126 | return fmt.Errorf("sshstdio: ssh exited: %w: %s", err, stderrText) | |
| 119 | 127 | } | |
| @@ -157,11 +165,17 @@ func Dial(target, session string) (ports.Transport, error) { | |||
| 157 | 165 | } | |
| 158 | 166 | ||
| 159 | 167 | // DialContext is like Dial, but the context is propagated to ssh startup so a | |
| 160 | - | // canceled attach attempt interrupts the local ssh process. | |
| 161 | - | func DialContext(ctx context.Context, target, session string) (ports.Transport, error) { | |
| 168 | + | // canceled attach attempt interrupts the local ssh process. Callers may pass a | |
| 169 | + | // logger to record ssh start failures and non-clean exits without logging the | |
| 170 | + | // generated command line. | |
| 171 | + | func DialContext(ctx context.Context, target, session string, logger ...*slog.Logger) (ports.Transport, error) { | |
| 162 | 172 | if err := ctx.Err(); err != nil { | |
| 163 | 173 | return nil, err | |
| 164 | 174 | } | |
| 175 | + | var log *slog.Logger | |
| 176 | + | if len(logger) > 0 { | |
| 177 | + | log = logger[0] | |
| 178 | + | } | |
| 165 | 179 | spec := BuildCommand(target, session) | |
| 166 | 180 | cmd := exec.CommandContext(ctx, spec.Path, spec.Args...) | |
| 167 | 181 | stdin, err := cmd.StdinPipe() | |
| @@ -175,8 +189,11 @@ func DialContext(ctx context.Context, target, session string) (ports.Transport, | |||
| 175 | 189 | var stderr bytes.Buffer | |
| 176 | 190 | cmd.Stderr = &stderr | |
| 177 | 191 | if err := cmd.Start(); err != nil { | |
| 192 | + | if log != nil { | |
| 193 | + | log.Error("ssh start failed", "target", target, "session", session, "err", err) | |
| 194 | + | } | |
| 178 | 195 | return nil, fmt.Errorf("sshstdio: start ssh: %w", err) | |
| 179 | 196 | } | |
| 180 | 197 | ||
| 181 | - | return NewTransport(stdout, stdin, newProcessCloser(cmd, stdin, &stderr, sshCloseTimeout)), nil | |
| 198 | + | return NewTransport(stdout, stdin, newProcessCloser(cmd, stdin, &stderr, sshCloseTimeout, log, target, session)), nil | |
| 182 | 199 | } | |
| @@ -11,6 +11,7 @@ import ( | |||||
| 11 | "errors" | 11 | "errors" | ||
| 12 | "fmt" | 12 | "fmt" | ||
| 13 | "io" | 13 | "io" | ||
| 14 | + | "log/slog" | |||
| 14 | "os/exec" | 15 | "os/exec" | ||
| 15 | "strings" | 16 | "strings" | ||
| 16 | "sync" | 17 | "sync" | ||
| @@ -95,7 +96,7 @@ func (t *transport) Recv() (ports.Frame, error) { | |||||
| 95 | 96 | ||||
| 96 | func (t *transport) Close() error { return t.close() } | 97 | func (t *transport) Close() error { return t.close() } | ||
| 97 | 98 | ||||
| 98 | - | func newProcessCloser(cmd *exec.Cmd, stdin io.Closer, stderr *bytes.Buffer, timeout time.Duration) closeFunc { | 99 | + | func newProcessCloser(cmd *exec.Cmd, stdin io.Closer, stderr *bytes.Buffer, timeout time.Duration, log *slog.Logger, target, session string) closeFunc { |
| 99 | return func() error { | 100 | return func() error { | ||
| 100 | _ = stdin.Close() | 101 | _ = stdin.Close() | ||
| 101 | 102 | ||||
| @@ -114,6 +115,13 @@ func newProcessCloser(cmd *exec.Cmd, stdin io.Closer, stderr *bytes.Buffer, time | |||||
| 114 | } | 115 | } | ||
| 115 | 116 | ||||
| 116 | stderrText := strings.TrimSpace(stderr.String()) | 117 | stderrText := strings.TrimSpace(stderr.String()) | ||
| 118 | + | if log != nil { | |||
| 119 | + | attrs := []any{"target", target, "session", session, "err", err} | |||
| 120 | + | if stderrText != "" { | |||
| 121 | + | attrs = append(attrs, "stderr", stderrText) | |||
| 122 | + | } | |||
| 123 | + | log.Warn("ssh exited non-cleanly", attrs...) | |||
| 124 | + | } | |||
| 117 | if stderrText != "" { | 125 | if stderrText != "" { | ||
| 118 | return fmt.Errorf("sshstdio: ssh exited: %w: %s", err, stderrText) | 126 | return fmt.Errorf("sshstdio: ssh exited: %w: %s", err, stderrText) | ||
| 119 | } | 127 | } | ||
| @@ -157,11 +165,17 @@ func Dial(target, session string) (ports.Transport, error) { | |||||
| 157 | } | 165 | } | ||
| 158 | 166 | ||||
| 159 | // DialContext is like Dial, but the context is propagated to ssh startup so a | 167 | // DialContext is like Dial, but the context is propagated to ssh startup so a | ||
| 160 | - | // canceled attach attempt interrupts the local ssh process. | 168 | + | // canceled attach attempt interrupts the local ssh process. Callers may pass a |
| 161 | - | func DialContext(ctx context.Context, target, session string) (ports.Transport, error) { | 169 | + | // logger to record ssh start failures and non-clean exits without logging the |
| 170 | + | // generated command line. | |||
| 171 | + | func DialContext(ctx context.Context, target, session string, logger ...*slog.Logger) (ports.Transport, error) { | |||
| 162 | if err := ctx.Err(); err != nil { | 172 | if err := ctx.Err(); err != nil { | ||
| 163 | return nil, err | 173 | return nil, err | ||
| 164 | } | 174 | } | ||
| 175 | + | var log *slog.Logger | |||
| 176 | + | if len(logger) > 0 { | |||
| 177 | + | log = logger[0] | |||
| 178 | + | } | |||
| 165 | spec := BuildCommand(target, session) | 179 | spec := BuildCommand(target, session) | ||
| 166 | cmd := exec.CommandContext(ctx, spec.Path, spec.Args...) | 180 | cmd := exec.CommandContext(ctx, spec.Path, spec.Args...) | ||
| 167 | stdin, err := cmd.StdinPipe() | 181 | stdin, err := cmd.StdinPipe() | ||
| @@ -175,8 +189,11 @@ func DialContext(ctx context.Context, target, session string) (ports.Transport, | |||||
| 175 | var stderr bytes.Buffer | 189 | var stderr bytes.Buffer | ||
| 176 | cmd.Stderr = &stderr | 190 | cmd.Stderr = &stderr | ||
| 177 | if err := cmd.Start(); err != nil { | 191 | if err := cmd.Start(); err != nil { | ||
| 192 | + | if log != nil { | |||
| 193 | + | log.Error("ssh start failed", "target", target, "session", session, "err", err) | |||
| 194 | + | } | |||
| 178 | return nil, fmt.Errorf("sshstdio: start ssh: %w", err) | 195 | return nil, fmt.Errorf("sshstdio: start ssh: %w", err) | ||
| 179 | } | 196 | } | ||
| 180 | 197 | ||||
| 181 | - | return NewTransport(stdout, stdin, newProcessCloser(cmd, stdin, &stderr, sshCloseTimeout)), nil | 198 | + | return NewTransport(stdout, stdin, newProcessCloser(cmd, stdin, &stderr, sshCloseTimeout, log, target, session)), nil |
| 182 | } | 199 | } | ||
M internal/adapters/sshstdio/transport_test.go +31 -1
| @@ -5,6 +5,7 @@ import ( | |||
| 5 | 5 | "context" | |
| 6 | 6 | "errors" | |
| 7 | 7 | "io" | |
| 8 | + | "log/slog" | |
| 8 | 9 | "os/exec" | |
| 9 | 10 | "strings" | |
| 10 | 11 | "testing" | |
| @@ -125,6 +126,35 @@ func TestDialContextCanceledBeforeStart(t *testing.T) { | |||
| 125 | 126 | } | |
| 126 | 127 | } | |
| 127 | 128 | ||
| 129 | + | func TestProcessCloserLogsNonCleanExitStderr(t *testing.T) { | |
| 130 | + | cmd := exec.Command("sh", "-c", "echo remote failure >&2; exit 7") | |
| 131 | + | stdin, err := cmd.StdinPipe() | |
| 132 | + | if err != nil { | |
| 133 | + | t.Fatalf("StdinPipe: %v", err) | |
| 134 | + | } | |
| 135 | + | var stderr bytes.Buffer | |
| 136 | + | cmd.Stderr = &stderr | |
| 137 | + | if err := cmd.Start(); err != nil { | |
| 138 | + | t.Fatalf("Start: %v", err) | |
| 139 | + | } | |
| 140 | + | ||
| 141 | + | var logBuf bytes.Buffer | |
| 142 | + | log := slog.New(slog.NewJSONHandler(&logBuf, nil)) | |
| 143 | + | err = newProcessCloser(cmd, stdin, &stderr, time.Second, log, "user@example.com", "work")() | |
| 144 | + | if err == nil { | |
| 145 | + | t.Fatal("Close error = nil, want non-clean ssh exit") | |
| 146 | + | } | |
| 147 | + | entry := logBuf.String() | |
| 148 | + | for _, want := range []string{"ssh exited non-cleanly", "remote failure", "user@example.com", "work"} { | |
| 149 | + | if !strings.Contains(entry, want) { | |
| 150 | + | t.Fatalf("log entry = %q, want substring %q", entry, want) | |
| 151 | + | } | |
| 152 | + | } | |
| 153 | + | if strings.Contains(entry, "'vev' '_stdio'") || strings.Contains(entry, "-- user@example.com") { | |
| 154 | + | t.Fatalf("log entry includes generated command line: %q", entry) | |
| 155 | + | } | |
| 156 | + | } | |
| 157 | + | ||
| 128 | 158 | func TestProcessCloser(t *testing.T) { | |
| 129 | 159 | tests := []struct { | |
| 130 | 160 | name string | |
| @@ -161,7 +191,7 @@ func TestProcessCloser(t *testing.T) { | |||
| 161 | 191 | } | |
| 162 | 192 | ||
| 163 | 193 | started := time.Now() | |
| 164 | - | err = newProcessCloser(tt.cmd, stdin, &stderr, tt.timeout)() | |
| 194 | + | err = newProcessCloser(tt.cmd, stdin, &stderr, tt.timeout, nil, "", "")() | |
| 165 | 195 | elapsed := time.Since(started) | |
| 166 | 196 | ||
| 167 | 197 | if err == nil { | |
| @@ -5,6 +5,7 @@ import ( | |||||
| 5 | "context" | 5 | "context" | ||
| 6 | "errors" | 6 | "errors" | ||
| 7 | "io" | 7 | "io" | ||
| 8 | + | "log/slog" | |||
| 8 | "os/exec" | 9 | "os/exec" | ||
| 9 | "strings" | 10 | "strings" | ||
| 10 | "testing" | 11 | "testing" | ||
| @@ -125,6 +126,35 @@ func TestDialContextCanceledBeforeStart(t *testing.T) { | |||||
| 125 | } | 126 | } | ||
| 126 | } | 127 | } | ||
| 127 | 128 | ||||
| 129 | + | func TestProcessCloserLogsNonCleanExitStderr(t *testing.T) { | |||
| 130 | + | cmd := exec.Command("sh", "-c", "echo remote failure >&2; exit 7") | |||
| 131 | + | stdin, err := cmd.StdinPipe() | |||
| 132 | + | if err != nil { | |||
| 133 | + | t.Fatalf("StdinPipe: %v", err) | |||
| 134 | + | } | |||
| 135 | + | var stderr bytes.Buffer | |||
| 136 | + | cmd.Stderr = &stderr | |||
| 137 | + | if err := cmd.Start(); err != nil { | |||
| 138 | + | t.Fatalf("Start: %v", err) | |||
| 139 | + | } | |||
| 140 | + | ||||
| 141 | + | var logBuf bytes.Buffer | |||
| 142 | + | log := slog.New(slog.NewJSONHandler(&logBuf, nil)) | |||
| 143 | + | err = newProcessCloser(cmd, stdin, &stderr, time.Second, log, "user@example.com", "work")() | |||
| 144 | + | if err == nil { | |||
| 145 | + | t.Fatal("Close error = nil, want non-clean ssh exit") | |||
| 146 | + | } | |||
| 147 | + | entry := logBuf.String() | |||
| 148 | + | for _, want := range []string{"ssh exited non-cleanly", "remote failure", "user@example.com", "work"} { | |||
| 149 | + | if !strings.Contains(entry, want) { | |||
| 150 | + | t.Fatalf("log entry = %q, want substring %q", entry, want) | |||
| 151 | + | } | |||
| 152 | + | } | |||
| 153 | + | if strings.Contains(entry, "'vev' '_stdio'") || strings.Contains(entry, "-- user@example.com") { | |||
| 154 | + | t.Fatalf("log entry includes generated command line: %q", entry) | |||
| 155 | + | } | |||
| 156 | + | } | |||
| 157 | + | ||||
| 128 | func TestProcessCloser(t *testing.T) { | 158 | func TestProcessCloser(t *testing.T) { | ||
| 129 | tests := []struct { | 159 | tests := []struct { | ||
| 130 | name string | 160 | name string | ||
| @@ -161,7 +191,7 @@ func TestProcessCloser(t *testing.T) { | |||||
| 161 | } | 191 | } | ||
| 162 | 192 | ||||
| 163 | started := time.Now() | 193 | started := time.Now() | ||
| 164 | - | err = newProcessCloser(tt.cmd, stdin, &stderr, tt.timeout)() | 194 | + | err = newProcessCloser(tt.cmd, stdin, &stderr, tt.timeout, nil, "", "")() |
| 165 | elapsed := time.Since(started) | 195 | elapsed := time.Since(started) | ||
| 166 | 196 | ||||
| 167 | if err == nil { | 197 | if err == nil { | ||
D internal/app/logging.go +0 -50
| @@ -1,50 +0,0 @@ | |||
| 1 | - | package app | |
| 2 | - | ||
| 3 | - | import ( | |
| 4 | - | "fmt" | |
| 5 | - | "log/slog" | |
| 6 | - | "os" | |
| 7 | - | "path/filepath" | |
| 8 | - | "strings" | |
| 9 | - | ||
| 10 | - | "github.com/bnema/vev/internal/platform" | |
| 11 | - | ) | |
| 12 | - | ||
| 13 | - | // logFileName is the fixed name of vev's shared log file, used by both the | |
| 14 | - | // daemon and the raw-attached client (which must never log to the console). | |
| 15 | - | const logFileName = "vev.log" | |
| 16 | - | ||
| 17 | - | // parseLogLevel maps VEV_LOG to a slog level, defaulting to info. | |
| 18 | - | func parseLogLevel(s string) slog.Level { | |
| 19 | - | switch strings.ToLower(strings.TrimSpace(s)) { | |
| 20 | - | case "debug": | |
| 21 | - | return slog.LevelDebug | |
| 22 | - | case "warn", "warning": | |
| 23 | - | return slog.LevelWarn | |
| 24 | - | case "error": | |
| 25 | - | return slog.LevelError | |
| 26 | - | default: | |
| 27 | - | return slog.LevelInfo | |
| 28 | - | } | |
| 29 | - | } | |
| 30 | - | ||
| 31 | - | // setupLogging installs a JSON slog handler writing to the shared log file | |
| 32 | - | // and returns the open file so the caller can close it on exit. The level | |
| 33 | - | // comes from VEV_LOG (default info). Both the daemon and the client route | |
| 34 | - | // diagnostics here — the client because console output while the terminal is | |
| 35 | - | // raw would corrupt the display. | |
| 36 | - | // | |
| 37 | - | // No log rotation is performed for the MVP (future work). | |
| 38 | - | func setupLogging() (*os.File, error) { | |
| 39 | - | dir := platform.StateDir() | |
| 40 | - | if err := os.MkdirAll(dir, 0o700); err != nil { | |
| 41 | - | return nil, fmt.Errorf("vev: creating state dir: %w", err) | |
| 42 | - | } | |
| 43 | - | f, err := os.OpenFile(filepath.Join(dir, logFileName), os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) | |
| 44 | - | if err != nil { | |
| 45 | - | return nil, fmt.Errorf("vev: opening log file: %w", err) | |
| 46 | - | } | |
| 47 | - | handler := slog.NewJSONHandler(f, &slog.HandlerOptions{Level: parseLogLevel(os.Getenv("VEV_LOG"))}) | |
| 48 | - | slog.SetDefault(slog.New(handler)) | |
| 49 | - | return f, nil | |
| 50 | - | } | |
| @@ -1,50 +0,0 @@ | |||||
| 1 | - | package app | |||
| 2 | - | ||||
| 3 | - | import ( | |||
| 4 | - | "fmt" | |||
| 5 | - | "log/slog" | |||
| 6 | - | "os" | |||
| 7 | - | "path/filepath" | |||
| 8 | - | "strings" | |||
| 9 | - | ||||
| 10 | - | "github.com/bnema/vev/internal/platform" | |||
| 11 | - | ) | |||
| 12 | - | ||||
| 13 | - | // logFileName is the fixed name of vev's shared log file, used by both the | |||
| 14 | - | // daemon and the raw-attached client (which must never log to the console). | |||
| 15 | - | const logFileName = "vev.log" | |||
| 16 | - | ||||
| 17 | - | // parseLogLevel maps VEV_LOG to a slog level, defaulting to info. | |||
| 18 | - | func parseLogLevel(s string) slog.Level { | |||
| 19 | - | switch strings.ToLower(strings.TrimSpace(s)) { | |||
| 20 | - | case "debug": | |||
| 21 | - | return slog.LevelDebug | |||
| 22 | - | case "warn", "warning": | |||
| 23 | - | return slog.LevelWarn | |||
| 24 | - | case "error": | |||
| 25 | - | return slog.LevelError | |||
| 26 | - | default: | |||
| 27 | - | return slog.LevelInfo | |||
| 28 | - | } | |||
| 29 | - | } | |||
| 30 | - | ||||
| 31 | - | // setupLogging installs a JSON slog handler writing to the shared log file | |||
| 32 | - | // and returns the open file so the caller can close it on exit. The level | |||
| 33 | - | // comes from VEV_LOG (default info). Both the daemon and the client route | |||
| 34 | - | // diagnostics here — the client because console output while the terminal is | |||
| 35 | - | // raw would corrupt the display. | |||
| 36 | - | // | |||
| 37 | - | // No log rotation is performed for the MVP (future work). | |||
| 38 | - | func setupLogging() (*os.File, error) { | |||
| 39 | - | dir := platform.StateDir() | |||
| 40 | - | if err := os.MkdirAll(dir, 0o700); err != nil { | |||
| 41 | - | return nil, fmt.Errorf("vev: creating state dir: %w", err) | |||
| 42 | - | } | |||
| 43 | - | f, err := os.OpenFile(filepath.Join(dir, logFileName), os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) | |||
| 44 | - | if err != nil { | |||
| 45 | - | return nil, fmt.Errorf("vev: opening log file: %w", err) | |||
| 46 | - | } | |||
| 47 | - | handler := slog.NewJSONHandler(f, &slog.HandlerOptions{Level: parseLogLevel(os.Getenv("VEV_LOG"))}) | |||
| 48 | - | slog.SetDefault(slog.New(handler)) | |||
| 49 | - | return f, nil | |||
| 50 | - | } | |||
M internal/app/run.go +72 -27
| @@ -28,6 +28,7 @@ import ( | |||
| 28 | 28 | "github.com/bnema/vev/internal/adapters/sshstdio" | |
| 29 | 29 | "github.com/bnema/vev/internal/adapters/term" | |
| 30 | 30 | "github.com/bnema/vev/internal/domain" | |
| 31 | + | "github.com/bnema/vev/internal/logging" | |
| 31 | 32 | "github.com/bnema/vev/internal/persist" | |
| 32 | 33 | "github.com/bnema/vev/internal/platform" | |
| 33 | 34 | "github.com/bnema/vev/internal/ports" | |
| @@ -212,19 +213,30 @@ func dispatch(ctx context.Context, cmd command) error { | |||
| 212 | 213 | } | |
| 213 | 214 | } | |
| 214 | 215 | ||
| 216 | + | func configureLogging(component logging.Component, rotateAtRuntime bool) (*slog.Logger, io.Closer, error) { | |
| 217 | + | return logging.Setup(logging.Config{ | |
| 218 | + | Dir: platform.StateDir(), | |
| 219 | + | Component: component, | |
| 220 | + | Level: logging.EnvLevel(), | |
| 221 | + | MaxBytes: logging.DefaultMaxBytes, | |
| 222 | + | RotateAtRuntime: rotateAtRuntime, | |
| 223 | + | }) | |
| 224 | + | } | |
| 225 | + | ||
| 215 | 226 | // runDaemon runs the daemon in the foreground (the hidden --daemon path, | |
| 216 | 227 | // entered by an auto-spawned child): it sets up logging, binds the socket, | |
| 217 | 228 | // constructs the daemon, and serves until the last session exits or a | |
| 218 | 229 | // termination signal arrives (graceful shutdown notifies attached clients). | |
| 219 | 230 | func runDaemon() error { | |
| 220 | - | logFile, err := setupLogging() | |
| 231 | + | log, logCloser, err := configureLogging(logging.Daemon, true) | |
| 221 | 232 | if err != nil { | |
| 222 | 233 | return err | |
| 223 | 234 | } | |
| 224 | - | defer func() { _ = logFile.Close() }() | |
| 235 | + | defer func() { _ = logCloser.Close() }() | |
| 225 | 236 | ||
| 226 | 237 | ln, err := ipc.Listen(ipc.SocketDir()) | |
| 227 | 238 | if err != nil { | |
| 239 | + | log.Error("daemon listen failed", "socket_dir", ipc.SocketDir(), "err", err) | |
| 228 | 240 | return fmt.Errorf("vev: daemon listen: %w", err) | |
| 229 | 241 | } | |
| 230 | 242 | defer func() { _ = ln.Close() }() | |
| @@ -235,25 +247,27 @@ func runDaemon() error { | |||
| 235 | 247 | if addr := os.Getenv("VEV_PPROF_ADDR"); addr != "" { | |
| 236 | 248 | go func() { | |
| 237 | 249 | if err := http.ListenAndServe(addr, nil); err != nil && !errors.Is(err, http.ErrServerClosed) { | |
| 238 | - | slog.Error("pprof server exited", "err", err) | |
| 250 | + | log.Error("pprof server exited", "err", err) | |
| 239 | 251 | } | |
| 240 | 252 | }() | |
| 241 | - | slog.Info("pprof enabled", "addr", addr) | |
| 253 | + | log.Info("pprof enabled", "addr", addr) | |
| 242 | 254 | } | |
| 243 | 255 | ||
| 244 | - | slog.Info("daemon starting", "socket", ln.Addr()) | |
| 256 | + | log.Info("daemon starting", "socket", ln.Addr()) | |
| 245 | 257 | daemonOpts := []daemon.Option(nil) | |
| 246 | - | if store, err := kv.Open(persist.StorePath(platform.StateDir())); err != nil { | |
| 247 | - | slog.Warn("opening session store failed; persistence disabled", "err", err) | |
| 258 | + | storePath := persist.StorePath(platform.StateDir()) | |
| 259 | + | if store, err := kv.Open(storePath); err != nil { | |
| 260 | + | log.Warn("opening session store failed; persistence disabled", "path", storePath, "err", err) | |
| 248 | 261 | } else { | |
| 262 | + | log.Info("session persistence enabled", "path", storePath) | |
| 249 | 263 | daemonOpts = append(daemonOpts, daemon.WithStore(store)) | |
| 250 | 264 | } | |
| 251 | - | d := daemon.New(pty.NewFactory(), clock.New(), slog.Default(), daemonOpts...) | |
| 265 | + | d := daemon.New(pty.NewFactory(), clock.New(), log, daemonOpts...) | |
| 252 | 266 | if err := d.Serve(ctx, ln); err != nil { | |
| 253 | - | slog.Error("daemon exited", "err", err) | |
| 267 | + | log.Error("daemon exited", "err", err) | |
| 254 | 268 | return err | |
| 255 | 269 | } | |
| 256 | - | slog.Info("daemon exited cleanly") | |
| 270 | + | log.Info("daemon exited cleanly") | |
| 257 | 271 | return nil | |
| 258 | 272 | } | |
| 259 | 273 | ||
| @@ -261,13 +275,13 @@ func runDaemon() error { | |||
| 261 | 275 | // attach loop. Logging goes to the shared file: the client must never write | |
| 262 | 276 | // to the console while the terminal is raw. | |
| 263 | 277 | func runAttach(ctx context.Context, intent uint8, name, remoteTarget string) error { | |
| 264 | - | logFile, err := setupLogging() | |
| 278 | + | log, logCloser, err := configureLogging(logging.Client, false) | |
| 265 | 279 | if err != nil { | |
| 266 | 280 | return err | |
| 267 | 281 | } | |
| 268 | - | defer func() { _ = logFile.Close() }() | |
| 282 | + | defer func() { _ = logCloser.Close() }() | |
| 269 | 283 | ||
| 270 | - | return runAttachWithDeps(ctx, intent, name, remoteTarget, os.Getenv("VEV"), runAttachDeps{ | |
| 284 | + | return runAttachWithDeps(ctx, intent, name, remoteTarget, os.Getenv("VEV"), log, runAttachDeps{ | |
| 271 | 285 | localDialer: defaultLocalDialer, | |
| 272 | 286 | remoteDialer: defaultRemoteDialer, | |
| 273 | 287 | runClient: client.Run, | |
| @@ -277,19 +291,19 @@ func runAttach(ctx context.Context, intent uint8, name, remoteTarget string) err | |||
| 277 | 291 | ||
| 278 | 292 | func defaultLocalDialer() ports.Dialer { return localDaemonDialer{dir: ipc.SocketDir()} } | |
| 279 | 293 | ||
| 280 | - | func defaultRemoteDialer(target, session string) ports.Dialer { | |
| 281 | - | return dgram.NewRemoteDialer(target, session) | |
| 294 | + | func defaultRemoteDialer(target, session string, log *slog.Logger) ports.Dialer { | |
| 295 | + | return dgram.NewRemoteDialerWithLogger(target, session, log) | |
| 282 | 296 | } | |
| 283 | 297 | ||
| 284 | 298 | type runAttachDeps struct { | |
| 285 | - | attachLocal func(context.Context, uint8, string) error // compatibility hook for focused tests | |
| 299 | + | attachLocal func(context.Context, uint8, string, *slog.Logger) error // compatibility hook for focused tests | |
| 286 | 300 | localDialer func() ports.Dialer | |
| 287 | - | remoteDialer func(target, session string) ports.Dialer | |
| 288 | - | runClient func(context.Context, ports.Dialer, ports.Terminal, ports.Clock, uint8, string) error | |
| 301 | + | remoteDialer func(target, session string, log *slog.Logger) ports.Dialer | |
| 302 | + | runClient func(context.Context, ports.Dialer, ports.Terminal, ports.Clock, uint8, string, *slog.Logger) error | |
| 289 | 303 | createDetached func(context.Context, string) error | |
| 290 | 304 | } | |
| 291 | 305 | ||
| 292 | - | func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, activeSession string, deps runAttachDeps) error { | |
| 306 | + | func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, activeSession string, log *slog.Logger, deps runAttachDeps) error { | |
| 293 | 307 | if activeSession != "" { | |
| 294 | 308 | if remoteTarget == "" && intent == ports.IntentNew { | |
| 295 | 309 | return deps.createDetached(ctx, name) | |
| @@ -306,7 +320,10 @@ func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, ac | |||
| 306 | 320 | if remoteDialer == nil { | |
| 307 | 321 | remoteDialer = defaultRemoteDialer | |
| 308 | 322 | } | |
| 309 | - | return runClient(ctx, remoteDialer(remoteTarget, name), term.New(), clock.New(), intent, name) | |
| 323 | + | if log != nil { | |
| 324 | + | log.Info("attaching to remote session", "target", remoteTarget, "name", name) | |
| 325 | + | } | |
| 326 | + | return runClient(ctx, remoteDialer(remoteTarget, name, log), term.New(), clock.New(), intent, name, log) | |
| 310 | 327 | } | |
| 311 | 328 | ||
| 312 | 329 | attachLocal := deps.attachLocal | |
| @@ -315,13 +332,18 @@ func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, ac | |||
| 315 | 332 | if localDialer == nil { | |
| 316 | 333 | localDialer = defaultLocalDialer | |
| 317 | 334 | } | |
| 318 | - | attachLocal = func(ctx context.Context, intent uint8, name string) error { | |
| 319 | - | return runClient(ctx, localDialer(), term.New(), clock.New(), intent, name) | |
| 335 | + | attachLocal = func(ctx context.Context, intent uint8, name string, log *slog.Logger) error { | |
| 336 | + | if log != nil { | |
| 337 | + | log.Info("attaching to local session", "intent", intent, "name", name) | |
| 338 | + | } | |
| 339 | + | return runClient(ctx, localDialer(), term.New(), clock.New(), intent, name, log) | |
| 320 | 340 | } | |
| 321 | 341 | } | |
| 322 | 342 | return runLocalAttachWithRecovery(ctx, intent, name, attachRecoveryDeps{ | |
| 323 | - | confirmer: confirm.NewConfirmer(os.Stdin, os.Stderr), | |
| 324 | - | attach: attachLocal, | |
| 343 | + | confirmer: confirm.NewConfirmer(os.Stdin, os.Stderr), | |
| 344 | + | attach: func(ctx context.Context, intent uint8, name string) error { | |
| 345 | + | return attachLocal(ctx, intent, name, log) | |
| 346 | + | }, | |
| 325 | 347 | killDaemon: requestDaemonStop, | |
| 326 | 348 | settleAfterKill: waitForDaemonStop, | |
| 327 | 349 | }) | |
| @@ -489,6 +511,13 @@ func requestDaemonStop(ctx context.Context) error { | |||
| 489 | 511 | // connects to the per-user daemon (auto-spawning it if needed) and proxies the | |
| 490 | 512 | // framed protocol between process stdio and the daemon socket. | |
| 491 | 513 | func runStdio(ctx context.Context) error { | |
| 514 | + | log, logCloser, err := configureLogging(logging.Stdio, false) | |
| 515 | + | if err != nil { | |
| 516 | + | return err | |
| 517 | + | } | |
| 518 | + | defer func() { _ = logCloser.Close() }() | |
| 519 | + | log.Debug("stdio proxy starting") | |
| 520 | + | ||
| 492 | 521 | transport, err := ensureDaemon(ctx, ipc.SocketDir(), realDial, realSpawn, defaultBackoff) | |
| 493 | 522 | if err != nil { | |
| 494 | 523 | return err | |
| @@ -496,13 +525,20 @@ func runStdio(ctx context.Context) error { | |||
| 496 | 525 | defer func() { _ = transport.Close() }() | |
| 497 | 526 | ||
| 498 | 527 | stdio := sshstdio.NewTransport(os.Stdin, os.Stdout, nil) | |
| 499 | - | return proxyTransports(ctx, stdio, transport) | |
| 528 | + | return proxyTransports(ctx, stdio, transport, log) | |
| 500 | 529 | } | |
| 501 | 530 | ||
| 502 | 531 | // runUDPBootstrap is the hidden remote-side bootstrap used before switching to | |
| 503 | 532 | // authenticated datagrams. It deliberately prints only an ephemeral UDP port and | |
| 504 | 533 | // random session key to stdout so callers can fall back to _stdio if setup fails. | |
| 505 | 534 | func runUDPBootstrap(ctx context.Context, session string) error { | |
| 535 | + | log, logCloser, err := configureLogging(logging.Stdio, false) | |
| 536 | + | if err != nil { | |
| 537 | + | return err | |
| 538 | + | } | |
| 539 | + | defer func() { _ = logCloser.Close() }() | |
| 540 | + | log.Debug("udp bootstrap starting", "session", session) | |
| 541 | + | ||
| 506 | 542 | select { | |
| 507 | 543 | case <-ctx.Done(): | |
| 508 | 544 | return ctx.Err() | |
| @@ -542,7 +578,7 @@ func runUDPBootstrap(ctx context.Context, session string) error { | |||
| 542 | 578 | if session != "" { | |
| 543 | 579 | dgramTr = preHelloNameTransport{Transport: dg, session: session} | |
| 544 | 580 | } | |
| 545 | - | return proxyTransports(ctx, dgramTr, daemonTr) | |
| 581 | + | return proxyTransports(ctx, dgramTr, daemonTr, log) | |
| 546 | 582 | } | |
| 547 | 583 | ||
| 548 | 584 | type preHelloNameTransport struct { | |
| @@ -566,7 +602,7 @@ func (t preHelloNameTransport) Recv() (ports.Frame, error) { | |||
| 566 | 602 | return f, nil | |
| 567 | 603 | } | |
| 568 | 604 | ||
| 569 | - | func proxyTransports(ctx context.Context, a, b ports.Transport) error { | |
| 605 | + | func proxyTransports(ctx context.Context, a, b ports.Transport, log *slog.Logger) error { | |
| 570 | 606 | errCh := make(chan error, 2) | |
| 571 | 607 | copyFrames := func(dst, src ports.Transport) { | |
| 572 | 608 | for { | |
| @@ -586,11 +622,20 @@ func proxyTransports(ctx context.Context, a, b ports.Transport) error { | |||
| 586 | 622 | ||
| 587 | 623 | select { | |
| 588 | 624 | case <-ctx.Done(): | |
| 625 | + | if log != nil { | |
| 626 | + | log.Info("stdio proxy stopped by context", "err", ctx.Err()) | |
| 627 | + | } | |
| 589 | 628 | return ctx.Err() | |
| 590 | 629 | case err := <-errCh: | |
| 591 | 630 | if errors.Is(err, io.EOF) { | |
| 631 | + | if log != nil { | |
| 632 | + | log.Info("stdio proxy reached clean EOF") | |
| 633 | + | } | |
| 592 | 634 | return nil | |
| 593 | 635 | } | |
| 636 | + | if log != nil { | |
| 637 | + | log.Error("stdio proxy copy failed", "err", err) | |
| 638 | + | } | |
| 594 | 639 | return err | |
| 595 | 640 | } | |
| 596 | 641 | } | |
| @@ -28,6 +28,7 @@ import ( | |||||
| 28 | "github.com/bnema/vev/internal/adapters/sshstdio" | 28 | "github.com/bnema/vev/internal/adapters/sshstdio" | ||
| 29 | "github.com/bnema/vev/internal/adapters/term" | 29 | "github.com/bnema/vev/internal/adapters/term" | ||
| 30 | "github.com/bnema/vev/internal/domain" | 30 | "github.com/bnema/vev/internal/domain" | ||
| 31 | + | "github.com/bnema/vev/internal/logging" | |||
| 31 | "github.com/bnema/vev/internal/persist" | 32 | "github.com/bnema/vev/internal/persist" | ||
| 32 | "github.com/bnema/vev/internal/platform" | 33 | "github.com/bnema/vev/internal/platform" | ||
| 33 | "github.com/bnema/vev/internal/ports" | 34 | "github.com/bnema/vev/internal/ports" | ||
| @@ -212,19 +213,30 @@ func dispatch(ctx context.Context, cmd command) error { | |||||
| 212 | } | 213 | } | ||
| 213 | } | 214 | } | ||
| 214 | 215 | ||||
| 216 | + | func configureLogging(component logging.Component, rotateAtRuntime bool) (*slog.Logger, io.Closer, error) { | |||
| 217 | + | return logging.Setup(logging.Config{ | |||
| 218 | + | Dir: platform.StateDir(), | |||
| 219 | + | Component: component, | |||
| 220 | + | Level: logging.EnvLevel(), | |||
| 221 | + | MaxBytes: logging.DefaultMaxBytes, | |||
| 222 | + | RotateAtRuntime: rotateAtRuntime, | |||
| 223 | + | }) | |||
| 224 | + | } | |||
| 225 | + | ||||
| 215 | // runDaemon runs the daemon in the foreground (the hidden --daemon path, | 226 | // runDaemon runs the daemon in the foreground (the hidden --daemon path, | ||
| 216 | // entered by an auto-spawned child): it sets up logging, binds the socket, | 227 | // entered by an auto-spawned child): it sets up logging, binds the socket, | ||
| 217 | // constructs the daemon, and serves until the last session exits or a | 228 | // constructs the daemon, and serves until the last session exits or a | ||
| 218 | // termination signal arrives (graceful shutdown notifies attached clients). | 229 | // termination signal arrives (graceful shutdown notifies attached clients). | ||
| 219 | func runDaemon() error { | 230 | func runDaemon() error { | ||
| 220 | - | logFile, err := setupLogging() | 231 | + | log, logCloser, err := configureLogging(logging.Daemon, true) |
| 221 | if err != nil { | 232 | if err != nil { | ||
| 222 | return err | 233 | return err | ||
| 223 | } | 234 | } | ||
| 224 | - | defer func() { _ = logFile.Close() }() | 235 | + | defer func() { _ = logCloser.Close() }() |
| 225 | 236 | ||||
| 226 | ln, err := ipc.Listen(ipc.SocketDir()) | 237 | ln, err := ipc.Listen(ipc.SocketDir()) | ||
| 227 | if err != nil { | 238 | if err != nil { | ||
| 239 | + | log.Error("daemon listen failed", "socket_dir", ipc.SocketDir(), "err", err) | |||
| 228 | return fmt.Errorf("vev: daemon listen: %w", err) | 240 | return fmt.Errorf("vev: daemon listen: %w", err) | ||
| 229 | } | 241 | } | ||
| 230 | defer func() { _ = ln.Close() }() | 242 | defer func() { _ = ln.Close() }() | ||
| @@ -235,25 +247,27 @@ func runDaemon() error { | |||||
| 235 | if addr := os.Getenv("VEV_PPROF_ADDR"); addr != "" { | 247 | if addr := os.Getenv("VEV_PPROF_ADDR"); addr != "" { | ||
| 236 | go func() { | 248 | go func() { | ||
| 237 | if err := http.ListenAndServe(addr, nil); err != nil && !errors.Is(err, http.ErrServerClosed) { | 249 | if err := http.ListenAndServe(addr, nil); err != nil && !errors.Is(err, http.ErrServerClosed) { | ||
| 238 | - | slog.Error("pprof server exited", "err", err) | 250 | + | log.Error("pprof server exited", "err", err) |
| 239 | } | 251 | } | ||
| 240 | }() | 252 | }() | ||
| 241 | - | slog.Info("pprof enabled", "addr", addr) | 253 | + | log.Info("pprof enabled", "addr", addr) |
| 242 | } | 254 | } | ||
| 243 | 255 | ||||
| 244 | - | slog.Info("daemon starting", "socket", ln.Addr()) | 256 | + | log.Info("daemon starting", "socket", ln.Addr()) |
| 245 | daemonOpts := []daemon.Option(nil) | 257 | daemonOpts := []daemon.Option(nil) | ||
| 246 | - | if store, err := kv.Open(persist.StorePath(platform.StateDir())); err != nil { | 258 | + | storePath := persist.StorePath(platform.StateDir()) |
| 247 | - | slog.Warn("opening session store failed; persistence disabled", "err", err) | 259 | + | if store, err := kv.Open(storePath); err != nil { |
| 260 | + | log.Warn("opening session store failed; persistence disabled", "path", storePath, "err", err) | |||
| 248 | } else { | 261 | } else { | ||
| 262 | + | log.Info("session persistence enabled", "path", storePath) | |||
| 249 | daemonOpts = append(daemonOpts, daemon.WithStore(store)) | 263 | daemonOpts = append(daemonOpts, daemon.WithStore(store)) | ||
| 250 | } | 264 | } | ||
| 251 | - | d := daemon.New(pty.NewFactory(), clock.New(), slog.Default(), daemonOpts...) | 265 | + | d := daemon.New(pty.NewFactory(), clock.New(), log, daemonOpts...) |
| 252 | if err := d.Serve(ctx, ln); err != nil { | 266 | if err := d.Serve(ctx, ln); err != nil { | ||
| 253 | - | slog.Error("daemon exited", "err", err) | 267 | + | log.Error("daemon exited", "err", err) |
| 254 | return err | 268 | return err | ||
| 255 | } | 269 | } | ||
| 256 | - | slog.Info("daemon exited cleanly") | 270 | + | log.Info("daemon exited cleanly") |
| 257 | return nil | 271 | return nil | ||
| 258 | } | 272 | } | ||
| 259 | 273 | ||||
| @@ -261,13 +275,13 @@ func runDaemon() error { | |||||
| 261 | // attach loop. Logging goes to the shared file: the client must never write | 275 | // attach loop. Logging goes to the shared file: the client must never write | ||
| 262 | // to the console while the terminal is raw. | 276 | // to the console while the terminal is raw. | ||
| 263 | func runAttach(ctx context.Context, intent uint8, name, remoteTarget string) error { | 277 | func runAttach(ctx context.Context, intent uint8, name, remoteTarget string) error { | ||
| 264 | - | logFile, err := setupLogging() | 278 | + | log, logCloser, err := configureLogging(logging.Client, false) |
| 265 | if err != nil { | 279 | if err != nil { | ||
| 266 | return err | 280 | return err | ||
| 267 | } | 281 | } | ||
| 268 | - | defer func() { _ = logFile.Close() }() | 282 | + | defer func() { _ = logCloser.Close() }() |
| 269 | 283 | ||||
| 270 | - | return runAttachWithDeps(ctx, intent, name, remoteTarget, os.Getenv("VEV"), runAttachDeps{ | 284 | + | return runAttachWithDeps(ctx, intent, name, remoteTarget, os.Getenv("VEV"), log, runAttachDeps{ |
| 271 | localDialer: defaultLocalDialer, | 285 | localDialer: defaultLocalDialer, | ||
| 272 | remoteDialer: defaultRemoteDialer, | 286 | remoteDialer: defaultRemoteDialer, | ||
| 273 | runClient: client.Run, | 287 | runClient: client.Run, | ||
| @@ -277,19 +291,19 @@ func runAttach(ctx context.Context, intent uint8, name, remoteTarget string) err | |||||
| 277 | 291 | ||||
| 278 | func defaultLocalDialer() ports.Dialer { return localDaemonDialer{dir: ipc.SocketDir()} } | 292 | func defaultLocalDialer() ports.Dialer { return localDaemonDialer{dir: ipc.SocketDir()} } | ||
| 279 | 293 | ||||
| 280 | - | func defaultRemoteDialer(target, session string) ports.Dialer { | 294 | + | func defaultRemoteDialer(target, session string, log *slog.Logger) ports.Dialer { |
| 281 | - | return dgram.NewRemoteDialer(target, session) | 295 | + | return dgram.NewRemoteDialerWithLogger(target, session, log) |
| 282 | } | 296 | } | ||
| 283 | 297 | ||||
| 284 | type runAttachDeps struct { | 298 | type runAttachDeps struct { | ||
| 285 | - | attachLocal func(context.Context, uint8, string) error // compatibility hook for focused tests | 299 | + | attachLocal func(context.Context, uint8, string, *slog.Logger) error // compatibility hook for focused tests |
| 286 | localDialer func() ports.Dialer | 300 | localDialer func() ports.Dialer | ||
| 287 | - | remoteDialer func(target, session string) ports.Dialer | 301 | + | remoteDialer func(target, session string, log *slog.Logger) ports.Dialer |
| 288 | - | runClient func(context.Context, ports.Dialer, ports.Terminal, ports.Clock, uint8, string) error | 302 | + | runClient func(context.Context, ports.Dialer, ports.Terminal, ports.Clock, uint8, string, *slog.Logger) error |
| 289 | createDetached func(context.Context, string) error | 303 | createDetached func(context.Context, string) error | ||
| 290 | } | 304 | } | ||
| 291 | 305 | ||||
| 292 | - | func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, activeSession string, deps runAttachDeps) error { | 306 | + | func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, activeSession string, log *slog.Logger, deps runAttachDeps) error { |
| 293 | if activeSession != "" { | 307 | if activeSession != "" { | ||
| 294 | if remoteTarget == "" && intent == ports.IntentNew { | 308 | if remoteTarget == "" && intent == ports.IntentNew { | ||
| 295 | return deps.createDetached(ctx, name) | 309 | return deps.createDetached(ctx, name) | ||
| @@ -306,7 +320,10 @@ func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, ac | |||||
| 306 | if remoteDialer == nil { | 320 | if remoteDialer == nil { | ||
| 307 | remoteDialer = defaultRemoteDialer | 321 | remoteDialer = defaultRemoteDialer | ||
| 308 | } | 322 | } | ||
| 309 | - | return runClient(ctx, remoteDialer(remoteTarget, name), term.New(), clock.New(), intent, name) | 323 | + | if log != nil { |
| 324 | + | log.Info("attaching to remote session", "target", remoteTarget, "name", name) | |||
| 325 | + | } | |||
| 326 | + | return runClient(ctx, remoteDialer(remoteTarget, name, log), term.New(), clock.New(), intent, name, log) | |||
| 310 | } | 327 | } | ||
| 311 | 328 | ||||
| 312 | attachLocal := deps.attachLocal | 329 | attachLocal := deps.attachLocal | ||
| @@ -315,13 +332,18 @@ func runAttachWithDeps(ctx context.Context, intent uint8, name, remoteTarget, ac | |||||
| 315 | if localDialer == nil { | 332 | if localDialer == nil { | ||
| 316 | localDialer = defaultLocalDialer | 333 | localDialer = defaultLocalDialer | ||
| 317 | } | 334 | } | ||
| 318 | - | attachLocal = func(ctx context.Context, intent uint8, name string) error { | 335 | + | attachLocal = func(ctx context.Context, intent uint8, name string, log *slog.Logger) error { |
| 319 | - | return runClient(ctx, localDialer(), term.New(), clock.New(), intent, name) | 336 | + | if log != nil { |
| 337 | + | log.Info("attaching to local session", "intent", intent, "name", name) | |||
| 338 | + | } | |||
| 339 | + | return runClient(ctx, localDialer(), term.New(), clock.New(), intent, name, log) | |||
| 320 | } | 340 | } | ||
| 321 | } | 341 | } | ||
| 322 | return runLocalAttachWithRecovery(ctx, intent, name, attachRecoveryDeps{ | 342 | return runLocalAttachWithRecovery(ctx, intent, name, attachRecoveryDeps{ | ||
| 323 | - | confirmer: confirm.NewConfirmer(os.Stdin, os.Stderr), | 343 | + | confirmer: confirm.NewConfirmer(os.Stdin, os.Stderr), |
| 324 | - | attach: attachLocal, | 344 | + | attach: func(ctx context.Context, intent uint8, name string) error { |
| 345 | + | return attachLocal(ctx, intent, name, log) | |||
| 346 | + | }, | |||
| 325 | killDaemon: requestDaemonStop, | 347 | killDaemon: requestDaemonStop, | ||
| 326 | settleAfterKill: waitForDaemonStop, | 348 | settleAfterKill: waitForDaemonStop, | ||
| 327 | }) | 349 | }) | ||
| @@ -489,6 +511,13 @@ func requestDaemonStop(ctx context.Context) error { | |||||
| 489 | // connects to the per-user daemon (auto-spawning it if needed) and proxies the | 511 | // connects to the per-user daemon (auto-spawning it if needed) and proxies the | ||
| 490 | // framed protocol between process stdio and the daemon socket. | 512 | // framed protocol between process stdio and the daemon socket. | ||
| 491 | func runStdio(ctx context.Context) error { | 513 | func runStdio(ctx context.Context) error { | ||
| 514 | + | log, logCloser, err := configureLogging(logging.Stdio, false) | |||
| 515 | + | if err != nil { | |||
| 516 | + | return err | |||
| 517 | + | } | |||
| 518 | + | defer func() { _ = logCloser.Close() }() | |||
| 519 | + | log.Debug("stdio proxy starting") | |||
| 520 | + | ||||
| 492 | transport, err := ensureDaemon(ctx, ipc.SocketDir(), realDial, realSpawn, defaultBackoff) | 521 | transport, err := ensureDaemon(ctx, ipc.SocketDir(), realDial, realSpawn, defaultBackoff) | ||
| 493 | if err != nil { | 522 | if err != nil { | ||
| 494 | return err | 523 | return err | ||
| @@ -496,13 +525,20 @@ func runStdio(ctx context.Context) error { | |||||
| 496 | defer func() { _ = transport.Close() }() | 525 | defer func() { _ = transport.Close() }() | ||
| 497 | 526 | ||||
| 498 | stdio := sshstdio.NewTransport(os.Stdin, os.Stdout, nil) | 527 | stdio := sshstdio.NewTransport(os.Stdin, os.Stdout, nil) | ||
| 499 | - | return proxyTransports(ctx, stdio, transport) | 528 | + | return proxyTransports(ctx, stdio, transport, log) |
| 500 | } | 529 | } | ||
| 501 | 530 | ||||
| 502 | // runUDPBootstrap is the hidden remote-side bootstrap used before switching to | 531 | // runUDPBootstrap is the hidden remote-side bootstrap used before switching to | ||
| 503 | // authenticated datagrams. It deliberately prints only an ephemeral UDP port and | 532 | // authenticated datagrams. It deliberately prints only an ephemeral UDP port and | ||
| 504 | // random session key to stdout so callers can fall back to _stdio if setup fails. | 533 | // random session key to stdout so callers can fall back to _stdio if setup fails. | ||
| 505 | func runUDPBootstrap(ctx context.Context, session string) error { | 534 | func runUDPBootstrap(ctx context.Context, session string) error { | ||
| 535 | + | log, logCloser, err := configureLogging(logging.Stdio, false) | |||
| 536 | + | if err != nil { | |||
| 537 | + | return err | |||
| 538 | + | } | |||
| 539 | + | defer func() { _ = logCloser.Close() }() | |||
| 540 | + | log.Debug("udp bootstrap starting", "session", session) | |||
| 541 | + | ||||
| 506 | select { | 542 | select { | ||
| 507 | case <-ctx.Done(): | 543 | case <-ctx.Done(): | ||
| 508 | return ctx.Err() | 544 | return ctx.Err() | ||
| @@ -542,7 +578,7 @@ func runUDPBootstrap(ctx context.Context, session string) error { | |||||
| 542 | if session != "" { | 578 | if session != "" { | ||
| 543 | dgramTr = preHelloNameTransport{Transport: dg, session: session} | 579 | dgramTr = preHelloNameTransport{Transport: dg, session: session} | ||
| 544 | } | 580 | } | ||
| 545 | - | return proxyTransports(ctx, dgramTr, daemonTr) | 581 | + | return proxyTransports(ctx, dgramTr, daemonTr, log) |
| 546 | } | 582 | } | ||
| 547 | 583 | ||||
| 548 | type preHelloNameTransport struct { | 584 | type preHelloNameTransport struct { | ||
| @@ -566,7 +602,7 @@ func (t preHelloNameTransport) Recv() (ports.Frame, error) { | |||||
| 566 | return f, nil | 602 | return f, nil | ||
| 567 | } | 603 | } | ||
| 568 | 604 | ||||
| 569 | - | func proxyTransports(ctx context.Context, a, b ports.Transport) error { | 605 | + | func proxyTransports(ctx context.Context, a, b ports.Transport, log *slog.Logger) error { |
| 570 | errCh := make(chan error, 2) | 606 | errCh := make(chan error, 2) | ||
| 571 | copyFrames := func(dst, src ports.Transport) { | 607 | copyFrames := func(dst, src ports.Transport) { | ||
| 572 | for { | 608 | for { | ||
| @@ -586,11 +622,20 @@ func proxyTransports(ctx context.Context, a, b ports.Transport) error { | |||||
| 586 | 622 | ||||
| 587 | select { | 623 | select { | ||
| 588 | case <-ctx.Done(): | 624 | case <-ctx.Done(): | ||
| 625 | + | if log != nil { | |||
| 626 | + | log.Info("stdio proxy stopped by context", "err", ctx.Err()) | |||
| 627 | + | } | |||
| 589 | return ctx.Err() | 628 | return ctx.Err() | ||
| 590 | case err := <-errCh: | 629 | case err := <-errCh: | ||
| 591 | if errors.Is(err, io.EOF) { | 630 | if errors.Is(err, io.EOF) { | ||
| 631 | + | if log != nil { | |||
| 632 | + | log.Info("stdio proxy reached clean EOF") | |||
| 633 | + | } | |||
| 592 | return nil | 634 | return nil | ||
| 593 | } | 635 | } | ||
| 636 | + | if log != nil { | |||
| 637 | + | log.Error("stdio proxy copy failed", "err", err) | |||
| 638 | + | } | |||
| 594 | return err | 639 | return err | ||
| 595 | } | 640 | } | ||
| 596 | } | 641 | } | ||
M internal/app/run_test.go +10 -9
| @@ -5,6 +5,7 @@ import ( | |||
| 5 | 5 | "context" | |
| 6 | 6 | "errors" | |
| 7 | 7 | "io" | |
| 8 | + | "log/slog" | |
| 8 | 9 | "os" | |
| 9 | 10 | "path/filepath" | |
| 10 | 11 | "strings" | |
| @@ -346,8 +347,8 @@ func TestRunLocalAttachDeclineKeepsOriginalError(t *testing.T) { | |||
| 346 | 347 | ||
| 347 | 348 | func TestRunAttachRejectsNestedVEVBeforeDial(t *testing.T) { | |
| 348 | 349 | called := false | |
| 349 | - | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "outer", runAttachDeps{ | |
| 350 | - | attachLocal: func(context.Context, uint8, string) error { | |
| 350 | + | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "outer", nil, runAttachDeps{ | |
| 351 | + | attachLocal: func(context.Context, uint8, string, *slog.Logger) error { | |
| 351 | 352 | called = true | |
| 352 | 353 | return nil | |
| 353 | 354 | }, | |
| @@ -369,8 +370,8 @@ func TestRunAttachRejectsNestedVEVBeforeDial(t *testing.T) { | |||
| 369 | 370 | ||
| 370 | 371 | func TestRunAttachNestedNewCreatesDetachedSession(t *testing.T) { | |
| 371 | 372 | var gotName string | |
| 372 | - | err := runAttachWithDeps(context.Background(), ports.IntentNew, "scratch", "", "outer", runAttachDeps{ | |
| 373 | - | attachLocal: func(context.Context, uint8, string) error { | |
| 373 | + | err := runAttachWithDeps(context.Background(), ports.IntentNew, "scratch", "", "outer", nil, runAttachDeps{ | |
| 374 | + | attachLocal: func(context.Context, uint8, string, *slog.Logger) error { | |
| 374 | 375 | t.Fatal("nested new should not attach to the session") | |
| 375 | 376 | return nil | |
| 376 | 377 | }, | |
| @@ -395,12 +396,12 @@ func (d namedDialer) Dial(context.Context) (ports.Transport, error) { | |||
| 395 | 396 | ||
| 396 | 397 | func TestRunAttachWithDepsBuildsRemoteDialer(t *testing.T) { | |
| 397 | 398 | var gotTarget, gotSession, gotDialer string | |
| 398 | - | err := runAttachWithDeps(context.Background(), ports.IntentAttach, "work", "remote.example", "", runAttachDeps{ | |
| 399 | - | remoteDialer: func(target, session string) ports.Dialer { | |
| 399 | + | err := runAttachWithDeps(context.Background(), ports.IntentAttach, "work", "remote.example", "", nil, runAttachDeps{ | |
| 400 | + | remoteDialer: func(target, session string, _ *slog.Logger) ports.Dialer { | |
| 400 | 401 | gotTarget, gotSession = target, session | |
| 401 | 402 | return namedDialer{name: "remote"} | |
| 402 | 403 | }, | |
| 403 | - | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string) error { | |
| 404 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string, _ *slog.Logger) error { | |
| 404 | 405 | gotDialer = d.(namedDialer).name | |
| 405 | 406 | if intent != ports.IntentAttach || name != "work" { | |
| 406 | 407 | t.Fatalf("intent/name = %d/%q, want attach/work", intent, name) | |
| @@ -418,9 +419,9 @@ func TestRunAttachWithDepsBuildsRemoteDialer(t *testing.T) { | |||
| 418 | 419 | ||
| 419 | 420 | func TestRunAttachWithDepsBuildsLocalDialer(t *testing.T) { | |
| 420 | 421 | var gotDialer string | |
| 421 | - | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "", runAttachDeps{ | |
| 422 | + | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "", nil, runAttachDeps{ | |
| 422 | 423 | localDialer: func() ports.Dialer { return namedDialer{name: "local"} }, | |
| 423 | - | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string) error { | |
| 424 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string, _ *slog.Logger) error { | |
| 424 | 425 | gotDialer = d.(namedDialer).name | |
| 425 | 426 | if intent != ports.IntentEphemeral || name != "" { | |
| 426 | 427 | t.Fatalf("intent/name = %d/%q, want ephemeral/empty", intent, name) | |
| @@ -5,6 +5,7 @@ import ( | |||||
| 5 | "context" | 5 | "context" | ||
| 6 | "errors" | 6 | "errors" | ||
| 7 | "io" | 7 | "io" | ||
| 8 | + | "log/slog" | |||
| 8 | "os" | 9 | "os" | ||
| 9 | "path/filepath" | 10 | "path/filepath" | ||
| 10 | "strings" | 11 | "strings" | ||
| @@ -346,8 +347,8 @@ func TestRunLocalAttachDeclineKeepsOriginalError(t *testing.T) { | |||||
| 346 | 347 | ||||
| 347 | func TestRunAttachRejectsNestedVEVBeforeDial(t *testing.T) { | 348 | func TestRunAttachRejectsNestedVEVBeforeDial(t *testing.T) { | ||
| 348 | called := false | 349 | called := false | ||
| 349 | - | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "outer", runAttachDeps{ | 350 | + | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "outer", nil, runAttachDeps{ |
| 350 | - | attachLocal: func(context.Context, uint8, string) error { | 351 | + | attachLocal: func(context.Context, uint8, string, *slog.Logger) error { |
| 351 | called = true | 352 | called = true | ||
| 352 | return nil | 353 | return nil | ||
| 353 | }, | 354 | }, | ||
| @@ -369,8 +370,8 @@ func TestRunAttachRejectsNestedVEVBeforeDial(t *testing.T) { | |||||
| 369 | 370 | ||||
| 370 | func TestRunAttachNestedNewCreatesDetachedSession(t *testing.T) { | 371 | func TestRunAttachNestedNewCreatesDetachedSession(t *testing.T) { | ||
| 371 | var gotName string | 372 | var gotName string | ||
| 372 | - | err := runAttachWithDeps(context.Background(), ports.IntentNew, "scratch", "", "outer", runAttachDeps{ | 373 | + | err := runAttachWithDeps(context.Background(), ports.IntentNew, "scratch", "", "outer", nil, runAttachDeps{ |
| 373 | - | attachLocal: func(context.Context, uint8, string) error { | 374 | + | attachLocal: func(context.Context, uint8, string, *slog.Logger) error { |
| 374 | t.Fatal("nested new should not attach to the session") | 375 | t.Fatal("nested new should not attach to the session") | ||
| 375 | return nil | 376 | return nil | ||
| 376 | }, | 377 | }, | ||
| @@ -395,12 +396,12 @@ func (d namedDialer) Dial(context.Context) (ports.Transport, error) { | |||||
| 395 | 396 | ||||
| 396 | func TestRunAttachWithDepsBuildsRemoteDialer(t *testing.T) { | 397 | func TestRunAttachWithDepsBuildsRemoteDialer(t *testing.T) { | ||
| 397 | var gotTarget, gotSession, gotDialer string | 398 | var gotTarget, gotSession, gotDialer string | ||
| 398 | - | err := runAttachWithDeps(context.Background(), ports.IntentAttach, "work", "remote.example", "", runAttachDeps{ | 399 | + | err := runAttachWithDeps(context.Background(), ports.IntentAttach, "work", "remote.example", "", nil, runAttachDeps{ |
| 399 | - | remoteDialer: func(target, session string) ports.Dialer { | 400 | + | remoteDialer: func(target, session string, _ *slog.Logger) ports.Dialer { |
| 400 | gotTarget, gotSession = target, session | 401 | gotTarget, gotSession = target, session | ||
| 401 | return namedDialer{name: "remote"} | 402 | return namedDialer{name: "remote"} | ||
| 402 | }, | 403 | }, | ||
| 403 | - | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string) error { | 404 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string, _ *slog.Logger) error { |
| 404 | gotDialer = d.(namedDialer).name | 405 | gotDialer = d.(namedDialer).name | ||
| 405 | if intent != ports.IntentAttach || name != "work" { | 406 | if intent != ports.IntentAttach || name != "work" { | ||
| 406 | t.Fatalf("intent/name = %d/%q, want attach/work", intent, name) | 407 | t.Fatalf("intent/name = %d/%q, want attach/work", intent, name) | ||
| @@ -418,9 +419,9 @@ func TestRunAttachWithDepsBuildsRemoteDialer(t *testing.T) { | |||||
| 418 | 419 | ||||
| 419 | func TestRunAttachWithDepsBuildsLocalDialer(t *testing.T) { | 420 | func TestRunAttachWithDepsBuildsLocalDialer(t *testing.T) { | ||
| 420 | var gotDialer string | 421 | var gotDialer string | ||
| 421 | - | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "", runAttachDeps{ | 422 | + | err := runAttachWithDeps(context.Background(), ports.IntentEphemeral, "", "", "", nil, runAttachDeps{ |
| 422 | localDialer: func() ports.Dialer { return namedDialer{name: "local"} }, | 423 | localDialer: func() ports.Dialer { return namedDialer{name: "local"} }, | ||
| 423 | - | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string) error { | 424 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, _ ports.Clock, intent uint8, name string, _ *slog.Logger) error { |
| 424 | gotDialer = d.(namedDialer).name | 425 | gotDialer = d.(namedDialer).name | ||
| 425 | if intent != ports.IntentEphemeral || name != "" { | 426 | if intent != ports.IntentEphemeral || name != "" { | ||
| 426 | t.Fatalf("intent/name = %d/%q, want ephemeral/empty", intent, name) | 427 | t.Fatalf("intent/name = %d/%q, want ephemeral/empty", intent, name) | ||
M internal/app/spawn.go +10 -0
| @@ -4,6 +4,7 @@ import ( | |||
| 4 | 4 | "context" | |
| 5 | 5 | "errors" | |
| 6 | 6 | "fmt" | |
| 7 | + | "log/slog" | |
| 7 | 8 | "os" | |
| 8 | 9 | "os/exec" | |
| 9 | 10 | "path/filepath" | |
| @@ -57,6 +58,7 @@ var defaultBackoff = backoffConfig{ | |||
| 57 | 58 | // backoff until the socket is live or the budget expires. | |
| 58 | 59 | func ensureDaemon(ctx context.Context, dir string, dial dialFunc, spawn spawnFunc, cfg backoffConfig) (ports.Transport, error) { | |
| 59 | 60 | if t, err := dial(dir); err == nil { | |
| 61 | + | slog.Debug("daemon already reachable", "socket_dir", dir) | |
| 60 | 62 | return t, nil | |
| 61 | 63 | } | |
| 62 | 64 | ||
| @@ -69,9 +71,13 @@ func ensureDaemon(ctx context.Context, dir string, dial dialFunc, spawn spawnFun | |||
| 69 | 71 | // dialable (or spawn fails) so late-arriving clients keep waiting | |
| 70 | 72 | // rather than spawning a second daemon. | |
| 71 | 73 | defer release() | |
| 74 | + | slog.Info("spawning daemon", "socket_dir", dir) | |
| 72 | 75 | if err := spawn(); err != nil { | |
| 76 | + | slog.Error("daemon spawn failed", "err", err) | |
| 73 | 77 | return nil, fmt.Errorf("vev: spawning daemon: %w", err) | |
| 74 | 78 | } | |
| 79 | + | } else { | |
| 80 | + | slog.Debug("waiting for daemon spawned by another process", "socket_dir", dir) | |
| 75 | 81 | } | |
| 76 | 82 | ||
| 77 | 83 | return retryDial(ctx, dir, dial, cfg) | |
| @@ -95,6 +101,8 @@ func acquireSpawnLock(dir string) (release func(), acquired bool, err error) { | |||
| 95 | 101 | ||
| 96 | 102 | // Lock exists: take it over only if it looks abandoned. | |
| 97 | 103 | if info, statErr := os.Stat(path); statErr == nil && time.Since(info.ModTime()) > staleLockAge { | |
| 104 | + | age := time.Since(info.ModTime()) | |
| 105 | + | slog.Warn("taking over stale daemon spawn lock", "path", path, "age", age) | |
| 98 | 106 | _ = os.Remove(path) | |
| 99 | 107 | if mkErr := os.Mkdir(path, 0o700); mkErr == nil { | |
| 100 | 108 | return func() { _ = os.Remove(path) }, true, nil | |
| @@ -115,6 +123,7 @@ func retryDial(ctx context.Context, dir string, dial dialFunc, cfg backoffConfig | |||
| 115 | 123 | return t, nil | |
| 116 | 124 | } | |
| 117 | 125 | if !time.Now().Before(deadline) { | |
| 126 | + | slog.Error("daemon did not become reachable before retry budget expired", "socket_dir", dir, "budget", cfg.total) | |
| 118 | 127 | return nil, ErrDaemonUnreachable | |
| 119 | 128 | } | |
| 120 | 129 | select { | |
| @@ -153,6 +162,7 @@ func realSpawn() error { | |||
| 153 | 162 | if err := cmd.Start(); err != nil { | |
| 154 | 163 | return err | |
| 155 | 164 | } | |
| 165 | + | slog.Info("daemon process started", "pid", cmd.Process.Pid) | |
| 156 | 166 | // Detach: we neither wait for nor signal the daemon after launch. | |
| 157 | 167 | return cmd.Process.Release() | |
| 158 | 168 | } | |
| @@ -4,6 +4,7 @@ import ( | |||||
| 4 | "context" | 4 | "context" | ||
| 5 | "errors" | 5 | "errors" | ||
| 6 | "fmt" | 6 | "fmt" | ||
| 7 | + | "log/slog" | |||
| 7 | "os" | 8 | "os" | ||
| 8 | "os/exec" | 9 | "os/exec" | ||
| 9 | "path/filepath" | 10 | "path/filepath" | ||
| @@ -57,6 +58,7 @@ var defaultBackoff = backoffConfig{ | |||||
| 57 | // backoff until the socket is live or the budget expires. | 58 | // backoff until the socket is live or the budget expires. | ||
| 58 | func ensureDaemon(ctx context.Context, dir string, dial dialFunc, spawn spawnFunc, cfg backoffConfig) (ports.Transport, error) { | 59 | func ensureDaemon(ctx context.Context, dir string, dial dialFunc, spawn spawnFunc, cfg backoffConfig) (ports.Transport, error) { | ||
| 59 | if t, err := dial(dir); err == nil { | 60 | if t, err := dial(dir); err == nil { | ||
| 61 | + | slog.Debug("daemon already reachable", "socket_dir", dir) | |||
| 60 | return t, nil | 62 | return t, nil | ||
| 61 | } | 63 | } | ||
| 62 | 64 | ||||
| @@ -69,9 +71,13 @@ func ensureDaemon(ctx context.Context, dir string, dial dialFunc, spawn spawnFun | |||||
| 69 | // dialable (or spawn fails) so late-arriving clients keep waiting | 71 | // dialable (or spawn fails) so late-arriving clients keep waiting | ||
| 70 | // rather than spawning a second daemon. | 72 | // rather than spawning a second daemon. | ||
| 71 | defer release() | 73 | defer release() | ||
| 74 | + | slog.Info("spawning daemon", "socket_dir", dir) | |||
| 72 | if err := spawn(); err != nil { | 75 | if err := spawn(); err != nil { | ||
| 76 | + | slog.Error("daemon spawn failed", "err", err) | |||
| 73 | return nil, fmt.Errorf("vev: spawning daemon: %w", err) | 77 | return nil, fmt.Errorf("vev: spawning daemon: %w", err) | ||
| 74 | } | 78 | } | ||
| 79 | + | } else { | |||
| 80 | + | slog.Debug("waiting for daemon spawned by another process", "socket_dir", dir) | |||
| 75 | } | 81 | } | ||
| 76 | 82 | ||||
| 77 | return retryDial(ctx, dir, dial, cfg) | 83 | return retryDial(ctx, dir, dial, cfg) | ||
| @@ -95,6 +101,8 @@ func acquireSpawnLock(dir string) (release func(), acquired bool, err error) { | |||||
| 95 | 101 | ||||
| 96 | // Lock exists: take it over only if it looks abandoned. | 102 | // Lock exists: take it over only if it looks abandoned. | ||
| 97 | if info, statErr := os.Stat(path); statErr == nil && time.Since(info.ModTime()) > staleLockAge { | 103 | if info, statErr := os.Stat(path); statErr == nil && time.Since(info.ModTime()) > staleLockAge { | ||
| 104 | + | age := time.Since(info.ModTime()) | |||
| 105 | + | slog.Warn("taking over stale daemon spawn lock", "path", path, "age", age) | |||
| 98 | _ = os.Remove(path) | 106 | _ = os.Remove(path) | ||
| 99 | if mkErr := os.Mkdir(path, 0o700); mkErr == nil { | 107 | if mkErr := os.Mkdir(path, 0o700); mkErr == nil { | ||
| 100 | return func() { _ = os.Remove(path) }, true, nil | 108 | return func() { _ = os.Remove(path) }, true, nil | ||
| @@ -115,6 +123,7 @@ func retryDial(ctx context.Context, dir string, dial dialFunc, cfg backoffConfig | |||||
| 115 | return t, nil | 123 | return t, nil | ||
| 116 | } | 124 | } | ||
| 117 | if !time.Now().Before(deadline) { | 125 | if !time.Now().Before(deadline) { | ||
| 126 | + | slog.Error("daemon did not become reachable before retry budget expired", "socket_dir", dir, "budget", cfg.total) | |||
| 118 | return nil, ErrDaemonUnreachable | 127 | return nil, ErrDaemonUnreachable | ||
| 119 | } | 128 | } | ||
| 120 | select { | 129 | select { | ||
| @@ -153,6 +162,7 @@ func realSpawn() error { | |||||
| 153 | if err := cmd.Start(); err != nil { | 162 | if err := cmd.Start(); err != nil { | ||
| 154 | return err | 163 | return err | ||
| 155 | } | 164 | } | ||
| 165 | + | slog.Info("daemon process started", "pid", cmd.Process.Pid) | |||
| 156 | // Detach: we neither wait for nor signal the daemon after launch. | 166 | // Detach: we neither wait for nor signal the daemon after launch. | ||
| 157 | return cmd.Process.Release() | 167 | return cmd.Process.Release() | ||
| 158 | } | 168 | } | ||
A internal/logging/logging.go +97 -0
| @@ -0,0 +1,97 @@ | |||
| 1 | + | package logging | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "io" | |
| 5 | + | "log/slog" | |
| 6 | + | "os" | |
| 7 | + | "path/filepath" | |
| 8 | + | "runtime/debug" | |
| 9 | + | "strings" | |
| 10 | + | "sync" | |
| 11 | + | ) | |
| 12 | + | ||
| 13 | + | type Component string | |
| 14 | + | ||
| 15 | + | const ( | |
| 16 | + | Daemon Component = "daemon" | |
| 17 | + | Client Component = "client" | |
| 18 | + | Stdio Component = "stdio" | |
| 19 | + | ) | |
| 20 | + | ||
| 21 | + | const DefaultMaxBytes = 20 << 20 | |
| 22 | + | ||
| 23 | + | type Config struct { | |
| 24 | + | Dir string | |
| 25 | + | Component Component | |
| 26 | + | Level slog.Level | |
| 27 | + | MaxBytes int64 | |
| 28 | + | RotateAtRuntime bool | |
| 29 | + | } | |
| 30 | + | ||
| 31 | + | func Setup(cfg Config) (*slog.Logger, io.Closer, error) { | |
| 32 | + | if err := os.MkdirAll(cfg.Dir, 0o700); err != nil { | |
| 33 | + | return nil, nil, err | |
| 34 | + | } | |
| 35 | + | ||
| 36 | + | component := cfg.Component | |
| 37 | + | logPath := filepath.Join(cfg.Dir, "vev-"+string(component)+".log") | |
| 38 | + | writer, err := newRotatingWriter(logPath, cfg.MaxBytes, cfg.RotateAtRuntime) | |
| 39 | + | if err != nil { | |
| 40 | + | return nil, nil, err | |
| 41 | + | } | |
| 42 | + | ||
| 43 | + | crashPath := filepath.Join(cfg.Dir, "vev-"+string(component)+"-crash.log") | |
| 44 | + | crashFile, err := os.OpenFile(crashPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) | |
| 45 | + | if err != nil { | |
| 46 | + | _ = writer.Close() | |
| 47 | + | return nil, nil, err | |
| 48 | + | } | |
| 49 | + | if err := debug.SetCrashOutput(crashFile, debug.CrashOptions{}); err != nil { | |
| 50 | + | _ = crashFile.Close() | |
| 51 | + | _ = writer.Close() | |
| 52 | + | return nil, nil, err | |
| 53 | + | } | |
| 54 | + | ||
| 55 | + | logger := slog.New(slog.NewJSONHandler(writer, &slog.HandlerOptions{Level: cfg.Level})).With("component", string(component)) | |
| 56 | + | slog.SetDefault(logger) | |
| 57 | + | ||
| 58 | + | return logger, &setupCloser{log: writer, crash: crashFile}, nil | |
| 59 | + | } | |
| 60 | + | ||
| 61 | + | func ParseLevel(s string) slog.Level { | |
| 62 | + | switch strings.ToLower(strings.TrimSpace(s)) { | |
| 63 | + | case "debug": | |
| 64 | + | return slog.LevelDebug | |
| 65 | + | case "warn", "warning": | |
| 66 | + | return slog.LevelWarn | |
| 67 | + | case "error": | |
| 68 | + | return slog.LevelError | |
| 69 | + | default: | |
| 70 | + | return slog.LevelInfo | |
| 71 | + | } | |
| 72 | + | } | |
| 73 | + | ||
| 74 | + | func EnvLevel() slog.Level { | |
| 75 | + | return ParseLevel(os.Getenv("VEV_LOG")) | |
| 76 | + | } | |
| 77 | + | ||
| 78 | + | type setupCloser struct { | |
| 79 | + | once sync.Once | |
| 80 | + | log io.Closer | |
| 81 | + | crash io.Closer | |
| 82 | + | err error | |
| 83 | + | } | |
| 84 | + | ||
| 85 | + | func (c *setupCloser) Close() error { | |
| 86 | + | c.once.Do(func() { | |
| 87 | + | if c.log != nil { | |
| 88 | + | c.err = c.log.Close() | |
| 89 | + | } | |
| 90 | + | if c.crash != nil { | |
| 91 | + | if err := c.crash.Close(); c.err == nil { | |
| 92 | + | c.err = err | |
| 93 | + | } | |
| 94 | + | } | |
| 95 | + | }) | |
| 96 | + | return c.err | |
| 97 | + | } | |
| @@ -0,0 +1,97 @@ | |||||
| 1 | + | package logging | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "io" | |||
| 5 | + | "log/slog" | |||
| 6 | + | "os" | |||
| 7 | + | "path/filepath" | |||
| 8 | + | "runtime/debug" | |||
| 9 | + | "strings" | |||
| 10 | + | "sync" | |||
| 11 | + | ) | |||
| 12 | + | ||||
| 13 | + | type Component string | |||
| 14 | + | ||||
| 15 | + | const ( | |||
| 16 | + | Daemon Component = "daemon" | |||
| 17 | + | Client Component = "client" | |||
| 18 | + | Stdio Component = "stdio" | |||
| 19 | + | ) | |||
| 20 | + | ||||
| 21 | + | const DefaultMaxBytes = 20 << 20 | |||
| 22 | + | ||||
| 23 | + | type Config struct { | |||
| 24 | + | Dir string | |||
| 25 | + | Component Component | |||
| 26 | + | Level slog.Level | |||
| 27 | + | MaxBytes int64 | |||
| 28 | + | RotateAtRuntime bool | |||
| 29 | + | } | |||
| 30 | + | ||||
| 31 | + | func Setup(cfg Config) (*slog.Logger, io.Closer, error) { | |||
| 32 | + | if err := os.MkdirAll(cfg.Dir, 0o700); err != nil { | |||
| 33 | + | return nil, nil, err | |||
| 34 | + | } | |||
| 35 | + | ||||
| 36 | + | component := cfg.Component | |||
| 37 | + | logPath := filepath.Join(cfg.Dir, "vev-"+string(component)+".log") | |||
| 38 | + | writer, err := newRotatingWriter(logPath, cfg.MaxBytes, cfg.RotateAtRuntime) | |||
| 39 | + | if err != nil { | |||
| 40 | + | return nil, nil, err | |||
| 41 | + | } | |||
| 42 | + | ||||
| 43 | + | crashPath := filepath.Join(cfg.Dir, "vev-"+string(component)+"-crash.log") | |||
| 44 | + | crashFile, err := os.OpenFile(crashPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) | |||
| 45 | + | if err != nil { | |||
| 46 | + | _ = writer.Close() | |||
| 47 | + | return nil, nil, err | |||
| 48 | + | } | |||
| 49 | + | if err := debug.SetCrashOutput(crashFile, debug.CrashOptions{}); err != nil { | |||
| 50 | + | _ = crashFile.Close() | |||
| 51 | + | _ = writer.Close() | |||
| 52 | + | return nil, nil, err | |||
| 53 | + | } | |||
| 54 | + | ||||
| 55 | + | logger := slog.New(slog.NewJSONHandler(writer, &slog.HandlerOptions{Level: cfg.Level})).With("component", string(component)) | |||
| 56 | + | slog.SetDefault(logger) | |||
| 57 | + | ||||
| 58 | + | return logger, &setupCloser{log: writer, crash: crashFile}, nil | |||
| 59 | + | } | |||
| 60 | + | ||||
| 61 | + | func ParseLevel(s string) slog.Level { | |||
| 62 | + | switch strings.ToLower(strings.TrimSpace(s)) { | |||
| 63 | + | case "debug": | |||
| 64 | + | return slog.LevelDebug | |||
| 65 | + | case "warn", "warning": | |||
| 66 | + | return slog.LevelWarn | |||
| 67 | + | case "error": | |||
| 68 | + | return slog.LevelError | |||
| 69 | + | default: | |||
| 70 | + | return slog.LevelInfo | |||
| 71 | + | } | |||
| 72 | + | } | |||
| 73 | + | ||||
| 74 | + | func EnvLevel() slog.Level { | |||
| 75 | + | return ParseLevel(os.Getenv("VEV_LOG")) | |||
| 76 | + | } | |||
| 77 | + | ||||
| 78 | + | type setupCloser struct { | |||
| 79 | + | once sync.Once | |||
| 80 | + | log io.Closer | |||
| 81 | + | crash io.Closer | |||
| 82 | + | err error | |||
| 83 | + | } | |||
| 84 | + | ||||
| 85 | + | func (c *setupCloser) Close() error { | |||
| 86 | + | c.once.Do(func() { | |||
| 87 | + | if c.log != nil { | |||
| 88 | + | c.err = c.log.Close() | |||
| 89 | + | } | |||
| 90 | + | if c.crash != nil { | |||
| 91 | + | if err := c.crash.Close(); c.err == nil { | |||
| 92 | + | c.err = err | |||
| 93 | + | } | |||
| 94 | + | } | |||
| 95 | + | }) | |||
| 96 | + | return c.err | |||
| 97 | + | } | |||
A internal/logging/logging_test.go +259 -0
| @@ -0,0 +1,259 @@ | |||
| 1 | + | package logging | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "encoding/json" | |
| 5 | + | "log/slog" | |
| 6 | + | "os" | |
| 7 | + | "os/exec" | |
| 8 | + | "path/filepath" | |
| 9 | + | "strings" | |
| 10 | + | "sync" | |
| 11 | + | "testing" | |
| 12 | + | ) | |
| 13 | + | ||
| 14 | + | func TestParseLevelAndEnvLevel(t *testing.T) { | |
| 15 | + | tests := []struct { | |
| 16 | + | in string | |
| 17 | + | want slog.Level | |
| 18 | + | }{ | |
| 19 | + | {"debug", slog.LevelDebug}, | |
| 20 | + | {" DEBUG ", slog.LevelDebug}, | |
| 21 | + | {"info", slog.LevelInfo}, | |
| 22 | + | {"", slog.LevelInfo}, | |
| 23 | + | {"warn", slog.LevelWarn}, | |
| 24 | + | {"warning", slog.LevelWarn}, | |
| 25 | + | {"error", slog.LevelError}, | |
| 26 | + | {"bogus", slog.LevelInfo}, | |
| 27 | + | } | |
| 28 | + | for _, tt := range tests { | |
| 29 | + | if got := ParseLevel(tt.in); got != tt.want { | |
| 30 | + | t.Fatalf("ParseLevel(%q) = %v, want %v", tt.in, got, tt.want) | |
| 31 | + | } | |
| 32 | + | } | |
| 33 | + | ||
| 34 | + | t.Setenv("VEV_LOG", "debug") | |
| 35 | + | if got := EnvLevel(); got != slog.LevelDebug { | |
| 36 | + | t.Fatalf("EnvLevel() = %v, want %v", got, slog.LevelDebug) | |
| 37 | + | } | |
| 38 | + | } | |
| 39 | + | ||
| 40 | + | func TestSetupWritesJSONWithComponent(t *testing.T) { | |
| 41 | + | dir := t.TempDir() | |
| 42 | + | logger, closer, err := Setup(Config{Dir: dir, Component: Client, Level: slog.LevelDebug}) | |
| 43 | + | if err != nil { | |
| 44 | + | t.Fatalf("Setup() error = %v", err) | |
| 45 | + | } | |
| 46 | + | defer func() { | |
| 47 | + | if err := closer.Close(); err != nil { | |
| 48 | + | t.Errorf("Close() error = %v", err) | |
| 49 | + | } | |
| 50 | + | }() | |
| 51 | + | ||
| 52 | + | logger.Info("hello", "answer", 42) | |
| 53 | + | ||
| 54 | + | data, err := os.ReadFile(filepath.Join(dir, "vev-client.log")) | |
| 55 | + | if err != nil { | |
| 56 | + | t.Fatalf("ReadFile() error = %v", err) | |
| 57 | + | } | |
| 58 | + | var entry map[string]any | |
| 59 | + | if err := json.Unmarshal(data, &entry); err != nil { | |
| 60 | + | t.Fatalf("log entry is not JSON: %v; data=%q", err, data) | |
| 61 | + | } | |
| 62 | + | if entry["component"] != "client" { | |
| 63 | + | t.Fatalf("component = %v, want client; entry=%v", entry["component"], entry) | |
| 64 | + | } | |
| 65 | + | if entry["msg"] != "hello" || entry["answer"] != float64(42) { | |
| 66 | + | t.Fatalf("unexpected entry fields: %v", entry) | |
| 67 | + | } | |
| 68 | + | if _, err := os.Stat(filepath.Join(dir, "vev-client-crash.log")); err != nil { | |
| 69 | + | t.Fatalf("crash log not created: %v", err) | |
| 70 | + | } | |
| 71 | + | } | |
| 72 | + | ||
| 73 | + | func TestRuntimeRotation(t *testing.T) { | |
| 74 | + | dir := t.TempDir() | |
| 75 | + | path := filepath.Join(dir, "vev-daemon.log") | |
| 76 | + | w, err := newRotatingWriter(path, 10, true) | |
| 77 | + | if err != nil { | |
| 78 | + | t.Fatalf("newRotatingWriter() error = %v", err) | |
| 79 | + | } | |
| 80 | + | defer func() { | |
| 81 | + | if err := w.Close(); err != nil { | |
| 82 | + | t.Errorf("Close() error = %v", err) | |
| 83 | + | } | |
| 84 | + | }() | |
| 85 | + | ||
| 86 | + | if _, err := w.Write([]byte("0123456789")); err != nil { | |
| 87 | + | t.Fatalf("Write() error = %v", err) | |
| 88 | + | } | |
| 89 | + | if _, err := os.Stat(path + ".old"); err != nil { | |
| 90 | + | t.Fatalf("rotated file missing: %v", err) | |
| 91 | + | } | |
| 92 | + | live, err := os.ReadFile(path) | |
| 93 | + | if err != nil { | |
| 94 | + | t.Fatalf("read live file: %v", err) | |
| 95 | + | } | |
| 96 | + | if len(live) != 0 { | |
| 97 | + | t.Fatalf("live file length = %d, want 0 after rotation", len(live)) | |
| 98 | + | } | |
| 99 | + | old, err := os.ReadFile(path + ".old") | |
| 100 | + | if err != nil { | |
| 101 | + | t.Fatalf("read old file: %v", err) | |
| 102 | + | } | |
| 103 | + | if string(old) != "0123456789" { | |
| 104 | + | t.Fatalf("old file = %q, want original write", old) | |
| 105 | + | } | |
| 106 | + | } | |
| 107 | + | ||
| 108 | + | func TestStartupOnlyRotation(t *testing.T) { | |
| 109 | + | dir := t.TempDir() | |
| 110 | + | path := filepath.Join(dir, "vev-client.log") | |
| 111 | + | if err := os.WriteFile(path, []byte("already-too-large"), 0o600); err != nil { | |
| 112 | + | t.Fatalf("seed log: %v", err) | |
| 113 | + | } | |
| 114 | + | w, err := newRotatingWriter(path, 5, false) | |
| 115 | + | if err != nil { | |
| 116 | + | t.Fatalf("newRotatingWriter() error = %v", err) | |
| 117 | + | } | |
| 118 | + | defer func() { | |
| 119 | + | if err := w.Close(); err != nil { | |
| 120 | + | t.Errorf("Close() error = %v", err) | |
| 121 | + | } | |
| 122 | + | }() | |
| 123 | + | ||
| 124 | + | if old, err := os.ReadFile(path + ".old"); err != nil || string(old) != "already-too-large" { | |
| 125 | + | t.Fatalf("startup rotation old = %q, err = %v", old, err) | |
| 126 | + | } | |
| 127 | + | if _, err := w.Write([]byte("first")); err != nil { | |
| 128 | + | t.Fatalf("Write(first) error = %v", err) | |
| 129 | + | } | |
| 130 | + | if _, err := w.Write([]byte("second")); err != nil { | |
| 131 | + | t.Fatalf("Write(second) error = %v", err) | |
| 132 | + | } | |
| 133 | + | if old, err := os.ReadFile(path + ".old"); err != nil || string(old) != "already-too-large" { | |
| 134 | + | t.Fatalf("startup-only mode rotated during writes; old = %q, err = %v", old, err) | |
| 135 | + | } | |
| 136 | + | live, err := os.ReadFile(path) | |
| 137 | + | if err != nil { | |
| 138 | + | t.Fatalf("read live file: %v", err) | |
| 139 | + | } | |
| 140 | + | if string(live) != "firstsecond" { | |
| 141 | + | t.Fatalf("live file = %q, want appended writes", live) | |
| 142 | + | } | |
| 143 | + | } | |
| 144 | + | ||
| 145 | + | func TestCrashOutputCapturesPanicStack(t *testing.T) { | |
| 146 | + | dir := t.TempDir() | |
| 147 | + | cmd := exec.Command(os.Args[0], "-test.run=TestCrashOutputHelper") | |
| 148 | + | cmd.Env = append(os.Environ(), "VEV_CRASH_HELPER=1", "VEV_CRASH_DIR="+dir) | |
| 149 | + | if err := cmd.Run(); err == nil { | |
| 150 | + | t.Fatal("crash helper exited successfully, want panic failure") | |
| 151 | + | } | |
| 152 | + | ||
| 153 | + | data, err := os.ReadFile(filepath.Join(dir, "vev-daemon-crash.log")) | |
| 154 | + | if err != nil { | |
| 155 | + | t.Fatalf("read crash log: %v", err) | |
| 156 | + | } | |
| 157 | + | if !strings.Contains(string(data), "intentional crash for SetCrashOutput test") || !strings.Contains(string(data), "goroutine") { | |
| 158 | + | t.Fatalf("crash log did not contain panic stack; data=%q", data) | |
| 159 | + | } | |
| 160 | + | } | |
| 161 | + | ||
| 162 | + | func TestCrashOutputHelper(t *testing.T) { | |
| 163 | + | if os.Getenv("VEV_CRASH_HELPER") != "1" { | |
| 164 | + | return | |
| 165 | + | } | |
| 166 | + | if _, _, err := Setup(Config{Dir: os.Getenv("VEV_CRASH_DIR"), Component: Daemon, Level: slog.LevelInfo}); err != nil { | |
| 167 | + | panic(err) | |
| 168 | + | } | |
| 169 | + | panic("intentional crash for SetCrashOutput test") | |
| 170 | + | } | |
| 171 | + | ||
| 172 | + | func TestStartupOnlyConcurrentRotationRaceIsIgnored(t *testing.T) { | |
| 173 | + | dir := t.TempDir() | |
| 174 | + | path := filepath.Join(dir, "vev-client.log") | |
| 175 | + | if err := os.WriteFile(path, []byte("already-too-large"), 0o600); err != nil { | |
| 176 | + | t.Fatalf("seed log: %v", err) | |
| 177 | + | } | |
| 178 | + | ||
| 179 | + | var wg sync.WaitGroup | |
| 180 | + | errCh := make(chan error, 8) | |
| 181 | + | for i := 0; i < cap(errCh); i++ { | |
| 182 | + | wg.Add(1) | |
| 183 | + | go func() { | |
| 184 | + | defer wg.Done() | |
| 185 | + | w, err := newRotatingWriter(path, 5, false) | |
| 186 | + | if err != nil { | |
| 187 | + | errCh <- err | |
| 188 | + | return | |
| 189 | + | } | |
| 190 | + | if _, err := w.Write([]byte("x")); err != nil { | |
| 191 | + | errCh <- err | |
| 192 | + | } | |
| 193 | + | if err := w.Close(); err != nil { | |
| 194 | + | errCh <- err | |
| 195 | + | } | |
| 196 | + | }() | |
| 197 | + | } | |
| 198 | + | wg.Wait() | |
| 199 | + | close(errCh) | |
| 200 | + | for err := range errCh { | |
| 201 | + | if err != nil { | |
| 202 | + | t.Fatalf("concurrent startup writer failed: %v", err) | |
| 203 | + | } | |
| 204 | + | } | |
| 205 | + | if _, err := os.Stat(path); err != nil { | |
| 206 | + | t.Fatalf("live log missing after concurrent startup rotation: %v", err) | |
| 207 | + | } | |
| 208 | + | if _, err := os.Stat(path + ".old"); err != nil { | |
| 209 | + | t.Fatalf("rotated log missing after concurrent startup rotation: %v", err) | |
| 210 | + | } | |
| 211 | + | } | |
| 212 | + | ||
| 213 | + | func TestDoubleClose(t *testing.T) { | |
| 214 | + | _, closer, err := Setup(Config{Dir: t.TempDir(), Component: Stdio, Level: slog.LevelInfo}) | |
| 215 | + | if err != nil { | |
| 216 | + | t.Fatalf("Setup() error = %v", err) | |
| 217 | + | } | |
| 218 | + | if err := closer.Close(); err != nil { | |
| 219 | + | t.Fatalf("first Close() error = %v", err) | |
| 220 | + | } | |
| 221 | + | if err := closer.Close(); err != nil { | |
| 222 | + | t.Fatalf("second Close() error = %v", err) | |
| 223 | + | } | |
| 224 | + | } | |
| 225 | + | ||
| 226 | + | func TestRotationRenameFailureIsNonFatal(t *testing.T) { | |
| 227 | + | dir := t.TempDir() | |
| 228 | + | path := filepath.Join(dir, "vev-daemon.log") | |
| 229 | + | if err := os.WriteFile(path, nil, 0o600); err != nil { | |
| 230 | + | t.Fatalf("seed log: %v", err) | |
| 231 | + | } | |
| 232 | + | if err := os.Mkdir(path+".old", 0o700); err != nil { | |
| 233 | + | t.Fatalf("make rename obstacle: %v", err) | |
| 234 | + | } | |
| 235 | + | if err := os.WriteFile(filepath.Join(path+".old", "child"), []byte("x"), 0o600); err != nil { | |
| 236 | + | t.Fatalf("make non-empty obstacle: %v", err) | |
| 237 | + | } | |
| 238 | + | ||
| 239 | + | w, err := newRotatingWriter(path, 4, true) | |
| 240 | + | if err != nil { | |
| 241 | + | t.Fatalf("newRotatingWriter() error = %v", err) | |
| 242 | + | } | |
| 243 | + | defer func() { | |
| 244 | + | if err := w.Close(); err != nil { | |
| 245 | + | t.Errorf("Close() error = %v", err) | |
| 246 | + | } | |
| 247 | + | }() | |
| 248 | + | ||
| 249 | + | if _, err := w.Write([]byte("exceeds")); err != nil { | |
| 250 | + | t.Fatalf("Write() error = %v", err) | |
| 251 | + | } | |
| 252 | + | live, err := os.ReadFile(path) | |
| 253 | + | if err != nil { | |
| 254 | + | t.Fatalf("read live file: %v", err) | |
| 255 | + | } | |
| 256 | + | if !strings.Contains(string(live), "exceeds") { | |
| 257 | + | t.Fatalf("write was not preserved after failed rename: %q", live) | |
| 258 | + | } | |
| 259 | + | } | |
| @@ -0,0 +1,259 @@ | |||||
| 1 | + | package logging | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "encoding/json" | |||
| 5 | + | "log/slog" | |||
| 6 | + | "os" | |||
| 7 | + | "os/exec" | |||
| 8 | + | "path/filepath" | |||
| 9 | + | "strings" | |||
| 10 | + | "sync" | |||
| 11 | + | "testing" | |||
| 12 | + | ) | |||
| 13 | + | ||||
| 14 | + | func TestParseLevelAndEnvLevel(t *testing.T) { | |||
| 15 | + | tests := []struct { | |||
| 16 | + | in string | |||
| 17 | + | want slog.Level | |||
| 18 | + | }{ | |||
| 19 | + | {"debug", slog.LevelDebug}, | |||
| 20 | + | {" DEBUG ", slog.LevelDebug}, | |||
| 21 | + | {"info", slog.LevelInfo}, | |||
| 22 | + | {"", slog.LevelInfo}, | |||
| 23 | + | {"warn", slog.LevelWarn}, | |||
| 24 | + | {"warning", slog.LevelWarn}, | |||
| 25 | + | {"error", slog.LevelError}, | |||
| 26 | + | {"bogus", slog.LevelInfo}, | |||
| 27 | + | } | |||
| 28 | + | for _, tt := range tests { | |||
| 29 | + | if got := ParseLevel(tt.in); got != tt.want { | |||
| 30 | + | t.Fatalf("ParseLevel(%q) = %v, want %v", tt.in, got, tt.want) | |||
| 31 | + | } | |||
| 32 | + | } | |||
| 33 | + | ||||
| 34 | + | t.Setenv("VEV_LOG", "debug") | |||
| 35 | + | if got := EnvLevel(); got != slog.LevelDebug { | |||
| 36 | + | t.Fatalf("EnvLevel() = %v, want %v", got, slog.LevelDebug) | |||
| 37 | + | } | |||
| 38 | + | } | |||
| 39 | + | ||||
| 40 | + | func TestSetupWritesJSONWithComponent(t *testing.T) { | |||
| 41 | + | dir := t.TempDir() | |||
| 42 | + | logger, closer, err := Setup(Config{Dir: dir, Component: Client, Level: slog.LevelDebug}) | |||
| 43 | + | if err != nil { | |||
| 44 | + | t.Fatalf("Setup() error = %v", err) | |||
| 45 | + | } | |||
| 46 | + | defer func() { | |||
| 47 | + | if err := closer.Close(); err != nil { | |||
| 48 | + | t.Errorf("Close() error = %v", err) | |||
| 49 | + | } | |||
| 50 | + | }() | |||
| 51 | + | ||||
| 52 | + | logger.Info("hello", "answer", 42) | |||
| 53 | + | ||||
| 54 | + | data, err := os.ReadFile(filepath.Join(dir, "vev-client.log")) | |||
| 55 | + | if err != nil { | |||
| 56 | + | t.Fatalf("ReadFile() error = %v", err) | |||
| 57 | + | } | |||
| 58 | + | var entry map[string]any | |||
| 59 | + | if err := json.Unmarshal(data, &entry); err != nil { | |||
| 60 | + | t.Fatalf("log entry is not JSON: %v; data=%q", err, data) | |||
| 61 | + | } | |||
| 62 | + | if entry["component"] != "client" { | |||
| 63 | + | t.Fatalf("component = %v, want client; entry=%v", entry["component"], entry) | |||
| 64 | + | } | |||
| 65 | + | if entry["msg"] != "hello" || entry["answer"] != float64(42) { | |||
| 66 | + | t.Fatalf("unexpected entry fields: %v", entry) | |||
| 67 | + | } | |||
| 68 | + | if _, err := os.Stat(filepath.Join(dir, "vev-client-crash.log")); err != nil { | |||
| 69 | + | t.Fatalf("crash log not created: %v", err) | |||
| 70 | + | } | |||
| 71 | + | } | |||
| 72 | + | ||||
| 73 | + | func TestRuntimeRotation(t *testing.T) { | |||
| 74 | + | dir := t.TempDir() | |||
| 75 | + | path := filepath.Join(dir, "vev-daemon.log") | |||
| 76 | + | w, err := newRotatingWriter(path, 10, true) | |||
| 77 | + | if err != nil { | |||
| 78 | + | t.Fatalf("newRotatingWriter() error = %v", err) | |||
| 79 | + | } | |||
| 80 | + | defer func() { | |||
| 81 | + | if err := w.Close(); err != nil { | |||
| 82 | + | t.Errorf("Close() error = %v", err) | |||
| 83 | + | } | |||
| 84 | + | }() | |||
| 85 | + | ||||
| 86 | + | if _, err := w.Write([]byte("0123456789")); err != nil { | |||
| 87 | + | t.Fatalf("Write() error = %v", err) | |||
| 88 | + | } | |||
| 89 | + | if _, err := os.Stat(path + ".old"); err != nil { | |||
| 90 | + | t.Fatalf("rotated file missing: %v", err) | |||
| 91 | + | } | |||
| 92 | + | live, err := os.ReadFile(path) | |||
| 93 | + | if err != nil { | |||
| 94 | + | t.Fatalf("read live file: %v", err) | |||
| 95 | + | } | |||
| 96 | + | if len(live) != 0 { | |||
| 97 | + | t.Fatalf("live file length = %d, want 0 after rotation", len(live)) | |||
| 98 | + | } | |||
| 99 | + | old, err := os.ReadFile(path + ".old") | |||
| 100 | + | if err != nil { | |||
| 101 | + | t.Fatalf("read old file: %v", err) | |||
| 102 | + | } | |||
| 103 | + | if string(old) != "0123456789" { | |||
| 104 | + | t.Fatalf("old file = %q, want original write", old) | |||
| 105 | + | } | |||
| 106 | + | } | |||
| 107 | + | ||||
| 108 | + | func TestStartupOnlyRotation(t *testing.T) { | |||
| 109 | + | dir := t.TempDir() | |||
| 110 | + | path := filepath.Join(dir, "vev-client.log") | |||
| 111 | + | if err := os.WriteFile(path, []byte("already-too-large"), 0o600); err != nil { | |||
| 112 | + | t.Fatalf("seed log: %v", err) | |||
| 113 | + | } | |||
| 114 | + | w, err := newRotatingWriter(path, 5, false) | |||
| 115 | + | if err != nil { | |||
| 116 | + | t.Fatalf("newRotatingWriter() error = %v", err) | |||
| 117 | + | } | |||
| 118 | + | defer func() { | |||
| 119 | + | if err := w.Close(); err != nil { | |||
| 120 | + | t.Errorf("Close() error = %v", err) | |||
| 121 | + | } | |||
| 122 | + | }() | |||
| 123 | + | ||||
| 124 | + | if old, err := os.ReadFile(path + ".old"); err != nil || string(old) != "already-too-large" { | |||
| 125 | + | t.Fatalf("startup rotation old = %q, err = %v", old, err) | |||
| 126 | + | } | |||
| 127 | + | if _, err := w.Write([]byte("first")); err != nil { | |||
| 128 | + | t.Fatalf("Write(first) error = %v", err) | |||
| 129 | + | } | |||
| 130 | + | if _, err := w.Write([]byte("second")); err != nil { | |||
| 131 | + | t.Fatalf("Write(second) error = %v", err) | |||
| 132 | + | } | |||
| 133 | + | if old, err := os.ReadFile(path + ".old"); err != nil || string(old) != "already-too-large" { | |||
| 134 | + | t.Fatalf("startup-only mode rotated during writes; old = %q, err = %v", old, err) | |||
| 135 | + | } | |||
| 136 | + | live, err := os.ReadFile(path) | |||
| 137 | + | if err != nil { | |||
| 138 | + | t.Fatalf("read live file: %v", err) | |||
| 139 | + | } | |||
| 140 | + | if string(live) != "firstsecond" { | |||
| 141 | + | t.Fatalf("live file = %q, want appended writes", live) | |||
| 142 | + | } | |||
| 143 | + | } | |||
| 144 | + | ||||
| 145 | + | func TestCrashOutputCapturesPanicStack(t *testing.T) { | |||
| 146 | + | dir := t.TempDir() | |||
| 147 | + | cmd := exec.Command(os.Args[0], "-test.run=TestCrashOutputHelper") | |||
| 148 | + | cmd.Env = append(os.Environ(), "VEV_CRASH_HELPER=1", "VEV_CRASH_DIR="+dir) | |||
| 149 | + | if err := cmd.Run(); err == nil { | |||
| 150 | + | t.Fatal("crash helper exited successfully, want panic failure") | |||
| 151 | + | } | |||
| 152 | + | ||||
| 153 | + | data, err := os.ReadFile(filepath.Join(dir, "vev-daemon-crash.log")) | |||
| 154 | + | if err != nil { | |||
| 155 | + | t.Fatalf("read crash log: %v", err) | |||
| 156 | + | } | |||
| 157 | + | if !strings.Contains(string(data), "intentional crash for SetCrashOutput test") || !strings.Contains(string(data), "goroutine") { | |||
| 158 | + | t.Fatalf("crash log did not contain panic stack; data=%q", data) | |||
| 159 | + | } | |||
| 160 | + | } | |||
| 161 | + | ||||
| 162 | + | func TestCrashOutputHelper(t *testing.T) { | |||
| 163 | + | if os.Getenv("VEV_CRASH_HELPER") != "1" { | |||
| 164 | + | return | |||
| 165 | + | } | |||
| 166 | + | if _, _, err := Setup(Config{Dir: os.Getenv("VEV_CRASH_DIR"), Component: Daemon, Level: slog.LevelInfo}); err != nil { | |||
| 167 | + | panic(err) | |||
| 168 | + | } | |||
| 169 | + | panic("intentional crash for SetCrashOutput test") | |||
| 170 | + | } | |||
| 171 | + | ||||
| 172 | + | func TestStartupOnlyConcurrentRotationRaceIsIgnored(t *testing.T) { | |||
| 173 | + | dir := t.TempDir() | |||
| 174 | + | path := filepath.Join(dir, "vev-client.log") | |||
| 175 | + | if err := os.WriteFile(path, []byte("already-too-large"), 0o600); err != nil { | |||
| 176 | + | t.Fatalf("seed log: %v", err) | |||
| 177 | + | } | |||
| 178 | + | ||||
| 179 | + | var wg sync.WaitGroup | |||
| 180 | + | errCh := make(chan error, 8) | |||
| 181 | + | for i := 0; i < cap(errCh); i++ { | |||
| 182 | + | wg.Add(1) | |||
| 183 | + | go func() { | |||
| 184 | + | defer wg.Done() | |||
| 185 | + | w, err := newRotatingWriter(path, 5, false) | |||
| 186 | + | if err != nil { | |||
| 187 | + | errCh <- err | |||
| 188 | + | return | |||
| 189 | + | } | |||
| 190 | + | if _, err := w.Write([]byte("x")); err != nil { | |||
| 191 | + | errCh <- err | |||
| 192 | + | } | |||
| 193 | + | if err := w.Close(); err != nil { | |||
| 194 | + | errCh <- err | |||
| 195 | + | } | |||
| 196 | + | }() | |||
| 197 | + | } | |||
| 198 | + | wg.Wait() | |||
| 199 | + | close(errCh) | |||
| 200 | + | for err := range errCh { | |||
| 201 | + | if err != nil { | |||
| 202 | + | t.Fatalf("concurrent startup writer failed: %v", err) | |||
| 203 | + | } | |||
| 204 | + | } | |||
| 205 | + | if _, err := os.Stat(path); err != nil { | |||
| 206 | + | t.Fatalf("live log missing after concurrent startup rotation: %v", err) | |||
| 207 | + | } | |||
| 208 | + | if _, err := os.Stat(path + ".old"); err != nil { | |||
| 209 | + | t.Fatalf("rotated log missing after concurrent startup rotation: %v", err) | |||
| 210 | + | } | |||
| 211 | + | } | |||
| 212 | + | ||||
| 213 | + | func TestDoubleClose(t *testing.T) { | |||
| 214 | + | _, closer, err := Setup(Config{Dir: t.TempDir(), Component: Stdio, Level: slog.LevelInfo}) | |||
| 215 | + | if err != nil { | |||
| 216 | + | t.Fatalf("Setup() error = %v", err) | |||
| 217 | + | } | |||
| 218 | + | if err := closer.Close(); err != nil { | |||
| 219 | + | t.Fatalf("first Close() error = %v", err) | |||
| 220 | + | } | |||
| 221 | + | if err := closer.Close(); err != nil { | |||
| 222 | + | t.Fatalf("second Close() error = %v", err) | |||
| 223 | + | } | |||
| 224 | + | } | |||
| 225 | + | ||||
| 226 | + | func TestRotationRenameFailureIsNonFatal(t *testing.T) { | |||
| 227 | + | dir := t.TempDir() | |||
| 228 | + | path := filepath.Join(dir, "vev-daemon.log") | |||
| 229 | + | if err := os.WriteFile(path, nil, 0o600); err != nil { | |||
| 230 | + | t.Fatalf("seed log: %v", err) | |||
| 231 | + | } | |||
| 232 | + | if err := os.Mkdir(path+".old", 0o700); err != nil { | |||
| 233 | + | t.Fatalf("make rename obstacle: %v", err) | |||
| 234 | + | } | |||
| 235 | + | if err := os.WriteFile(filepath.Join(path+".old", "child"), []byte("x"), 0o600); err != nil { | |||
| 236 | + | t.Fatalf("make non-empty obstacle: %v", err) | |||
| 237 | + | } | |||
| 238 | + | ||||
| 239 | + | w, err := newRotatingWriter(path, 4, true) | |||
| 240 | + | if err != nil { | |||
| 241 | + | t.Fatalf("newRotatingWriter() error = %v", err) | |||
| 242 | + | } | |||
| 243 | + | defer func() { | |||
| 244 | + | if err := w.Close(); err != nil { | |||
| 245 | + | t.Errorf("Close() error = %v", err) | |||
| 246 | + | } | |||
| 247 | + | }() | |||
| 248 | + | ||||
| 249 | + | if _, err := w.Write([]byte("exceeds")); err != nil { | |||
| 250 | + | t.Fatalf("Write() error = %v", err) | |||
| 251 | + | } | |||
| 252 | + | live, err := os.ReadFile(path) | |||
| 253 | + | if err != nil { | |||
| 254 | + | t.Fatalf("read live file: %v", err) | |||
| 255 | + | } | |||
| 256 | + | if !strings.Contains(string(live), "exceeds") { | |||
| 257 | + | t.Fatalf("write was not preserved after failed rename: %q", live) | |||
| 258 | + | } | |||
| 259 | + | } | |||
A internal/logging/rotate.go +82 -0
| @@ -0,0 +1,82 @@ | |||
| 1 | + | package logging | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "os" | |
| 5 | + | "sync" | |
| 6 | + | ) | |
| 7 | + | ||
| 8 | + | type rotatingWriter struct { | |
| 9 | + | mu sync.Mutex | |
| 10 | + | path string | |
| 11 | + | max int64 | |
| 12 | + | runtime bool | |
| 13 | + | file *os.File | |
| 14 | + | size int64 | |
| 15 | + | closed bool | |
| 16 | + | } | |
| 17 | + | ||
| 18 | + | func newRotatingWriter(path string, maxBytes int64, rotateAtRuntime bool) (*rotatingWriter, error) { | |
| 19 | + | if maxBytes <= 0 { | |
| 20 | + | maxBytes = DefaultMaxBytes | |
| 21 | + | } | |
| 22 | + | rw := &rotatingWriter{path: path, max: maxBytes, runtime: rotateAtRuntime} | |
| 23 | + | if err := rw.open(); err != nil { | |
| 24 | + | return nil, err | |
| 25 | + | } | |
| 26 | + | if !rotateAtRuntime && rw.size >= rw.max { | |
| 27 | + | rw.rotateLocked() | |
| 28 | + | } | |
| 29 | + | return rw, nil | |
| 30 | + | } | |
| 31 | + | ||
| 32 | + | func (w *rotatingWriter) Write(p []byte) (int, error) { | |
| 33 | + | w.mu.Lock() | |
| 34 | + | defer w.mu.Unlock() | |
| 35 | + | ||
| 36 | + | if w.closed { | |
| 37 | + | return 0, os.ErrClosed | |
| 38 | + | } | |
| 39 | + | n, err := w.file.Write(p) | |
| 40 | + | w.size += int64(n) | |
| 41 | + | if err == nil && w.runtime && w.size >= w.max { | |
| 42 | + | w.rotateLocked() | |
| 43 | + | } | |
| 44 | + | return n, err | |
| 45 | + | } | |
| 46 | + | ||
| 47 | + | func (w *rotatingWriter) Close() error { | |
| 48 | + | w.mu.Lock() | |
| 49 | + | defer w.mu.Unlock() | |
| 50 | + | ||
| 51 | + | if w.closed { | |
| 52 | + | return nil | |
| 53 | + | } | |
| 54 | + | w.closed = true | |
| 55 | + | return w.file.Close() | |
| 56 | + | } | |
| 57 | + | ||
| 58 | + | func (w *rotatingWriter) open() error { | |
| 59 | + | f, err := os.OpenFile(w.path, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) | |
| 60 | + | if err != nil { | |
| 61 | + | return err | |
| 62 | + | } | |
| 63 | + | info, err := f.Stat() | |
| 64 | + | if err != nil { | |
| 65 | + | _ = f.Close() | |
| 66 | + | return err | |
| 67 | + | } | |
| 68 | + | w.file = f | |
| 69 | + | w.size = info.Size() | |
| 70 | + | return nil | |
| 71 | + | } | |
| 72 | + | ||
| 73 | + | func (w *rotatingWriter) rotateLocked() { | |
| 74 | + | old := w.file | |
| 75 | + | _ = os.Rename(w.path, w.path+".old") | |
| 76 | + | if err := w.open(); err != nil { | |
| 77 | + | w.file = old | |
| 78 | + | w.size = w.max | |
| 79 | + | return | |
| 80 | + | } | |
| 81 | + | _ = old.Close() | |
| 82 | + | } | |
| @@ -0,0 +1,82 @@ | |||||
| 1 | + | package logging | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "os" | |||
| 5 | + | "sync" | |||
| 6 | + | ) | |||
| 7 | + | ||||
| 8 | + | type rotatingWriter struct { | |||
| 9 | + | mu sync.Mutex | |||
| 10 | + | path string | |||
| 11 | + | max int64 | |||
| 12 | + | runtime bool | |||
| 13 | + | file *os.File | |||
| 14 | + | size int64 | |||
| 15 | + | closed bool | |||
| 16 | + | } | |||
| 17 | + | ||||
| 18 | + | func newRotatingWriter(path string, maxBytes int64, rotateAtRuntime bool) (*rotatingWriter, error) { | |||
| 19 | + | if maxBytes <= 0 { | |||
| 20 | + | maxBytes = DefaultMaxBytes | |||
| 21 | + | } | |||
| 22 | + | rw := &rotatingWriter{path: path, max: maxBytes, runtime: rotateAtRuntime} | |||
| 23 | + | if err := rw.open(); err != nil { | |||
| 24 | + | return nil, err | |||
| 25 | + | } | |||
| 26 | + | if !rotateAtRuntime && rw.size >= rw.max { | |||
| 27 | + | rw.rotateLocked() | |||
| 28 | + | } | |||
| 29 | + | return rw, nil | |||
| 30 | + | } | |||
| 31 | + | ||||
| 32 | + | func (w *rotatingWriter) Write(p []byte) (int, error) { | |||
| 33 | + | w.mu.Lock() | |||
| 34 | + | defer w.mu.Unlock() | |||
| 35 | + | ||||
| 36 | + | if w.closed { | |||
| 37 | + | return 0, os.ErrClosed | |||
| 38 | + | } | |||
| 39 | + | n, err := w.file.Write(p) | |||
| 40 | + | w.size += int64(n) | |||
| 41 | + | if err == nil && w.runtime && w.size >= w.max { | |||
| 42 | + | w.rotateLocked() | |||
| 43 | + | } | |||
| 44 | + | return n, err | |||
| 45 | + | } | |||
| 46 | + | ||||
| 47 | + | func (w *rotatingWriter) Close() error { | |||
| 48 | + | w.mu.Lock() | |||
| 49 | + | defer w.mu.Unlock() | |||
| 50 | + | ||||
| 51 | + | if w.closed { | |||
| 52 | + | return nil | |||
| 53 | + | } | |||
| 54 | + | w.closed = true | |||
| 55 | + | return w.file.Close() | |||
| 56 | + | } | |||
| 57 | + | ||||
| 58 | + | func (w *rotatingWriter) open() error { | |||
| 59 | + | f, err := os.OpenFile(w.path, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) | |||
| 60 | + | if err != nil { | |||
| 61 | + | return err | |||
| 62 | + | } | |||
| 63 | + | info, err := f.Stat() | |||
| 64 | + | if err != nil { | |||
| 65 | + | _ = f.Close() | |||
| 66 | + | return err | |||
| 67 | + | } | |||
| 68 | + | w.file = f | |||
| 69 | + | w.size = info.Size() | |||
| 70 | + | return nil | |||
| 71 | + | } | |||
| 72 | + | ||||
| 73 | + | func (w *rotatingWriter) rotateLocked() { | |||
| 74 | + | old := w.file | |||
| 75 | + | _ = os.Rename(w.path, w.path+".old") | |||
| 76 | + | if err := w.open(); err != nil { | |||
| 77 | + | w.file = old | |||
| 78 | + | w.size = w.max | |||
| 79 | + | return | |||
| 80 | + | } | |||
| 81 | + | _ = old.Close() | |||
| 82 | + | } | |||
M internal/usecase/client/client.go +31 -14
| @@ -119,8 +119,10 @@ const ( | |||
| 119 | 119 | // Run connects via dialer and runs the attach client. It owns the terminal | |
| 120 | 120 | // lifecycle above attach attempts so raw mode remains active while a live | |
| 121 | 121 | // client process redials a lost link. | |
| 122 | - | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk ports.Clock, intent uint8, name string) (retErr error) { | |
| 123 | - | log := slog.Default().With("component", "client") | |
| 122 | + | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk ports.Clock, intent uint8, name string, log *slog.Logger) (retErr error) { | |
| 123 | + | if log == nil { | |
| 124 | + | log = slog.Default() | |
| 125 | + | } | |
| 124 | 126 | ms := milestones{} | |
| 125 | 127 | ||
| 126 | 128 | defer func() { | |
| @@ -179,6 +181,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk port | |||
| 179 | 181 | if resumeToken == 0 || ctx.Err() != nil { | |
| 180 | 182 | return err | |
| 181 | 183 | } | |
| 184 | + | log.Warn("reconnect dial failed", "err", err, "backoff", backoff) | |
| 182 | 185 | drawStatus() | |
| 183 | 186 | if !reconnectSleep(ctx, backoff) { | |
| 184 | 187 | return ctx.Err() | |
| @@ -189,7 +192,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk port | |||
| 189 | 192 | } | |
| 190 | 193 | ms.dialed = true | |
| 191 | 194 | ||
| 192 | - | result := attachOnce(ctx, transport, term, clk, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus) | |
| 195 | + | result := attachOnce(ctx, transport, term, clk, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus, log) | |
| 193 | 196 | if result.welcomed { | |
| 194 | 197 | backoff = defaultReconnectBackoff.initial | |
| 195 | 198 | } | |
| @@ -205,6 +208,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk port | |||
| 205 | 208 | clearStatus() | |
| 206 | 209 | return result.err | |
| 207 | 210 | } | |
| 211 | + | log.Warn("reconnecting after attach error", "err", result.err, "backoff", backoff) | |
| 208 | 212 | drawStatus() | |
| 209 | 213 | if !reconnectSleep(ctx, backoff) { | |
| 210 | 214 | clearStatus() | |
| @@ -251,7 +255,7 @@ func shouldReconnect(err error) bool { | |||
| 251 | 255 | // | |
| 252 | 256 | // It is kept as a compatibility wrapper for callers that still own dialing. | |
| 253 | 257 | func Attach(ctx context.Context, transport ports.Transport, term ports.Terminal, clk ports.Clock, intent uint8, name string) error { | |
| 254 | - | return Run(ctx, singleTransportDialer{transport: transport}, term, clk, intent, name) | |
| 258 | + | return Run(ctx, singleTransportDialer{transport: transport}, term, clk, intent, name, slog.Default()) | |
| 255 | 259 | } | |
| 256 | 260 | ||
| 257 | 261 | type singleTransportDialer struct{ transport ports.Transport } | |
| @@ -266,7 +270,7 @@ type attachResult struct { | |||
| 266 | 270 | err error | |
| 267 | 271 | } | |
| 268 | 272 | ||
| 269 | - | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, clk ports.Clock, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func()) attachResult { | |
| 273 | + | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, clk ports.Clock, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func(), log *slog.Logger) attachResult { | |
| 270 | 274 | // 1. Handshake: send Hello with our size and TERM. | |
| 271 | 275 | size, err := term.Size() | |
| 272 | 276 | if err != nil { | |
| @@ -306,6 +310,7 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||
| 306 | 310 | } | |
| 307 | 311 | resumeToken = welcome.ResumeToken | |
| 308 | 312 | ms.welcomed = true | |
| 313 | + | log.Debug("welcomed by daemon", "resume_token_present", resumeToken != 0) | |
| 309 | 314 | case ports.MsgError: | |
| 310 | 315 | em, derr := ports.UnmarshalErrorMsg(reply.Payload) | |
| 311 | 316 | if derr != nil { | |
| @@ -331,13 +336,13 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||
| 331 | 336 | sendCh := make(chan ports.Frame, sendQueueDepth) | |
| 332 | 337 | sendErrCh := make(chan error, 1) | |
| 333 | 338 | ||
| 334 | - | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh) | |
| 335 | - | go runStdin(loopCtx, cancel, term.In(), sendCh, clk, trueColor) | |
| 336 | - | go runResize(loopCtx, term.ResizeEvents(), sendCh) | |
| 339 | + | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh, log) | |
| 340 | + | go runStdin(loopCtx, cancel, term.In(), sendCh, clk, trueColor, log) | |
| 341 | + | go runResize(loopCtx, term.ResizeEvents(), sendCh, log) | |
| 337 | 342 | ||
| 338 | 343 | // 5. Output/main loop: the only goroutine that touches the terminal. | |
| 339 | 344 | recvCh := make(chan recvResult, 1) | |
| 340 | - | go runRecv(loopCtx, transport, recvCh) | |
| 345 | + | go runRecv(loopCtx, transport, recvCh, log) | |
| 341 | 346 | ||
| 342 | 347 | for { | |
| 343 | 348 | select { | |
| @@ -369,13 +374,21 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||
| 369 | 374 | if ferr := term.Flush(); ferr != nil { | |
| 370 | 375 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: flushing terminal: %w", ferr)} | |
| 371 | 376 | } | |
| 372 | - | ms.firstOutput = true | |
| 377 | + | if !ms.firstOutput { | |
| 378 | + | ms.firstOutput = true | |
| 379 | + | log.Debug("received first output") | |
| 380 | + | } | |
| 373 | 381 | case ports.MsgDetached: | |
| 374 | 382 | d, derr := ports.UnmarshalDetached(r.frame.Payload) | |
| 375 | 383 | if derr != nil { | |
| 376 | 384 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: decoding detached: %w", derr)} | |
| 377 | 385 | } | |
| 378 | 386 | ms.detached = true | |
| 387 | + | if d.Reason == ports.ReasonDetach { | |
| 388 | + | log.Info("detached cleanly", "reason", d.Reason) | |
| 389 | + | } else { | |
| 390 | + | log.Warn("detached by daemon", "reason", d.Reason) | |
| 391 | + | } | |
| 379 | 392 | return attachResult{resumeToken: resumeToken, welcomed: true, err: detachedResult(d.Reason)} | |
| 380 | 393 | case ports.MsgPong: | |
| 381 | 394 | // Liveness reply; nothing to do. | |
| @@ -396,7 +409,8 @@ type recvResult struct { | |||
| 396 | 409 | ||
| 397 | 410 | // runRecv reads frames until an error, forwarding each to the main loop. | |
| 398 | 411 | // It exits on the first error or when the loop context is cancelled. | |
| 399 | - | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult) { | |
| 412 | + | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult, log *slog.Logger) { | |
| 413 | + | defer log.Debug("receive pump exited") | |
| 400 | 414 | for { | |
| 401 | 415 | f, err := transport.Recv() | |
| 402 | 416 | select { | |
| @@ -413,7 +427,8 @@ func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResu | |||
| 413 | 427 | // runSender is the sole caller of transport.Send: serialising the input and | |
| 414 | 428 | // resize pumps through one goroutine keeps the transport's single-writer | |
| 415 | 429 | // contract intact. A send failure cancels the loop and is surfaced once. | |
| 416 | - | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error) { | |
| 430 | + | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error, log *slog.Logger) { | |
| 431 | + | defer log.Debug("sender pump exited") | |
| 417 | 432 | for { | |
| 418 | 433 | select { | |
| 419 | 434 | case f := <-in: | |
| @@ -446,7 +461,8 @@ func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.T | |||
| 446 | 461 | // exits. That is harmless here — Attach has already returned and restored | |
| 447 | 462 | // the terminal — and matches the standard pattern for stdin pumps; a | |
| 448 | 463 | // closable stdin duplicate could lift it later if ever needed. | |
| 449 | - | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, clk ports.Clock, trueColor bool) { | |
| 464 | + | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, clk ports.Clock, trueColor bool, log *slog.Logger) { | |
| 465 | + | defer log.Debug("stdin pump exited") | |
| 450 | 466 | buf := make([]byte, stdinBufSize) | |
| 451 | 467 | var scanner theme.Scanner | |
| 452 | 468 | var inputSeq uint64 | |
| @@ -507,7 +523,8 @@ func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out | |||
| 507 | 523 | // runResize forwards coalesced terminal resize events to the daemon. It | |
| 508 | 524 | // tolerates an already-closed resize channel (which the terminal adapter | |
| 509 | 525 | // hands back when restore ran before ResizeEvents was first called). | |
| 510 | - | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame) { | |
| 526 | + | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame, log *slog.Logger) { | |
| 527 | + | defer log.Debug("resize pump exited") | |
| 511 | 528 | for { | |
| 512 | 529 | select { | |
| 513 | 530 | case sz, ok := <-events: | |
| @@ -119,8 +119,10 @@ const ( | |||||
| 119 | // Run connects via dialer and runs the attach client. It owns the terminal | 119 | // Run connects via dialer and runs the attach client. It owns the terminal | ||
| 120 | // lifecycle above attach attempts so raw mode remains active while a live | 120 | // lifecycle above attach attempts so raw mode remains active while a live | ||
| 121 | // client process redials a lost link. | 121 | // client process redials a lost link. | ||
| 122 | - | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk ports.Clock, intent uint8, name string) (retErr error) { | 122 | + | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk ports.Clock, intent uint8, name string, log *slog.Logger) (retErr error) { |
| 123 | - | log := slog.Default().With("component", "client") | 123 | + | if log == nil { |
| 124 | + | log = slog.Default() | |||
| 125 | + | } | |||
| 124 | ms := milestones{} | 126 | ms := milestones{} | ||
| 125 | 127 | ||||
| 126 | defer func() { | 128 | defer func() { | ||
| @@ -179,6 +181,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk port | |||||
| 179 | if resumeToken == 0 || ctx.Err() != nil { | 181 | if resumeToken == 0 || ctx.Err() != nil { | ||
| 180 | return err | 182 | return err | ||
| 181 | } | 183 | } | ||
| 184 | + | log.Warn("reconnect dial failed", "err", err, "backoff", backoff) | |||
| 182 | drawStatus() | 185 | drawStatus() | ||
| 183 | if !reconnectSleep(ctx, backoff) { | 186 | if !reconnectSleep(ctx, backoff) { | ||
| 184 | return ctx.Err() | 187 | return ctx.Err() | ||
| @@ -189,7 +192,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk port | |||||
| 189 | } | 192 | } | ||
| 190 | ms.dialed = true | 193 | ms.dialed = true | ||
| 191 | 194 | ||||
| 192 | - | result := attachOnce(ctx, transport, term, clk, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus) | 195 | + | result := attachOnce(ctx, transport, term, clk, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus, log) |
| 193 | if result.welcomed { | 196 | if result.welcomed { | ||
| 194 | backoff = defaultReconnectBackoff.initial | 197 | backoff = defaultReconnectBackoff.initial | ||
| 195 | } | 198 | } | ||
| @@ -205,6 +208,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, clk port | |||||
| 205 | clearStatus() | 208 | clearStatus() | ||
| 206 | return result.err | 209 | return result.err | ||
| 207 | } | 210 | } | ||
| 211 | + | log.Warn("reconnecting after attach error", "err", result.err, "backoff", backoff) | |||
| 208 | drawStatus() | 212 | drawStatus() | ||
| 209 | if !reconnectSleep(ctx, backoff) { | 213 | if !reconnectSleep(ctx, backoff) { | ||
| 210 | clearStatus() | 214 | clearStatus() | ||
| @@ -251,7 +255,7 @@ func shouldReconnect(err error) bool { | |||||
| 251 | // | 255 | // | ||
| 252 | // It is kept as a compatibility wrapper for callers that still own dialing. | 256 | // It is kept as a compatibility wrapper for callers that still own dialing. | ||
| 253 | func Attach(ctx context.Context, transport ports.Transport, term ports.Terminal, clk ports.Clock, intent uint8, name string) error { | 257 | func Attach(ctx context.Context, transport ports.Transport, term ports.Terminal, clk ports.Clock, intent uint8, name string) error { | ||
| 254 | - | return Run(ctx, singleTransportDialer{transport: transport}, term, clk, intent, name) | 258 | + | return Run(ctx, singleTransportDialer{transport: transport}, term, clk, intent, name, slog.Default()) |
| 255 | } | 259 | } | ||
| 256 | 260 | ||||
| 257 | type singleTransportDialer struct{ transport ports.Transport } | 261 | type singleTransportDialer struct{ transport ports.Transport } | ||
| @@ -266,7 +270,7 @@ type attachResult struct { | |||||
| 266 | err error | 270 | err error | ||
| 267 | } | 271 | } | ||
| 268 | 272 | ||||
| 269 | - | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, clk ports.Clock, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func()) attachResult { | 273 | + | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, clk ports.Clock, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func(), log *slog.Logger) attachResult { |
| 270 | // 1. Handshake: send Hello with our size and TERM. | 274 | // 1. Handshake: send Hello with our size and TERM. | ||
| 271 | size, err := term.Size() | 275 | size, err := term.Size() | ||
| 272 | if err != nil { | 276 | if err != nil { | ||
| @@ -306,6 +310,7 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||||
| 306 | } | 310 | } | ||
| 307 | resumeToken = welcome.ResumeToken | 311 | resumeToken = welcome.ResumeToken | ||
| 308 | ms.welcomed = true | 312 | ms.welcomed = true | ||
| 313 | + | log.Debug("welcomed by daemon", "resume_token_present", resumeToken != 0) | |||
| 309 | case ports.MsgError: | 314 | case ports.MsgError: | ||
| 310 | em, derr := ports.UnmarshalErrorMsg(reply.Payload) | 315 | em, derr := ports.UnmarshalErrorMsg(reply.Payload) | ||
| 311 | if derr != nil { | 316 | if derr != nil { | ||
| @@ -331,13 +336,13 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||||
| 331 | sendCh := make(chan ports.Frame, sendQueueDepth) | 336 | sendCh := make(chan ports.Frame, sendQueueDepth) | ||
| 332 | sendErrCh := make(chan error, 1) | 337 | sendErrCh := make(chan error, 1) | ||
| 333 | 338 | ||||
| 334 | - | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh) | 339 | + | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh, log) |
| 335 | - | go runStdin(loopCtx, cancel, term.In(), sendCh, clk, trueColor) | 340 | + | go runStdin(loopCtx, cancel, term.In(), sendCh, clk, trueColor, log) |
| 336 | - | go runResize(loopCtx, term.ResizeEvents(), sendCh) | 341 | + | go runResize(loopCtx, term.ResizeEvents(), sendCh, log) |
| 337 | 342 | ||||
| 338 | // 5. Output/main loop: the only goroutine that touches the terminal. | 343 | // 5. Output/main loop: the only goroutine that touches the terminal. | ||
| 339 | recvCh := make(chan recvResult, 1) | 344 | recvCh := make(chan recvResult, 1) | ||
| 340 | - | go runRecv(loopCtx, transport, recvCh) | 345 | + | go runRecv(loopCtx, transport, recvCh, log) |
| 341 | 346 | ||||
| 342 | for { | 347 | for { | ||
| 343 | select { | 348 | select { | ||
| @@ -369,13 +374,21 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||||
| 369 | if ferr := term.Flush(); ferr != nil { | 374 | if ferr := term.Flush(); ferr != nil { | ||
| 370 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: flushing terminal: %w", ferr)} | 375 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: flushing terminal: %w", ferr)} | ||
| 371 | } | 376 | } | ||
| 372 | - | ms.firstOutput = true | 377 | + | if !ms.firstOutput { |
| 378 | + | ms.firstOutput = true | |||
| 379 | + | log.Debug("received first output") | |||
| 380 | + | } | |||
| 373 | case ports.MsgDetached: | 381 | case ports.MsgDetached: | ||
| 374 | d, derr := ports.UnmarshalDetached(r.frame.Payload) | 382 | d, derr := ports.UnmarshalDetached(r.frame.Payload) | ||
| 375 | if derr != nil { | 383 | if derr != nil { | ||
| 376 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: decoding detached: %w", derr)} | 384 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: decoding detached: %w", derr)} | ||
| 377 | } | 385 | } | ||
| 378 | ms.detached = true | 386 | ms.detached = true | ||
| 387 | + | if d.Reason == ports.ReasonDetach { | |||
| 388 | + | log.Info("detached cleanly", "reason", d.Reason) | |||
| 389 | + | } else { | |||
| 390 | + | log.Warn("detached by daemon", "reason", d.Reason) | |||
| 391 | + | } | |||
| 379 | return attachResult{resumeToken: resumeToken, welcomed: true, err: detachedResult(d.Reason)} | 392 | return attachResult{resumeToken: resumeToken, welcomed: true, err: detachedResult(d.Reason)} | ||
| 380 | case ports.MsgPong: | 393 | case ports.MsgPong: | ||
| 381 | // Liveness reply; nothing to do. | 394 | // Liveness reply; nothing to do. | ||
| @@ -396,7 +409,8 @@ type recvResult struct { | |||||
| 396 | 409 | ||||
| 397 | // runRecv reads frames until an error, forwarding each to the main loop. | 410 | // runRecv reads frames until an error, forwarding each to the main loop. | ||
| 398 | // It exits on the first error or when the loop context is cancelled. | 411 | // It exits on the first error or when the loop context is cancelled. | ||
| 399 | - | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult) { | 412 | + | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult, log *slog.Logger) { |
| 413 | + | defer log.Debug("receive pump exited") | |||
| 400 | for { | 414 | for { | ||
| 401 | f, err := transport.Recv() | 415 | f, err := transport.Recv() | ||
| 402 | select { | 416 | select { | ||
| @@ -413,7 +427,8 @@ func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResu | |||||
| 413 | // runSender is the sole caller of transport.Send: serialising the input and | 427 | // runSender is the sole caller of transport.Send: serialising the input and | ||
| 414 | // resize pumps through one goroutine keeps the transport's single-writer | 428 | // resize pumps through one goroutine keeps the transport's single-writer | ||
| 415 | // contract intact. A send failure cancels the loop and is surfaced once. | 429 | // contract intact. A send failure cancels the loop and is surfaced once. | ||
| 416 | - | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error) { | 430 | + | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error, log *slog.Logger) { |
| 431 | + | defer log.Debug("sender pump exited") | |||
| 417 | for { | 432 | for { | ||
| 418 | select { | 433 | select { | ||
| 419 | case f := <-in: | 434 | case f := <-in: | ||
| @@ -446,7 +461,8 @@ func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.T | |||||
| 446 | // exits. That is harmless here — Attach has already returned and restored | 461 | // exits. That is harmless here — Attach has already returned and restored | ||
| 447 | // the terminal — and matches the standard pattern for stdin pumps; a | 462 | // the terminal — and matches the standard pattern for stdin pumps; a | ||
| 448 | // closable stdin duplicate could lift it later if ever needed. | 463 | // closable stdin duplicate could lift it later if ever needed. | ||
| 449 | - | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, clk ports.Clock, trueColor bool) { | 464 | + | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, clk ports.Clock, trueColor bool, log *slog.Logger) { |
| 465 | + | defer log.Debug("stdin pump exited") | |||
| 450 | buf := make([]byte, stdinBufSize) | 466 | buf := make([]byte, stdinBufSize) | ||
| 451 | var scanner theme.Scanner | 467 | var scanner theme.Scanner | ||
| 452 | var inputSeq uint64 | 468 | var inputSeq uint64 | ||
| @@ -507,7 +523,8 @@ func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out | |||||
| 507 | // runResize forwards coalesced terminal resize events to the daemon. It | 523 | // runResize forwards coalesced terminal resize events to the daemon. It | ||
| 508 | // tolerates an already-closed resize channel (which the terminal adapter | 524 | // tolerates an already-closed resize channel (which the terminal adapter | ||
| 509 | // hands back when restore ran before ResizeEvents was first called). | 525 | // hands back when restore ran before ResizeEvents was first called). | ||
| 510 | - | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame) { | 526 | + | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame, log *slog.Logger) { |
| 527 | + | defer log.Debug("resize pump exited") | |||
| 511 | for { | 528 | for { | ||
| 512 | select { | 529 | select { | ||
| 513 | case sz, ok := <-events: | 530 | case sz, ok := <-events: | ||
M internal/usecase/client/client_test.go +5 -5
| @@ -650,7 +650,7 @@ func TestRunRestoresRawModeAfterAttachError(t *testing.T) { | |||
| 650 | 650 | d := portsmocks.NewMockDialer(t) | |
| 651 | 651 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | |
| 652 | 652 | ||
| 653 | - | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "") | |
| 653 | + | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) | |
| 654 | 654 | require.Error(t, err) | |
| 655 | 655 | require.Equal(t, int32(1), restoreCount.Load(), "Run must restore raw mode after attachOnce errors") | |
| 656 | 656 | } | |
| @@ -670,7 +670,7 @@ func TestRunDoesNotEnterRawBeforePreWelcomeError(t *testing.T) { | |||
| 670 | 670 | d := portsmocks.NewMockDialer(t) | |
| 671 | 671 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | |
| 672 | 672 | ||
| 673 | - | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentAttach, "main") | |
| 673 | + | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) | |
| 674 | 674 | require.Error(t, err) | |
| 675 | 675 | var pe *client.ProtocolError | |
| 676 | 676 | require.True(t, errors.As(err, &pe), "want *client.ProtocolError, got %T", err) | |
| @@ -682,7 +682,7 @@ func TestRunPhaseASingleAttempt(t *testing.T) { | |||
| 682 | 682 | d.EXPECT().Dial(mock.Anything).Return(nil, dialErr).Once() | |
| 683 | 683 | tm := portsmocks.NewMockTerminal(t) | |
| 684 | 684 | ||
| 685 | - | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "") | |
| 685 | + | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) | |
| 686 | 686 | require.ErrorIs(t, err, dialErr) | |
| 687 | 687 | } | |
| 688 | 688 | ||
| @@ -771,7 +771,7 @@ func TestRunReconnectsWithRotatedTokenAndSameClientID(t *testing.T) { | |||
| 771 | 771 | tr3 := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(33)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonDetach}))}}} | |
| 772 | 772 | d := &sequenceDialer{trs: []ports.Transport{tr1, tr2, tr3}} | |
| 773 | 773 | ||
| 774 | - | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main") | |
| 774 | + | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) | |
| 775 | 775 | require.NoError(t, err) | |
| 776 | 776 | require.Equal(t, int32(3), d.calls.Load()) | |
| 777 | 777 | require.Equal(t, int32(1), term.rawCount.Load()) | |
| @@ -798,7 +798,7 @@ func TestRunDoesNotRetryTerminalDetachedError(t *testing.T) { | |||
| 798 | 798 | tr := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(11)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonSessionKilled}))}}} | |
| 799 | 799 | d := &sequenceDialer{trs: []ports.Transport{tr}} | |
| 800 | 800 | ||
| 801 | - | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main") | |
| 801 | + | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) | |
| 802 | 802 | require.Error(t, err) | |
| 803 | 803 | var de *client.DetachedError | |
| 804 | 804 | require.True(t, errors.As(err, &de)) | |
| @@ -650,7 +650,7 @@ func TestRunRestoresRawModeAfterAttachError(t *testing.T) { | |||||
| 650 | d := portsmocks.NewMockDialer(t) | 650 | d := portsmocks.NewMockDialer(t) | ||
| 651 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | 651 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | ||
| 652 | 652 | ||||
| 653 | - | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "") | 653 | + | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) |
| 654 | require.Error(t, err) | 654 | require.Error(t, err) | ||
| 655 | require.Equal(t, int32(1), restoreCount.Load(), "Run must restore raw mode after attachOnce errors") | 655 | require.Equal(t, int32(1), restoreCount.Load(), "Run must restore raw mode after attachOnce errors") | ||
| 656 | } | 656 | } | ||
| @@ -670,7 +670,7 @@ func TestRunDoesNotEnterRawBeforePreWelcomeError(t *testing.T) { | |||||
| 670 | d := portsmocks.NewMockDialer(t) | 670 | d := portsmocks.NewMockDialer(t) | ||
| 671 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | 671 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | ||
| 672 | 672 | ||||
| 673 | - | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentAttach, "main") | 673 | + | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) |
| 674 | require.Error(t, err) | 674 | require.Error(t, err) | ||
| 675 | var pe *client.ProtocolError | 675 | var pe *client.ProtocolError | ||
| 676 | require.True(t, errors.As(err, &pe), "want *client.ProtocolError, got %T", err) | 676 | require.True(t, errors.As(err, &pe), "want *client.ProtocolError, got %T", err) | ||
| @@ -682,7 +682,7 @@ func TestRunPhaseASingleAttempt(t *testing.T) { | |||||
| 682 | d.EXPECT().Dial(mock.Anything).Return(nil, dialErr).Once() | 682 | d.EXPECT().Dial(mock.Anything).Return(nil, dialErr).Once() | ||
| 683 | tm := portsmocks.NewMockTerminal(t) | 683 | tm := portsmocks.NewMockTerminal(t) | ||
| 684 | 684 | ||||
| 685 | - | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "") | 685 | + | err := client.Run(context.Background(), d, tm, realClock{}, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) |
| 686 | require.ErrorIs(t, err, dialErr) | 686 | require.ErrorIs(t, err, dialErr) | ||
| 687 | } | 687 | } | ||
| 688 | 688 | ||||
| @@ -771,7 +771,7 @@ func TestRunReconnectsWithRotatedTokenAndSameClientID(t *testing.T) { | |||||
| 771 | tr3 := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(33)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonDetach}))}}} | 771 | tr3 := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(33)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonDetach}))}}} | ||
| 772 | d := &sequenceDialer{trs: []ports.Transport{tr1, tr2, tr3}} | 772 | d := &sequenceDialer{trs: []ports.Transport{tr1, tr2, tr3}} | ||
| 773 | 773 | ||||
| 774 | - | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main") | 774 | + | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) |
| 775 | require.NoError(t, err) | 775 | require.NoError(t, err) | ||
| 776 | require.Equal(t, int32(3), d.calls.Load()) | 776 | require.Equal(t, int32(3), d.calls.Load()) | ||
| 777 | require.Equal(t, int32(1), term.rawCount.Load()) | 777 | require.Equal(t, int32(1), term.rawCount.Load()) | ||
| @@ -798,7 +798,7 @@ func TestRunDoesNotRetryTerminalDetachedError(t *testing.T) { | |||||
| 798 | tr := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(11)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonSessionKilled}))}}} | 798 | tr := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(11)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonSessionKilled}))}}} | ||
| 799 | d := &sequenceDialer{trs: []ports.Transport{tr}} | 799 | d := &sequenceDialer{trs: []ports.Transport{tr}} | ||
| 800 | 800 | ||||
| 801 | - | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main") | 801 | + | err := client.Run(context.Background(), d, term, realClock{}, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) |
| 802 | require.Error(t, err) | 802 | require.Error(t, err) | ||
| 803 | var de *client.DetachedError | 803 | var de *client.DetachedError | ||
| 804 | require.True(t, errors.As(err, &de)) | 804 | require.True(t, errors.As(err, &de)) | ||
M internal/usecase/copy/mode.go +12 -0
| @@ -239,6 +239,18 @@ func OSC52(text string) [][]byte { | |||
| 239 | 239 | return [][]byte{[]byte("\x1b]52;c;" + encoded + "\x07")} | |
| 240 | 240 | } | |
| 241 | 241 | ||
| 242 | + | // OSC52FromBase64 builds the normalized OSC 52 sequence to forward a | |
| 243 | + | // clipboard set request that a pane app already emitted as base64. It | |
| 244 | + | // returns nil if b64 is not valid base64 or its decoded length exceeds | |
| 245 | + | // OSC52MaxPayloadBytes — callers must drop the request silently in that case. | |
| 246 | + | func OSC52FromBase64(b64 string) []byte { | |
| 247 | + | decoded, err := base64.StdEncoding.DecodeString(b64) | |
| 248 | + | if err != nil || len(decoded) > OSC52MaxPayloadBytes { | |
| 249 | + | return nil | |
| 250 | + | } | |
| 251 | + | return []byte("\x1b]52;c;" + b64 + "\x07") | |
| 252 | + | } | |
| 253 | + | ||
| 242 | 254 | func strconvItoa(n int) string { | |
| 243 | 255 | if n == 0 { | |
| 244 | 256 | return "0" | |
| @@ -239,6 +239,18 @@ func OSC52(text string) [][]byte { | |||||
| 239 | return [][]byte{[]byte("\x1b]52;c;" + encoded + "\x07")} | 239 | return [][]byte{[]byte("\x1b]52;c;" + encoded + "\x07")} | ||
| 240 | } | 240 | } | ||
| 241 | 241 | ||||
| 242 | + | // OSC52FromBase64 builds the normalized OSC 52 sequence to forward a | |||
| 243 | + | // clipboard set request that a pane app already emitted as base64. It | |||
| 244 | + | // returns nil if b64 is not valid base64 or its decoded length exceeds | |||
| 245 | + | // OSC52MaxPayloadBytes — callers must drop the request silently in that case. | |||
| 246 | + | func OSC52FromBase64(b64 string) []byte { | |||
| 247 | + | decoded, err := base64.StdEncoding.DecodeString(b64) | |||
| 248 | + | if err != nil || len(decoded) > OSC52MaxPayloadBytes { | |||
| 249 | + | return nil | |||
| 250 | + | } | |||
| 251 | + | return []byte("\x1b]52;c;" + b64 + "\x07") | |||
| 252 | + | } | |||
| 253 | + | ||||
| 242 | func strconvItoa(n int) string { | 254 | func strconvItoa(n int) string { | ||
| 243 | if n == 0 { | 255 | if n == 0 { | ||
| 244 | return "0" | 256 | return "0" | ||
M internal/usecase/copy/mode_test.go +25 -0
| @@ -1,6 +1,7 @@ | |||
| 1 | 1 | package copy | |
| 2 | 2 | ||
| 3 | 3 | import ( | |
| 4 | + | "bytes" | |
| 4 | 5 | "encoding/base64" | |
| 5 | 6 | "strings" | |
| 6 | 7 | "testing" | |
| @@ -366,6 +367,30 @@ func TestOSC52OversizedPayloadIsDeferred(t *testing.T) { | |||
| 366 | 367 | } | |
| 367 | 368 | } | |
| 368 | 369 | ||
| 370 | + | func TestOSC52FromBase64(t *testing.T) { | |
| 371 | + | valid := base64.StdEncoding.EncodeToString([]byte("hello")) | |
| 372 | + | oversized := base64.StdEncoding.EncodeToString([]byte(strings.Repeat("x", OSC52MaxPayloadBytes+1))) | |
| 373 | + | ||
| 374 | + | tests := []struct { | |
| 375 | + | name string | |
| 376 | + | in string | |
| 377 | + | want []byte | |
| 378 | + | }{ | |
| 379 | + | {name: "valid", in: valid, want: []byte("\x1b]52;c;" + valid + "\x07")}, | |
| 380 | + | {name: "empty payload", in: "", want: []byte("\x1b]52;c;\x07")}, | |
| 381 | + | {name: "invalid base64", in: "not-valid-base64!!", want: nil}, | |
| 382 | + | {name: "oversized decoded payload", in: oversized, want: nil}, | |
| 383 | + | } | |
| 384 | + | for _, tt := range tests { | |
| 385 | + | t.Run(tt.name, func(t *testing.T) { | |
| 386 | + | got := OSC52FromBase64(tt.in) | |
| 387 | + | if !bytes.Equal(got, tt.want) { | |
| 388 | + | t.Fatalf("OSC52FromBase64(%q) = %q, want %q", tt.in, got, tt.want) | |
| 389 | + | } | |
| 390 | + | }) | |
| 391 | + | } | |
| 392 | + | } | |
| 393 | + | ||
| 369 | 394 | func decodeOSC52Chunk(t *testing.T, chunk []byte) []byte { | |
| 370 | 395 | t.Helper() | |
| 371 | 396 | s := string(chunk) | |
| @@ -1,6 +1,7 @@ | |||||
| 1 | package copy | 1 | package copy | ||
| 2 | 2 | ||||
| 3 | import ( | 3 | import ( | ||
| 4 | + | "bytes" | |||
| 4 | "encoding/base64" | 5 | "encoding/base64" | ||
| 5 | "strings" | 6 | "strings" | ||
| 6 | "testing" | 7 | "testing" | ||
| @@ -366,6 +367,30 @@ func TestOSC52OversizedPayloadIsDeferred(t *testing.T) { | |||||
| 366 | } | 367 | } | ||
| 367 | } | 368 | } | ||
| 368 | 369 | ||||
| 370 | + | func TestOSC52FromBase64(t *testing.T) { | |||
| 371 | + | valid := base64.StdEncoding.EncodeToString([]byte("hello")) | |||
| 372 | + | oversized := base64.StdEncoding.EncodeToString([]byte(strings.Repeat("x", OSC52MaxPayloadBytes+1))) | |||
| 373 | + | ||||
| 374 | + | tests := []struct { | |||
| 375 | + | name string | |||
| 376 | + | in string | |||
| 377 | + | want []byte | |||
| 378 | + | }{ | |||
| 379 | + | {name: "valid", in: valid, want: []byte("\x1b]52;c;" + valid + "\x07")}, | |||
| 380 | + | {name: "empty payload", in: "", want: []byte("\x1b]52;c;\x07")}, | |||
| 381 | + | {name: "invalid base64", in: "not-valid-base64!!", want: nil}, | |||
| 382 | + | {name: "oversized decoded payload", in: oversized, want: nil}, | |||
| 383 | + | } | |||
| 384 | + | for _, tt := range tests { | |||
| 385 | + | t.Run(tt.name, func(t *testing.T) { | |||
| 386 | + | got := OSC52FromBase64(tt.in) | |||
| 387 | + | if !bytes.Equal(got, tt.want) { | |||
| 388 | + | t.Fatalf("OSC52FromBase64(%q) = %q, want %q", tt.in, got, tt.want) | |||
| 389 | + | } | |||
| 390 | + | }) | |||
| 391 | + | } | |||
| 392 | + | } | |||
| 393 | + | ||||
| 369 | func decodeOSC52Chunk(t *testing.T, chunk []byte) []byte { | 394 | func decodeOSC52Chunk(t *testing.T, chunk []byte) []byte { | ||
| 370 | t.Helper() | 395 | t.Helper() | ||
| 371 | s := string(chunk) | 396 | s := string(chunk) | ||
M internal/usecase/daemon/client.go +11 -3
| @@ -232,7 +232,7 @@ func (d *Daemon) boundedSend(ac *attachedClient, f ports.Frame) { | |||
| 232 | 232 | } | |
| 233 | 233 | ||
| 234 | 234 | func (d *Daemon) boundedSendErr(ac *attachedClient, f ports.Frame) error { | |
| 235 | - | tr, err := d.boundedSendWith(ac, func(capture func(ports.Transport)) error { | |
| 235 | + | tr, err := d.boundedSendWith(func(capture func(ports.Transport)) error { | |
| 236 | 236 | tr, err := ac.sendTransport(f) | |
| 237 | 237 | capture(tr) | |
| 238 | 238 | return err | |
| @@ -249,7 +249,7 @@ func (d *Daemon) boundedSendOutputErr(ac *attachedClient, b []byte) error { | |||
| 249 | 249 | } | |
| 250 | 250 | ||
| 251 | 251 | func (d *Daemon) boundedSendOutputErrTransport(ac *attachedClient, b []byte) (ports.Transport, error) { | |
| 252 | - | return d.boundedSendWith(ac, func(capture func(ports.Transport)) error { | |
| 252 | + | return d.boundedSendWith(func(capture func(ports.Transport)) error { | |
| 253 | 253 | ac.sendMu.Lock() | |
| 254 | 254 | defer ac.sendMu.Unlock() | |
| 255 | 255 | tr := ac.transport() | |
| @@ -263,7 +263,7 @@ func (d *Daemon) boundedSendOutputErrTransport(ac *attachedClient, b []byte) (po | |||
| 263 | 263 | ||
| 264 | 264 | var errSendTimedOut = errors.New("send timed out") | |
| 265 | 265 | ||
| 266 | - | func (d *Daemon) boundedSendWith(ac *attachedClient, send func(capture func(ports.Transport)) error) (ports.Transport, error) { | |
| 266 | + | func (d *Daemon) boundedSendWith(send func(capture func(ports.Transport)) error) (ports.Transport, error) { | |
| 267 | 267 | timer := d.clock.NewTimer(detachNotifyTimeout) | |
| 268 | 268 | result := make(chan error, 1) | |
| 269 | 269 | var ( | |
| @@ -293,6 +293,7 @@ func (d *Daemon) boundedSendWith(ac *attachedClient, send func(capture func(port | |||
| 293 | 293 | return capturedTransport(), err | |
| 294 | 294 | default: | |
| 295 | 295 | } | |
| 296 | + | d.log.Warn("bounded send timed out; force closing client transport") | |
| 296 | 297 | return capturedTransport(), errSendTimedOut | |
| 297 | 298 | } | |
| 298 | 299 | } | |
| @@ -322,6 +323,7 @@ func (d *Daemon) notifyDetachedAsync(ac *attachedClient, reason uint8) { | |||
| 322 | 323 | defer close(done) | |
| 323 | 324 | d.boundedSend(ac, frameDetached(reason)) | |
| 324 | 325 | _ = ac.closeTransport() | |
| 326 | + | d.log.Info("client detached", "reason", reason) | |
| 325 | 327 | }() | |
| 326 | 328 | } | |
| 327 | 329 | ||
| @@ -365,8 +367,10 @@ func (d *Daemon) attachClient(sess *session, tr ports.Transport, sz domain.Size, | |||
| 365 | 367 | sess.mu.Lock() | |
| 366 | 368 | old := sess.client | |
| 367 | 369 | sess.client = ac | |
| 370 | + | name := sess.name | |
| 368 | 371 | tabs := append([]*tab(nil), sess.tabs...) | |
| 369 | 372 | sess.mu.Unlock() | |
| 373 | + | d.log.Info("client attached", "session", name, "resume", opts.resumeCapable) | |
| 370 | 374 | for _, tb := range tabs { | |
| 371 | 375 | tb.mu.Lock() | |
| 372 | 376 | panes := tb.panesSnapshot() | |
| @@ -417,6 +421,7 @@ func (d *Daemon) detachReplacedClient(old *attachedClient) { | |||
| 417 | 421 | } | |
| 418 | 422 | d.unregisterPreview(old) | |
| 419 | 423 | old.setSession(nil) | |
| 424 | + | d.log.Info("client displaced") | |
| 420 | 425 | // Async + bounded: a dead or wedged old client must not stall the new | |
| 421 | 426 | // client's handshake. | |
| 422 | 427 | d.notifyDetachedAsync(old, ports.ReasonDetach) | |
| @@ -513,12 +518,14 @@ func (d *Daemon) clientGone(sess *session, ac *attachedClient, failed ports.Tran | |||
| 513 | 518 | if !ephemeral { | |
| 514 | 519 | d.refreshSessionCwd(sess) | |
| 515 | 520 | } | |
| 521 | + | d.log.Info("client detach begin", "session", sess.name, "explicit", explicit, "ephemeral", ephemeral) | |
| 516 | 522 | oldTr := failed | |
| 517 | 523 | if oldTr == nil { | |
| 518 | 524 | oldTr = ac.transport() | |
| 519 | 525 | } | |
| 520 | 526 | if !explicit && d.parkAttachment(sess, ac) { | |
| 521 | 527 | _ = ac.closeCapturedTransport(oldTr) | |
| 528 | + | d.log.Info("client parked", "session", sess.name) | |
| 522 | 529 | return | |
| 523 | 530 | } | |
| 524 | 531 | d.resetScreenDefaultColors(sess) | |
| @@ -530,6 +537,7 @@ func (d *Daemon) clientGone(sess *session, ac *attachedClient, failed ports.Tran | |||
| 530 | 537 | d.boundedSend(ac, frameDetached(ports.ReasonDetach)) | |
| 531 | 538 | } | |
| 532 | 539 | _ = ac.closeCapturedTransport(oldTr) | |
| 540 | + | d.log.Info("client detached", "session", sess.name, "explicit", explicit) | |
| 533 | 541 | if ephemeral { | |
| 534 | 542 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | |
| 535 | 543 | } | |
| @@ -232,7 +232,7 @@ func (d *Daemon) boundedSend(ac *attachedClient, f ports.Frame) { | |||||
| 232 | } | 232 | } | ||
| 233 | 233 | ||||
| 234 | func (d *Daemon) boundedSendErr(ac *attachedClient, f ports.Frame) error { | 234 | func (d *Daemon) boundedSendErr(ac *attachedClient, f ports.Frame) error { | ||
| 235 | - | tr, err := d.boundedSendWith(ac, func(capture func(ports.Transport)) error { | 235 | + | tr, err := d.boundedSendWith(func(capture func(ports.Transport)) error { |
| 236 | tr, err := ac.sendTransport(f) | 236 | tr, err := ac.sendTransport(f) | ||
| 237 | capture(tr) | 237 | capture(tr) | ||
| 238 | return err | 238 | return err | ||
| @@ -249,7 +249,7 @@ func (d *Daemon) boundedSendOutputErr(ac *attachedClient, b []byte) error { | |||||
| 249 | } | 249 | } | ||
| 250 | 250 | ||||
| 251 | func (d *Daemon) boundedSendOutputErrTransport(ac *attachedClient, b []byte) (ports.Transport, error) { | 251 | func (d *Daemon) boundedSendOutputErrTransport(ac *attachedClient, b []byte) (ports.Transport, error) { | ||
| 252 | - | return d.boundedSendWith(ac, func(capture func(ports.Transport)) error { | 252 | + | return d.boundedSendWith(func(capture func(ports.Transport)) error { |
| 253 | ac.sendMu.Lock() | 253 | ac.sendMu.Lock() | ||
| 254 | defer ac.sendMu.Unlock() | 254 | defer ac.sendMu.Unlock() | ||
| 255 | tr := ac.transport() | 255 | tr := ac.transport() | ||
| @@ -263,7 +263,7 @@ func (d *Daemon) boundedSendOutputErrTransport(ac *attachedClient, b []byte) (po | |||||
| 263 | 263 | ||||
| 264 | var errSendTimedOut = errors.New("send timed out") | 264 | var errSendTimedOut = errors.New("send timed out") | ||
| 265 | 265 | ||||
| 266 | - | func (d *Daemon) boundedSendWith(ac *attachedClient, send func(capture func(ports.Transport)) error) (ports.Transport, error) { | 266 | + | func (d *Daemon) boundedSendWith(send func(capture func(ports.Transport)) error) (ports.Transport, error) { |
| 267 | timer := d.clock.NewTimer(detachNotifyTimeout) | 267 | timer := d.clock.NewTimer(detachNotifyTimeout) | ||
| 268 | result := make(chan error, 1) | 268 | result := make(chan error, 1) | ||
| 269 | var ( | 269 | var ( | ||
| @@ -293,6 +293,7 @@ func (d *Daemon) boundedSendWith(ac *attachedClient, send func(capture func(port | |||||
| 293 | return capturedTransport(), err | 293 | return capturedTransport(), err | ||
| 294 | default: | 294 | default: | ||
| 295 | } | 295 | } | ||
| 296 | + | d.log.Warn("bounded send timed out; force closing client transport") | |||
| 296 | return capturedTransport(), errSendTimedOut | 297 | return capturedTransport(), errSendTimedOut | ||
| 297 | } | 298 | } | ||
| 298 | } | 299 | } | ||
| @@ -322,6 +323,7 @@ func (d *Daemon) notifyDetachedAsync(ac *attachedClient, reason uint8) { | |||||
| 322 | defer close(done) | 323 | defer close(done) | ||
| 323 | d.boundedSend(ac, frameDetached(reason)) | 324 | d.boundedSend(ac, frameDetached(reason)) | ||
| 324 | _ = ac.closeTransport() | 325 | _ = ac.closeTransport() | ||
| 326 | + | d.log.Info("client detached", "reason", reason) | |||
| 325 | }() | 327 | }() | ||
| 326 | } | 328 | } | ||
| 327 | 329 | ||||
| @@ -365,8 +367,10 @@ func (d *Daemon) attachClient(sess *session, tr ports.Transport, sz domain.Size, | |||||
| 365 | sess.mu.Lock() | 367 | sess.mu.Lock() | ||
| 366 | old := sess.client | 368 | old := sess.client | ||
| 367 | sess.client = ac | 369 | sess.client = ac | ||
| 370 | + | name := sess.name | |||
| 368 | tabs := append([]*tab(nil), sess.tabs...) | 371 | tabs := append([]*tab(nil), sess.tabs...) | ||
| 369 | sess.mu.Unlock() | 372 | sess.mu.Unlock() | ||
| 373 | + | d.log.Info("client attached", "session", name, "resume", opts.resumeCapable) | |||
| 370 | for _, tb := range tabs { | 374 | for _, tb := range tabs { | ||
| 371 | tb.mu.Lock() | 375 | tb.mu.Lock() | ||
| 372 | panes := tb.panesSnapshot() | 376 | panes := tb.panesSnapshot() | ||
| @@ -417,6 +421,7 @@ func (d *Daemon) detachReplacedClient(old *attachedClient) { | |||||
| 417 | } | 421 | } | ||
| 418 | d.unregisterPreview(old) | 422 | d.unregisterPreview(old) | ||
| 419 | old.setSession(nil) | 423 | old.setSession(nil) | ||
| 424 | + | d.log.Info("client displaced") | |||
| 420 | // Async + bounded: a dead or wedged old client must not stall the new | 425 | // Async + bounded: a dead or wedged old client must not stall the new | ||
| 421 | // client's handshake. | 426 | // client's handshake. | ||
| 422 | d.notifyDetachedAsync(old, ports.ReasonDetach) | 427 | d.notifyDetachedAsync(old, ports.ReasonDetach) | ||
| @@ -513,12 +518,14 @@ func (d *Daemon) clientGone(sess *session, ac *attachedClient, failed ports.Tran | |||||
| 513 | if !ephemeral { | 518 | if !ephemeral { | ||
| 514 | d.refreshSessionCwd(sess) | 519 | d.refreshSessionCwd(sess) | ||
| 515 | } | 520 | } | ||
| 521 | + | d.log.Info("client detach begin", "session", sess.name, "explicit", explicit, "ephemeral", ephemeral) | |||
| 516 | oldTr := failed | 522 | oldTr := failed | ||
| 517 | if oldTr == nil { | 523 | if oldTr == nil { | ||
| 518 | oldTr = ac.transport() | 524 | oldTr = ac.transport() | ||
| 519 | } | 525 | } | ||
| 520 | if !explicit && d.parkAttachment(sess, ac) { | 526 | if !explicit && d.parkAttachment(sess, ac) { | ||
| 521 | _ = ac.closeCapturedTransport(oldTr) | 527 | _ = ac.closeCapturedTransport(oldTr) | ||
| 528 | + | d.log.Info("client parked", "session", sess.name) | |||
| 522 | return | 529 | return | ||
| 523 | } | 530 | } | ||
| 524 | d.resetScreenDefaultColors(sess) | 531 | d.resetScreenDefaultColors(sess) | ||
| @@ -530,6 +537,7 @@ func (d *Daemon) clientGone(sess *session, ac *attachedClient, failed ports.Tran | |||||
| 530 | d.boundedSend(ac, frameDetached(ports.ReasonDetach)) | 537 | d.boundedSend(ac, frameDetached(ports.ReasonDetach)) | ||
| 531 | } | 538 | } | ||
| 532 | _ = ac.closeCapturedTransport(oldTr) | 539 | _ = ac.closeCapturedTransport(oldTr) | ||
| 540 | + | d.log.Info("client detached", "session", sess.name, "explicit", explicit) | |||
| 533 | if ephemeral { | 541 | if ephemeral { | ||
| 534 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | 542 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | ||
| 535 | } | 543 | } | ||
A internal/usecase/daemon/clipboard.go +84 -0
| @@ -0,0 +1,84 @@ | |||
| 1 | + | package daemon | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | scopy "github.com/bnema/vev/internal/usecase/copy" | |
| 5 | + | ) | |
| 6 | + | ||
| 7 | + | type clipboardForward struct { | |
| 8 | + | ac *attachedClient | |
| 9 | + | seq []byte | |
| 10 | + | } | |
| 11 | + | ||
| 12 | + | // forwardClipboardAsync re-emits an app-originated OSC 52 clipboard set | |
| 13 | + | // request (already captured off the pane's screen while ptyReader held pane.mu, | |
| 14 | + | // then handed here after that lock is released) to the session's attached | |
| 15 | + | // client, if any. Invalid base64 or an oversized decoded payload is dropped | |
| 16 | + | // silently, matching copy mode's own cap (scopy.OSC52MaxPayloadBytes). The | |
| 17 | + | // caller must not hold pane.mu, tab.mu, or session.mu. | |
| 18 | + | // | |
| 19 | + | // Requests are queued on the session and drained by one worker so clipboard | |
| 20 | + | // writes keep arrival order without making the PTY reader wait on client I/O. | |
| 21 | + | func (d *Daemon) forwardClipboardAsync(sess *session, b64 string) { | |
| 22 | + | seq := scopy.OSC52FromBase64(b64) | |
| 23 | + | if seq == nil { | |
| 24 | + | return | |
| 25 | + | } | |
| 26 | + | ||
| 27 | + | sess.mu.Lock() | |
| 28 | + | if sess.ctx != nil { | |
| 29 | + | select { | |
| 30 | + | case <-sess.ctx.Done(): | |
| 31 | + | sess.mu.Unlock() | |
| 32 | + | return | |
| 33 | + | default: | |
| 34 | + | } | |
| 35 | + | } | |
| 36 | + | ac := sess.client | |
| 37 | + | if ac == nil { | |
| 38 | + | sess.mu.Unlock() | |
| 39 | + | return | |
| 40 | + | } | |
| 41 | + | sess.clipboardQueue = append(sess.clipboardQueue, clipboardForward{ac: ac, seq: seq}) | |
| 42 | + | if !sess.clipboardWorkerRunning { | |
| 43 | + | sess.clipboardWorkerRunning = true | |
| 44 | + | go d.clipboardWorker(sess) | |
| 45 | + | } | |
| 46 | + | sess.mu.Unlock() | |
| 47 | + | } | |
| 48 | + | ||
| 49 | + | func (d *Daemon) clipboardWorker(sess *session) { | |
| 50 | + | for { | |
| 51 | + | item, ok := nextClipboardForward(sess) | |
| 52 | + | if !ok { | |
| 53 | + | return | |
| 54 | + | } | |
| 55 | + | failed, err := d.boundedSendOutputErrTransport(item.ac, item.seq) | |
| 56 | + | if err != nil { | |
| 57 | + | d.detachOnSendError(sess, item.ac, failed) | |
| 58 | + | } | |
| 59 | + | } | |
| 60 | + | } | |
| 61 | + | ||
| 62 | + | func nextClipboardForward(sess *session) (clipboardForward, bool) { | |
| 63 | + | sess.mu.Lock() | |
| 64 | + | defer sess.mu.Unlock() | |
| 65 | + | if sess.ctx != nil { | |
| 66 | + | select { | |
| 67 | + | case <-sess.ctx.Done(): | |
| 68 | + | sess.clipboardQueue = nil | |
| 69 | + | sess.clipboardWorkerRunning = false | |
| 70 | + | return clipboardForward{}, false | |
| 71 | + | default: | |
| 72 | + | } | |
| 73 | + | } | |
| 74 | + | if len(sess.clipboardQueue) == 0 { | |
| 75 | + | sess.clipboardWorkerRunning = false | |
| 76 | + | return clipboardForward{}, false | |
| 77 | + | } | |
| 78 | + | item := sess.clipboardQueue[0] | |
| 79 | + | copy(sess.clipboardQueue, sess.clipboardQueue[1:]) | |
| 80 | + | var zero clipboardForward | |
| 81 | + | sess.clipboardQueue[len(sess.clipboardQueue)-1] = zero | |
| 82 | + | sess.clipboardQueue = sess.clipboardQueue[:len(sess.clipboardQueue)-1] | |
| 83 | + | return item, true | |
| 84 | + | } | |
| @@ -0,0 +1,84 @@ | |||||
| 1 | + | package daemon | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | scopy "github.com/bnema/vev/internal/usecase/copy" | |||
| 5 | + | ) | |||
| 6 | + | ||||
| 7 | + | type clipboardForward struct { | |||
| 8 | + | ac *attachedClient | |||
| 9 | + | seq []byte | |||
| 10 | + | } | |||
| 11 | + | ||||
| 12 | + | // forwardClipboardAsync re-emits an app-originated OSC 52 clipboard set | |||
| 13 | + | // request (already captured off the pane's screen while ptyReader held pane.mu, | |||
| 14 | + | // then handed here after that lock is released) to the session's attached | |||
| 15 | + | // client, if any. Invalid base64 or an oversized decoded payload is dropped | |||
| 16 | + | // silently, matching copy mode's own cap (scopy.OSC52MaxPayloadBytes). The | |||
| 17 | + | // caller must not hold pane.mu, tab.mu, or session.mu. | |||
| 18 | + | // | |||
| 19 | + | // Requests are queued on the session and drained by one worker so clipboard | |||
| 20 | + | // writes keep arrival order without making the PTY reader wait on client I/O. | |||
| 21 | + | func (d *Daemon) forwardClipboardAsync(sess *session, b64 string) { | |||
| 22 | + | seq := scopy.OSC52FromBase64(b64) | |||
| 23 | + | if seq == nil { | |||
| 24 | + | return | |||
| 25 | + | } | |||
| 26 | + | ||||
| 27 | + | sess.mu.Lock() | |||
| 28 | + | if sess.ctx != nil { | |||
| 29 | + | select { | |||
| 30 | + | case <-sess.ctx.Done(): | |||
| 31 | + | sess.mu.Unlock() | |||
| 32 | + | return | |||
| 33 | + | default: | |||
| 34 | + | } | |||
| 35 | + | } | |||
| 36 | + | ac := sess.client | |||
| 37 | + | if ac == nil { | |||
| 38 | + | sess.mu.Unlock() | |||
| 39 | + | return | |||
| 40 | + | } | |||
| 41 | + | sess.clipboardQueue = append(sess.clipboardQueue, clipboardForward{ac: ac, seq: seq}) | |||
| 42 | + | if !sess.clipboardWorkerRunning { | |||
| 43 | + | sess.clipboardWorkerRunning = true | |||
| 44 | + | go d.clipboardWorker(sess) | |||
| 45 | + | } | |||
| 46 | + | sess.mu.Unlock() | |||
| 47 | + | } | |||
| 48 | + | ||||
| 49 | + | func (d *Daemon) clipboardWorker(sess *session) { | |||
| 50 | + | for { | |||
| 51 | + | item, ok := nextClipboardForward(sess) | |||
| 52 | + | if !ok { | |||
| 53 | + | return | |||
| 54 | + | } | |||
| 55 | + | failed, err := d.boundedSendOutputErrTransport(item.ac, item.seq) | |||
| 56 | + | if err != nil { | |||
| 57 | + | d.detachOnSendError(sess, item.ac, failed) | |||
| 58 | + | } | |||
| 59 | + | } | |||
| 60 | + | } | |||
| 61 | + | ||||
| 62 | + | func nextClipboardForward(sess *session) (clipboardForward, bool) { | |||
| 63 | + | sess.mu.Lock() | |||
| 64 | + | defer sess.mu.Unlock() | |||
| 65 | + | if sess.ctx != nil { | |||
| 66 | + | select { | |||
| 67 | + | case <-sess.ctx.Done(): | |||
| 68 | + | sess.clipboardQueue = nil | |||
| 69 | + | sess.clipboardWorkerRunning = false | |||
| 70 | + | return clipboardForward{}, false | |||
| 71 | + | default: | |||
| 72 | + | } | |||
| 73 | + | } | |||
| 74 | + | if len(sess.clipboardQueue) == 0 { | |||
| 75 | + | sess.clipboardWorkerRunning = false | |||
| 76 | + | return clipboardForward{}, false | |||
| 77 | + | } | |||
| 78 | + | item := sess.clipboardQueue[0] | |||
| 79 | + | copy(sess.clipboardQueue, sess.clipboardQueue[1:]) | |||
| 80 | + | var zero clipboardForward | |||
| 81 | + | sess.clipboardQueue[len(sess.clipboardQueue)-1] = zero | |||
| 82 | + | sess.clipboardQueue = sess.clipboardQueue[:len(sess.clipboardQueue)-1] | |||
| 83 | + | return item, true | |||
| 84 | + | } | |||
A internal/usecase/daemon/clipboard_test.go +194 -0
| @@ -0,0 +1,194 @@ | |||
| 1 | + | package daemon | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "context" | |
| 5 | + | "encoding/base64" | |
| 6 | + | "io" | |
| 7 | + | "strings" | |
| 8 | + | "testing" | |
| 9 | + | "time" | |
| 10 | + | ||
| 11 | + | "github.com/stretchr/testify/mock" | |
| 12 | + | "github.com/stretchr/testify/require" | |
| 13 | + | ||
| 14 | + | "github.com/bnema/vev/internal/ports" | |
| 15 | + | portsmocks "github.com/bnema/vev/internal/ports/mocks" | |
| 16 | + | scopy "github.com/bnema/vev/internal/usecase/copy" | |
| 17 | + | "github.com/bnema/vev/pkg/renderer" | |
| 18 | + | ) | |
| 19 | + | ||
| 20 | + | // chunkReadPTY returns a MockPTY whose Read yields each chunk in order, then | |
| 21 | + | // reports io.EOF — driving ptyReader through exactly len(chunks) reads before | |
| 22 | + | // it unwinds via reapPane, matching the style of TestPTYQueryGetsResponseWrittenBackToPTY. | |
| 23 | + | func chunkReadPTY(t *testing.T, chunks ...[]byte) *portsmocks.MockPTY { | |
| 24 | + | t.Helper() | |
| 25 | + | p := portsmocks.NewMockPTY(t) | |
| 26 | + | p.EXPECT().Read(mock.Anything).RunAndReturn(func(buf []byte) (int, error) { | |
| 27 | + | if len(chunks) == 0 { | |
| 28 | + | return 0, io.EOF | |
| 29 | + | } | |
| 30 | + | n := copy(buf, chunks[0]) | |
| 31 | + | if n == len(chunks[0]) { | |
| 32 | + | chunks = chunks[1:] | |
| 33 | + | } else { | |
| 34 | + | chunks[0] = chunks[0][n:] | |
| 35 | + | } | |
| 36 | + | return n, nil | |
| 37 | + | }) | |
| 38 | + | p.EXPECT().Write(mock.Anything).Return(0, nil).Maybe() | |
| 39 | + | p.EXPECT().Close().Return(nil).Maybe() | |
| 40 | + | return p | |
| 41 | + | } | |
| 42 | + | ||
| 43 | + | func TestPTYReaderForwardsOSC52ClipboardToAttachedClient(t *testing.T) { | |
| 44 | + | d := newTestDaemon(t, nil, stubClock{}) | |
| 45 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;aGVsbG8=\x07")) | |
| 46 | + | ||
| 47 | + | tr, sends := newCapturingTransport(t) | |
| 48 | + | sctx, cancel := context.WithCancel(context.Background()) | |
| 49 | + | defer cancel() | |
| 50 | + | win := newTestTabWithContext(p, sctx, cancel) | |
| 51 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |
| 52 | + | sess := &session{id: "clip", name: "clip", tabs: []*tab{win}, ctx: sctx, cancel: cancel, client: ac} | |
| 53 | + | ac.setSession(sess) | |
| 54 | + | d.sessions[sess.id] = sess | |
| 55 | + | ||
| 56 | + | d.sessWg.Add(1) | |
| 57 | + | d.ptyReader(sess, win, win.focusedPane()) | |
| 58 | + | ||
| 59 | + | f := awaitFrame(t, sends, ports.MsgOutput) | |
| 60 | + | out, err := ports.UnmarshalOutput(f.Payload) | |
| 61 | + | require.NoError(t, err) | |
| 62 | + | require.Contains(t, string(out.Data), "\x1b]52;c;aGVsbG8=\x07") | |
| 63 | + | } | |
| 64 | + | ||
| 65 | + | func TestPTYReaderDropsOversizedClipboardPayload(t *testing.T) { | |
| 66 | + | d := newTestDaemon(t, nil, stubClock{}) | |
| 67 | + | big := strings.Repeat("a", scopy.OSC52MaxPayloadBytes+1) | |
| 68 | + | b64 := base64.StdEncoding.EncodeToString([]byte(big)) | |
| 69 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;"+b64+"\x07")) | |
| 70 | + | ||
| 71 | + | tr, sends := newCapturingTransport(t) | |
| 72 | + | sctx, cancel := context.WithCancel(context.Background()) | |
| 73 | + | defer cancel() | |
| 74 | + | win := newTestTabWithContext(p, sctx, cancel) | |
| 75 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |
| 76 | + | sess := &session{id: "clip-big", name: "clip-big", tabs: []*tab{win}, ctx: sctx, cancel: cancel, client: ac} | |
| 77 | + | ac.setSession(sess) | |
| 78 | + | d.sessions[sess.id] = sess | |
| 79 | + | ||
| 80 | + | d.sessWg.Add(1) | |
| 81 | + | d.ptyReader(sess, win, win.focusedPane()) | |
| 82 | + | ||
| 83 | + | select { | |
| 84 | + | case f := <-sends: | |
| 85 | + | require.NotEqual(t, ports.MsgOutput, f.Type) | |
| 86 | + | default: | |
| 87 | + | } | |
| 88 | + | } | |
| 89 | + | ||
| 90 | + | func TestPTYReaderDropsInvalidBase64Clipboard(t *testing.T) { | |
| 91 | + | d := newTestDaemon(t, nil, stubClock{}) | |
| 92 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;not-valid-base64!!\x07")) | |
| 93 | + | ||
| 94 | + | tr, sends := newCapturingTransport(t) | |
| 95 | + | sctx, cancel := context.WithCancel(context.Background()) | |
| 96 | + | defer cancel() | |
| 97 | + | win := newTestTabWithContext(p, sctx, cancel) | |
| 98 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |
| 99 | + | sess := &session{id: "clip-bad", name: "clip-bad", tabs: []*tab{win}, ctx: sctx, cancel: cancel, client: ac} | |
| 100 | + | ac.setSession(sess) | |
| 101 | + | d.sessions[sess.id] = sess | |
| 102 | + | ||
| 103 | + | d.sessWg.Add(1) | |
| 104 | + | d.ptyReader(sess, win, win.focusedPane()) | |
| 105 | + | ||
| 106 | + | select { | |
| 107 | + | case f := <-sends: | |
| 108 | + | require.NotEqual(t, ports.MsgOutput, f.Type) | |
| 109 | + | default: | |
| 110 | + | } | |
| 111 | + | } | |
| 112 | + | ||
| 113 | + | func TestPTYReaderClipboardNoAttachedClientDoesNotPanic(t *testing.T) { | |
| 114 | + | d := newTestDaemon(t, nil, stubClock{}) | |
| 115 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;aGVsbG8=\x07")) | |
| 116 | + | ||
| 117 | + | sctx, cancel := context.WithCancel(context.Background()) | |
| 118 | + | defer cancel() | |
| 119 | + | win := newTestTabWithContext(p, sctx, cancel) | |
| 120 | + | sess := &session{id: "clip-noclient", name: "clip-noclient", tabs: []*tab{win}, ctx: sctx, cancel: cancel} | |
| 121 | + | d.sessions[sess.id] = sess | |
| 122 | + | ||
| 123 | + | d.sessWg.Add(1) | |
| 124 | + | require.NotPanics(t, func() { | |
| 125 | + | d.ptyReader(sess, win, win.focusedPane()) | |
| 126 | + | }) | |
| 127 | + | } | |
| 128 | + | ||
| 129 | + | func TestForwardClipboardAsyncSerializesClipboardWrites(t *testing.T) { | |
| 130 | + | d := newTestDaemon(t, nil, stubClock{}) | |
| 131 | + | tr := newBlockingClipboardTransport() | |
| 132 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |
| 133 | + | sctx, cancel := context.WithCancel(context.Background()) | |
| 134 | + | defer cancel() | |
| 135 | + | sess := &session{id: "clip-order", name: "clip-order", ctx: sctx, cancel: cancel, client: ac} | |
| 136 | + | ac.setSession(sess) | |
| 137 | + | ||
| 138 | + | first := base64.StdEncoding.EncodeToString([]byte("first")) | |
| 139 | + | second := base64.StdEncoding.EncodeToString([]byte("second")) | |
| 140 | + | d.forwardClipboardAsync(sess, first) | |
| 141 | + | require.Equal(t, "first", <-tr.started) | |
| 142 | + | ||
| 143 | + | d.forwardClipboardAsync(sess, second) | |
| 144 | + | select { | |
| 145 | + | case got := <-tr.started: | |
| 146 | + | t.Fatalf("second clipboard send started before first completed: %q", got) | |
| 147 | + | case <-time.After(50 * time.Millisecond): | |
| 148 | + | } | |
| 149 | + | ||
| 150 | + | close(tr.releaseFirst) | |
| 151 | + | require.Equal(t, "first", <-tr.sent) | |
| 152 | + | require.Equal(t, "second", <-tr.started) | |
| 153 | + | require.Equal(t, "second", <-tr.sent) | |
| 154 | + | } | |
| 155 | + | ||
| 156 | + | type blockingClipboardTransport struct { | |
| 157 | + | started chan string | |
| 158 | + | sent chan string | |
| 159 | + | releaseFirst chan struct{} | |
| 160 | + | } | |
| 161 | + | ||
| 162 | + | func newBlockingClipboardTransport() *blockingClipboardTransport { | |
| 163 | + | return &blockingClipboardTransport{ | |
| 164 | + | started: make(chan string, 2), | |
| 165 | + | sent: make(chan string, 2), | |
| 166 | + | releaseFirst: make(chan struct{}), | |
| 167 | + | } | |
| 168 | + | } | |
| 169 | + | ||
| 170 | + | func (tr *blockingClipboardTransport) Send(f ports.Frame) error { | |
| 171 | + | out, err := ports.UnmarshalOutput(f.Payload) | |
| 172 | + | if err != nil { | |
| 173 | + | return err | |
| 174 | + | } | |
| 175 | + | data := string(out.Data) | |
| 176 | + | var label string | |
| 177 | + | switch { | |
| 178 | + | case strings.Contains(data, base64.StdEncoding.EncodeToString([]byte("first"))): | |
| 179 | + | label = "first" | |
| 180 | + | case strings.Contains(data, base64.StdEncoding.EncodeToString([]byte("second"))): | |
| 181 | + | label = "second" | |
| 182 | + | default: | |
| 183 | + | label = data | |
| 184 | + | } | |
| 185 | + | tr.started <- label | |
| 186 | + | if label == "first" { | |
| 187 | + | <-tr.releaseFirst | |
| 188 | + | } | |
| 189 | + | tr.sent <- label | |
| 190 | + | return nil | |
| 191 | + | } | |
| 192 | + | ||
| 193 | + | func (tr *blockingClipboardTransport) Recv() (ports.Frame, error) { return ports.Frame{}, io.EOF } | |
| 194 | + | func (tr *blockingClipboardTransport) Close() error { return nil } | |
| @@ -0,0 +1,194 @@ | |||||
| 1 | + | package daemon | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "context" | |||
| 5 | + | "encoding/base64" | |||
| 6 | + | "io" | |||
| 7 | + | "strings" | |||
| 8 | + | "testing" | |||
| 9 | + | "time" | |||
| 10 | + | ||||
| 11 | + | "github.com/stretchr/testify/mock" | |||
| 12 | + | "github.com/stretchr/testify/require" | |||
| 13 | + | ||||
| 14 | + | "github.com/bnema/vev/internal/ports" | |||
| 15 | + | portsmocks "github.com/bnema/vev/internal/ports/mocks" | |||
| 16 | + | scopy "github.com/bnema/vev/internal/usecase/copy" | |||
| 17 | + | "github.com/bnema/vev/pkg/renderer" | |||
| 18 | + | ) | |||
| 19 | + | ||||
| 20 | + | // chunkReadPTY returns a MockPTY whose Read yields each chunk in order, then | |||
| 21 | + | // reports io.EOF — driving ptyReader through exactly len(chunks) reads before | |||
| 22 | + | // it unwinds via reapPane, matching the style of TestPTYQueryGetsResponseWrittenBackToPTY. | |||
| 23 | + | func chunkReadPTY(t *testing.T, chunks ...[]byte) *portsmocks.MockPTY { | |||
| 24 | + | t.Helper() | |||
| 25 | + | p := portsmocks.NewMockPTY(t) | |||
| 26 | + | p.EXPECT().Read(mock.Anything).RunAndReturn(func(buf []byte) (int, error) { | |||
| 27 | + | if len(chunks) == 0 { | |||
| 28 | + | return 0, io.EOF | |||
| 29 | + | } | |||
| 30 | + | n := copy(buf, chunks[0]) | |||
| 31 | + | if n == len(chunks[0]) { | |||
| 32 | + | chunks = chunks[1:] | |||
| 33 | + | } else { | |||
| 34 | + | chunks[0] = chunks[0][n:] | |||
| 35 | + | } | |||
| 36 | + | return n, nil | |||
| 37 | + | }) | |||
| 38 | + | p.EXPECT().Write(mock.Anything).Return(0, nil).Maybe() | |||
| 39 | + | p.EXPECT().Close().Return(nil).Maybe() | |||
| 40 | + | return p | |||
| 41 | + | } | |||
| 42 | + | ||||
| 43 | + | func TestPTYReaderForwardsOSC52ClipboardToAttachedClient(t *testing.T) { | |||
| 44 | + | d := newTestDaemon(t, nil, stubClock{}) | |||
| 45 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;aGVsbG8=\x07")) | |||
| 46 | + | ||||
| 47 | + | tr, sends := newCapturingTransport(t) | |||
| 48 | + | sctx, cancel := context.WithCancel(context.Background()) | |||
| 49 | + | defer cancel() | |||
| 50 | + | win := newTestTabWithContext(p, sctx, cancel) | |||
| 51 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |||
| 52 | + | sess := &session{id: "clip", name: "clip", tabs: []*tab{win}, ctx: sctx, cancel: cancel, client: ac} | |||
| 53 | + | ac.setSession(sess) | |||
| 54 | + | d.sessions[sess.id] = sess | |||
| 55 | + | ||||
| 56 | + | d.sessWg.Add(1) | |||
| 57 | + | d.ptyReader(sess, win, win.focusedPane()) | |||
| 58 | + | ||||
| 59 | + | f := awaitFrame(t, sends, ports.MsgOutput) | |||
| 60 | + | out, err := ports.UnmarshalOutput(f.Payload) | |||
| 61 | + | require.NoError(t, err) | |||
| 62 | + | require.Contains(t, string(out.Data), "\x1b]52;c;aGVsbG8=\x07") | |||
| 63 | + | } | |||
| 64 | + | ||||
| 65 | + | func TestPTYReaderDropsOversizedClipboardPayload(t *testing.T) { | |||
| 66 | + | d := newTestDaemon(t, nil, stubClock{}) | |||
| 67 | + | big := strings.Repeat("a", scopy.OSC52MaxPayloadBytes+1) | |||
| 68 | + | b64 := base64.StdEncoding.EncodeToString([]byte(big)) | |||
| 69 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;"+b64+"\x07")) | |||
| 70 | + | ||||
| 71 | + | tr, sends := newCapturingTransport(t) | |||
| 72 | + | sctx, cancel := context.WithCancel(context.Background()) | |||
| 73 | + | defer cancel() | |||
| 74 | + | win := newTestTabWithContext(p, sctx, cancel) | |||
| 75 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |||
| 76 | + | sess := &session{id: "clip-big", name: "clip-big", tabs: []*tab{win}, ctx: sctx, cancel: cancel, client: ac} | |||
| 77 | + | ac.setSession(sess) | |||
| 78 | + | d.sessions[sess.id] = sess | |||
| 79 | + | ||||
| 80 | + | d.sessWg.Add(1) | |||
| 81 | + | d.ptyReader(sess, win, win.focusedPane()) | |||
| 82 | + | ||||
| 83 | + | select { | |||
| 84 | + | case f := <-sends: | |||
| 85 | + | require.NotEqual(t, ports.MsgOutput, f.Type) | |||
| 86 | + | default: | |||
| 87 | + | } | |||
| 88 | + | } | |||
| 89 | + | ||||
| 90 | + | func TestPTYReaderDropsInvalidBase64Clipboard(t *testing.T) { | |||
| 91 | + | d := newTestDaemon(t, nil, stubClock{}) | |||
| 92 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;not-valid-base64!!\x07")) | |||
| 93 | + | ||||
| 94 | + | tr, sends := newCapturingTransport(t) | |||
| 95 | + | sctx, cancel := context.WithCancel(context.Background()) | |||
| 96 | + | defer cancel() | |||
| 97 | + | win := newTestTabWithContext(p, sctx, cancel) | |||
| 98 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |||
| 99 | + | sess := &session{id: "clip-bad", name: "clip-bad", tabs: []*tab{win}, ctx: sctx, cancel: cancel, client: ac} | |||
| 100 | + | ac.setSession(sess) | |||
| 101 | + | d.sessions[sess.id] = sess | |||
| 102 | + | ||||
| 103 | + | d.sessWg.Add(1) | |||
| 104 | + | d.ptyReader(sess, win, win.focusedPane()) | |||
| 105 | + | ||||
| 106 | + | select { | |||
| 107 | + | case f := <-sends: | |||
| 108 | + | require.NotEqual(t, ports.MsgOutput, f.Type) | |||
| 109 | + | default: | |||
| 110 | + | } | |||
| 111 | + | } | |||
| 112 | + | ||||
| 113 | + | func TestPTYReaderClipboardNoAttachedClientDoesNotPanic(t *testing.T) { | |||
| 114 | + | d := newTestDaemon(t, nil, stubClock{}) | |||
| 115 | + | p := chunkReadPTY(t, []byte("\x1b]52;c;aGVsbG8=\x07")) | |||
| 116 | + | ||||
| 117 | + | sctx, cancel := context.WithCancel(context.Background()) | |||
| 118 | + | defer cancel() | |||
| 119 | + | win := newTestTabWithContext(p, sctx, cancel) | |||
| 120 | + | sess := &session{id: "clip-noclient", name: "clip-noclient", tabs: []*tab{win}, ctx: sctx, cancel: cancel} | |||
| 121 | + | d.sessions[sess.id] = sess | |||
| 122 | + | ||||
| 123 | + | d.sessWg.Add(1) | |||
| 124 | + | require.NotPanics(t, func() { | |||
| 125 | + | d.ptyReader(sess, win, win.focusedPane()) | |||
| 126 | + | }) | |||
| 127 | + | } | |||
| 128 | + | ||||
| 129 | + | func TestForwardClipboardAsyncSerializesClipboardWrites(t *testing.T) { | |||
| 130 | + | d := newTestDaemon(t, nil, stubClock{}) | |||
| 131 | + | tr := newBlockingClipboardTransport() | |||
| 132 | + | ac := &attachedClient{tr: tr, rend: renderer.New(renderer.Capabilities{})} | |||
| 133 | + | sctx, cancel := context.WithCancel(context.Background()) | |||
| 134 | + | defer cancel() | |||
| 135 | + | sess := &session{id: "clip-order", name: "clip-order", ctx: sctx, cancel: cancel, client: ac} | |||
| 136 | + | ac.setSession(sess) | |||
| 137 | + | ||||
| 138 | + | first := base64.StdEncoding.EncodeToString([]byte("first")) | |||
| 139 | + | second := base64.StdEncoding.EncodeToString([]byte("second")) | |||
| 140 | + | d.forwardClipboardAsync(sess, first) | |||
| 141 | + | require.Equal(t, "first", <-tr.started) | |||
| 142 | + | ||||
| 143 | + | d.forwardClipboardAsync(sess, second) | |||
| 144 | + | select { | |||
| 145 | + | case got := <-tr.started: | |||
| 146 | + | t.Fatalf("second clipboard send started before first completed: %q", got) | |||
| 147 | + | case <-time.After(50 * time.Millisecond): | |||
| 148 | + | } | |||
| 149 | + | ||||
| 150 | + | close(tr.releaseFirst) | |||
| 151 | + | require.Equal(t, "first", <-tr.sent) | |||
| 152 | + | require.Equal(t, "second", <-tr.started) | |||
| 153 | + | require.Equal(t, "second", <-tr.sent) | |||
| 154 | + | } | |||
| 155 | + | ||||
| 156 | + | type blockingClipboardTransport struct { | |||
| 157 | + | started chan string | |||
| 158 | + | sent chan string | |||
| 159 | + | releaseFirst chan struct{} | |||
| 160 | + | } | |||
| 161 | + | ||||
| 162 | + | func newBlockingClipboardTransport() *blockingClipboardTransport { | |||
| 163 | + | return &blockingClipboardTransport{ | |||
| 164 | + | started: make(chan string, 2), | |||
| 165 | + | sent: make(chan string, 2), | |||
| 166 | + | releaseFirst: make(chan struct{}), | |||
| 167 | + | } | |||
| 168 | + | } | |||
| 169 | + | ||||
| 170 | + | func (tr *blockingClipboardTransport) Send(f ports.Frame) error { | |||
| 171 | + | out, err := ports.UnmarshalOutput(f.Payload) | |||
| 172 | + | if err != nil { | |||
| 173 | + | return err | |||
| 174 | + | } | |||
| 175 | + | data := string(out.Data) | |||
| 176 | + | var label string | |||
| 177 | + | switch { | |||
| 178 | + | case strings.Contains(data, base64.StdEncoding.EncodeToString([]byte("first"))): | |||
| 179 | + | label = "first" | |||
| 180 | + | case strings.Contains(data, base64.StdEncoding.EncodeToString([]byte("second"))): | |||
| 181 | + | label = "second" | |||
| 182 | + | default: | |||
| 183 | + | label = data | |||
| 184 | + | } | |||
| 185 | + | tr.started <- label | |||
| 186 | + | if label == "first" { | |||
| 187 | + | <-tr.releaseFirst | |||
| 188 | + | } | |||
| 189 | + | tr.sent <- label | |||
| 190 | + | return nil | |||
| 191 | + | } | |||
| 192 | + | ||||
| 193 | + | func (tr *blockingClipboardTransport) Recv() (ports.Frame, error) { return ports.Frame{}, io.EOF } | |||
| 194 | + | func (tr *blockingClipboardTransport) Close() error { return nil } | |||
M internal/usecase/daemon/daemon.go +12 -0
| @@ -245,6 +245,11 @@ func (d *Daemon) Serve(ctx context.Context, l ports.Listener) error { | |||
| 245 | 245 | for { | |
| 246 | 246 | tr, err := l.Accept() | |
| 247 | 247 | if err != nil { | |
| 248 | + | if d.serveCtx.Err() != nil { | |
| 249 | + | d.log.Info("accept loop exiting", "err", err, "reason", "context canceled") | |
| 250 | + | } else { | |
| 251 | + | d.log.Warn("accept loop exiting", "err", err) | |
| 252 | + | } | |
| 248 | 253 | break | |
| 249 | 254 | } | |
| 250 | 255 | d.connWg.Go(func() { | |
| @@ -288,6 +293,7 @@ func (d *Daemon) shutdownAll(reason uint8) { | |||
| 288 | 293 | snapshot := d.sessionsSnapshotLocked() | |
| 289 | 294 | empty := len(snapshot) == 0 | |
| 290 | 295 | d.mu.Unlock() | |
| 296 | + | d.log.Info("graceful shutdown begin", "reason", reason, "sessions", len(snapshot)) | |
| 291 | 297 | if empty { | |
| 292 | 298 | d.doneOnce.Do(func() { close(d.done) }) | |
| 293 | 299 | return | |
| @@ -314,6 +320,7 @@ func (d *Daemon) handleConn(tr ports.Transport) { | |||
| 314 | 320 | ||
| 315 | 321 | first, err := tr.Recv() | |
| 316 | 322 | if err != nil { | |
| 323 | + | d.log.Warn("connection closed before hello", "err", err) | |
| 317 | 324 | _ = tr.Close() | |
| 318 | 325 | return | |
| 319 | 326 | } | |
| @@ -325,6 +332,7 @@ func (d *Daemon) handleConn(tr ports.Transport) { | |||
| 325 | 332 | case ports.MsgHello: | |
| 326 | 333 | d.handleHello(tr, first) | |
| 327 | 334 | default: | |
| 335 | + | d.log.Warn("hello rejected", "err", "expected hello", "type", first.Type) | |
| 328 | 336 | _ = tr.Send(frameError(ports.ErrInternal, "expected hello")) | |
| 329 | 337 | _ = tr.Close() | |
| 330 | 338 | } | |
| @@ -416,14 +424,17 @@ func (d *Daemon) handleHello(tr ports.Transport, f ports.Frame) { | |||
| 416 | 424 | h, err := ports.UnmarshalHello(f.Payload) | |
| 417 | 425 | if err != nil { | |
| 418 | 426 | if version, ok := ports.PeekHelloVersion(f.Payload); ok && version != ports.ProtocolVersion { | |
| 427 | + | d.log.Warn("hello rejected", "err", "protocol version mismatch", "version", version, "expected", ports.ProtocolVersion) | |
| 419 | 428 | _ = tr.Send(frameError(ports.ErrVersionMismatch, "protocol version mismatch")) | |
| 420 | 429 | } else { | |
| 430 | + | d.log.Warn("hello rejected", "err", err) | |
| 421 | 431 | _ = tr.Send(frameError(ports.ErrInternal, "malformed hello")) | |
| 422 | 432 | } | |
| 423 | 433 | _ = tr.Close() | |
| 424 | 434 | return | |
| 425 | 435 | } | |
| 426 | 436 | if h.Version != ports.ProtocolVersion { | |
| 437 | + | d.log.Warn("hello rejected", "err", "protocol version mismatch", "version", h.Version, "expected", ports.ProtocolVersion, "intent", h.Intent, "session", h.Name) | |
| 427 | 438 | _ = tr.Send(frameError(ports.ErrVersionMismatch, "protocol version mismatch")) | |
| 428 | 439 | _ = tr.Close() | |
| 429 | 440 | return | |
| @@ -431,6 +442,7 @@ func (d *Daemon) handleHello(tr ports.Transport, f ports.Frame) { | |||
| 431 | 442 | ||
| 432 | 443 | sess, ac, rerr := d.route(h, tr) | |
| 433 | 444 | if rerr != nil { | |
| 445 | + | d.log.Warn("hello rejected", "err", rerr, "intent", h.Intent, "session", h.Name) | |
| 434 | 446 | if pe, ok := errors.AsType[*protoErr](rerr); ok { | |
| 435 | 447 | _ = tr.Send(frameError(pe.code, pe.text)) | |
| 436 | 448 | } else { | |
| @@ -245,6 +245,11 @@ func (d *Daemon) Serve(ctx context.Context, l ports.Listener) error { | |||||
| 245 | for { | 245 | for { | ||
| 246 | tr, err := l.Accept() | 246 | tr, err := l.Accept() | ||
| 247 | if err != nil { | 247 | if err != nil { | ||
| 248 | + | if d.serveCtx.Err() != nil { | |||
| 249 | + | d.log.Info("accept loop exiting", "err", err, "reason", "context canceled") | |||
| 250 | + | } else { | |||
| 251 | + | d.log.Warn("accept loop exiting", "err", err) | |||
| 252 | + | } | |||
| 248 | break | 253 | break | ||
| 249 | } | 254 | } | ||
| 250 | d.connWg.Go(func() { | 255 | d.connWg.Go(func() { | ||
| @@ -288,6 +293,7 @@ func (d *Daemon) shutdownAll(reason uint8) { | |||||
| 288 | snapshot := d.sessionsSnapshotLocked() | 293 | snapshot := d.sessionsSnapshotLocked() | ||
| 289 | empty := len(snapshot) == 0 | 294 | empty := len(snapshot) == 0 | ||
| 290 | d.mu.Unlock() | 295 | d.mu.Unlock() | ||
| 296 | + | d.log.Info("graceful shutdown begin", "reason", reason, "sessions", len(snapshot)) | |||
| 291 | if empty { | 297 | if empty { | ||
| 292 | d.doneOnce.Do(func() { close(d.done) }) | 298 | d.doneOnce.Do(func() { close(d.done) }) | ||
| 293 | return | 299 | return | ||
| @@ -314,6 +320,7 @@ func (d *Daemon) handleConn(tr ports.Transport) { | |||||
| 314 | 320 | ||||
| 315 | first, err := tr.Recv() | 321 | first, err := tr.Recv() | ||
| 316 | if err != nil { | 322 | if err != nil { | ||
| 323 | + | d.log.Warn("connection closed before hello", "err", err) | |||
| 317 | _ = tr.Close() | 324 | _ = tr.Close() | ||
| 318 | return | 325 | return | ||
| 319 | } | 326 | } | ||
| @@ -325,6 +332,7 @@ func (d *Daemon) handleConn(tr ports.Transport) { | |||||
| 325 | case ports.MsgHello: | 332 | case ports.MsgHello: | ||
| 326 | d.handleHello(tr, first) | 333 | d.handleHello(tr, first) | ||
| 327 | default: | 334 | default: | ||
| 335 | + | d.log.Warn("hello rejected", "err", "expected hello", "type", first.Type) | |||
| 328 | _ = tr.Send(frameError(ports.ErrInternal, "expected hello")) | 336 | _ = tr.Send(frameError(ports.ErrInternal, "expected hello")) | ||
| 329 | _ = tr.Close() | 337 | _ = tr.Close() | ||
| 330 | } | 338 | } | ||
| @@ -416,14 +424,17 @@ func (d *Daemon) handleHello(tr ports.Transport, f ports.Frame) { | |||||
| 416 | h, err := ports.UnmarshalHello(f.Payload) | 424 | h, err := ports.UnmarshalHello(f.Payload) | ||
| 417 | if err != nil { | 425 | if err != nil { | ||
| 418 | if version, ok := ports.PeekHelloVersion(f.Payload); ok && version != ports.ProtocolVersion { | 426 | if version, ok := ports.PeekHelloVersion(f.Payload); ok && version != ports.ProtocolVersion { | ||
| 427 | + | d.log.Warn("hello rejected", "err", "protocol version mismatch", "version", version, "expected", ports.ProtocolVersion) | |||
| 419 | _ = tr.Send(frameError(ports.ErrVersionMismatch, "protocol version mismatch")) | 428 | _ = tr.Send(frameError(ports.ErrVersionMismatch, "protocol version mismatch")) | ||
| 420 | } else { | 429 | } else { | ||
| 430 | + | d.log.Warn("hello rejected", "err", err) | |||
| 421 | _ = tr.Send(frameError(ports.ErrInternal, "malformed hello")) | 431 | _ = tr.Send(frameError(ports.ErrInternal, "malformed hello")) | ||
| 422 | } | 432 | } | ||
| 423 | _ = tr.Close() | 433 | _ = tr.Close() | ||
| 424 | return | 434 | return | ||
| 425 | } | 435 | } | ||
| 426 | if h.Version != ports.ProtocolVersion { | 436 | if h.Version != ports.ProtocolVersion { | ||
| 437 | + | d.log.Warn("hello rejected", "err", "protocol version mismatch", "version", h.Version, "expected", ports.ProtocolVersion, "intent", h.Intent, "session", h.Name) | |||
| 427 | _ = tr.Send(frameError(ports.ErrVersionMismatch, "protocol version mismatch")) | 438 | _ = tr.Send(frameError(ports.ErrVersionMismatch, "protocol version mismatch")) | ||
| 428 | _ = tr.Close() | 439 | _ = tr.Close() | ||
| 429 | return | 440 | return | ||
| @@ -431,6 +442,7 @@ func (d *Daemon) handleHello(tr ports.Transport, f ports.Frame) { | |||||
| 431 | 442 | ||||
| 432 | sess, ac, rerr := d.route(h, tr) | 443 | sess, ac, rerr := d.route(h, tr) | ||
| 433 | if rerr != nil { | 444 | if rerr != nil { | ||
| 445 | + | d.log.Warn("hello rejected", "err", rerr, "intent", h.Intent, "session", h.Name) | |||
| 434 | if pe, ok := errors.AsType[*protoErr](rerr); ok { | 446 | if pe, ok := errors.AsType[*protoErr](rerr); ok { | ||
| 435 | _ = tr.Send(frameError(pe.code, pe.text)) | 447 | _ = tr.Send(frameError(pe.code, pe.text)) | ||
| 436 | } else { | 448 | } else { | ||
M internal/usecase/daemon/pane_actions.go +2 -0
| @@ -61,6 +61,7 @@ func (d *Daemon) spawnPaneOp( | |||
| 61 | 61 | ||
| 62 | 62 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, rectSize(newRect)) | |
| 63 | 63 | if err != nil { | |
| 64 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "pane", newID, "kind", "pane") | |
| 64 | 65 | tb.mu.Lock() | |
| 65 | 66 | _ = tb.tree.Close(newID) | |
| 66 | 67 | tb.tree.Focus = oldFocus | |
| @@ -236,6 +237,7 @@ func (d *Daemon) closePane(sess *session, tb *tab, id layout.PaneID, ac *attache | |||
| 236 | 237 | if p.pty != nil { | |
| 237 | 238 | _ = p.pty.Close() | |
| 238 | 239 | } | |
| 240 | + | d.log.Info("pane closed", "session", sess.name, "pane", id) | |
| 239 | 241 | if repaint { | |
| 240 | 242 | if ac == nil { | |
| 241 | 243 | sess.mu.Lock() | |
| @@ -61,6 +61,7 @@ func (d *Daemon) spawnPaneOp( | |||||
| 61 | 61 | ||||
| 62 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, rectSize(newRect)) | 62 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, rectSize(newRect)) | ||
| 63 | if err != nil { | 63 | if err != nil { | ||
| 64 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "pane", newID, "kind", "pane") | |||
| 64 | tb.mu.Lock() | 65 | tb.mu.Lock() | ||
| 65 | _ = tb.tree.Close(newID) | 66 | _ = tb.tree.Close(newID) | ||
| 66 | tb.tree.Focus = oldFocus | 67 | tb.tree.Focus = oldFocus | ||
| @@ -236,6 +237,7 @@ func (d *Daemon) closePane(sess *session, tb *tab, id layout.PaneID, ac *attache | |||||
| 236 | if p.pty != nil { | 237 | if p.pty != nil { | ||
| 237 | _ = p.pty.Close() | 238 | _ = p.pty.Close() | ||
| 238 | } | 239 | } | ||
| 240 | + | d.log.Info("pane closed", "session", sess.name, "pane", id) | |||
| 239 | if repaint { | 241 | if repaint { | ||
| 240 | if ac == nil { | 242 | if ac == nil { | ||
| 241 | sess.mu.Lock() | 243 | sess.mu.Lock() | ||
M internal/usecase/daemon/render.go +8 -0
| @@ -54,11 +54,13 @@ func (d *Daemon) ptyReader(sess *session, tb *tab, p *pane) { | |||
| 54 | 54 | } | |
| 55 | 55 | buf := make([]byte, ptyReadBufSize) | |
| 56 | 56 | var resp []byte | |
| 57 | + | var clipboards []string | |
| 57 | 58 | attentionCh := make(chan struct{}, 1) | |
| 58 | 59 | p.mu.Lock() | |
| 59 | 60 | p.screen.OnResponse = func(b []byte) { resp = append(resp, b...) } | |
| 60 | 61 | p.screen.OnBell = func() { signal(attentionCh) } | |
| 61 | 62 | p.screen.OnNotify = func(string, string) { signal(attentionCh) } | |
| 63 | + | p.screen.OnClipboard = func(b64 string) { clipboards = append(clipboards, b64) } | |
| 62 | 64 | p.mu.Unlock() | |
| 63 | 65 | for { | |
| 64 | 66 | n, err := p.pty.Read(buf) | |
| @@ -74,6 +76,12 @@ func (d *Daemon) ptyReader(sess *session, tb *tab, p *pane) { | |||
| 74 | 76 | d.noteAttention(sess, tb) | |
| 75 | 77 | default: | |
| 76 | 78 | } | |
| 79 | + | if len(clipboards) > 0 { | |
| 80 | + | for _, b64 := range clipboards { | |
| 81 | + | d.forwardClipboardAsync(sess, b64) | |
| 82 | + | } | |
| 83 | + | clipboards = clipboards[:0] | |
| 84 | + | } | |
| 77 | 85 | if len(resp) > 0 { | |
| 78 | 86 | if _, writeErr := p.pty.Write(resp); writeErr != nil { | |
| 79 | 87 | d.log.Warn("pty response write failed", "err", writeErr, "session", sess.name) | |
| @@ -54,11 +54,13 @@ func (d *Daemon) ptyReader(sess *session, tb *tab, p *pane) { | |||||
| 54 | } | 54 | } | ||
| 55 | buf := make([]byte, ptyReadBufSize) | 55 | buf := make([]byte, ptyReadBufSize) | ||
| 56 | var resp []byte | 56 | var resp []byte | ||
| 57 | + | var clipboards []string | |||
| 57 | attentionCh := make(chan struct{}, 1) | 58 | attentionCh := make(chan struct{}, 1) | ||
| 58 | p.mu.Lock() | 59 | p.mu.Lock() | ||
| 59 | p.screen.OnResponse = func(b []byte) { resp = append(resp, b...) } | 60 | p.screen.OnResponse = func(b []byte) { resp = append(resp, b...) } | ||
| 60 | p.screen.OnBell = func() { signal(attentionCh) } | 61 | p.screen.OnBell = func() { signal(attentionCh) } | ||
| 61 | p.screen.OnNotify = func(string, string) { signal(attentionCh) } | 62 | p.screen.OnNotify = func(string, string) { signal(attentionCh) } | ||
| 63 | + | p.screen.OnClipboard = func(b64 string) { clipboards = append(clipboards, b64) } | |||
| 62 | p.mu.Unlock() | 64 | p.mu.Unlock() | ||
| 63 | for { | 65 | for { | ||
| 64 | n, err := p.pty.Read(buf) | 66 | n, err := p.pty.Read(buf) | ||
| @@ -74,6 +76,12 @@ func (d *Daemon) ptyReader(sess *session, tb *tab, p *pane) { | |||||
| 74 | d.noteAttention(sess, tb) | 76 | d.noteAttention(sess, tb) | ||
| 75 | default: | 77 | default: | ||
| 76 | } | 78 | } | ||
| 79 | + | if len(clipboards) > 0 { | |||
| 80 | + | for _, b64 := range clipboards { | |||
| 81 | + | d.forwardClipboardAsync(sess, b64) | |||
| 82 | + | } | |||
| 83 | + | clipboards = clipboards[:0] | |||
| 84 | + | } | |||
| 77 | if len(resp) > 0 { | 85 | if len(resp) > 0 { | ||
| 78 | if _, writeErr := p.pty.Write(resp); writeErr != nil { | 86 | if _, writeErr := p.pty.Write(resp); writeErr != nil { | ||
| 79 | d.log.Warn("pty response write failed", "err", writeErr, "session", sess.name) | 87 | d.log.Warn("pty response write failed", "err", writeErr, "session", sess.name) | ||
M internal/usecase/daemon/resume.go +8 -0
| @@ -43,6 +43,7 @@ func (d *Daemon) prepareParkAttachment(sess *session, ac *attachedClient) bool { | |||
| 43 | 43 | if ac.resumeToken == 0 { | |
| 44 | 44 | ac.resumeToken = d.nextResumeTokenLocked() | |
| 45 | 45 | } | |
| 46 | + | d.log.Info("parking client prepared", "session", sess.name) | |
| 46 | 47 | return true | |
| 47 | 48 | } | |
| 48 | 49 | ||
| @@ -65,6 +66,7 @@ func (d *Daemon) parkAttachment(sess *session, ac *attachedClient) bool { | |||
| 65 | 66 | ac.parked = true | |
| 66 | 67 | d.parked[token] = parked | |
| 67 | 68 | d.mu.Unlock() | |
| 69 | + | d.log.Info("client parked for resume", "session", sess.name, "grace", resumeParkGrace) | |
| 68 | 70 | ||
| 69 | 71 | go func(token uint64, parked *parkedAttachment) { | |
| 70 | 72 | select { | |
| @@ -80,6 +82,9 @@ func (d *Daemon) expireParked(token uint64, parked *parkedAttachment) { | |||
| 80 | 82 | d.mu.Lock() | |
| 81 | 83 | if d.parked[token] == parked { | |
| 82 | 84 | d.removeParkedLocked(token, parked) | |
| 85 | + | d.mu.Unlock() | |
| 86 | + | d.log.Warn("parked client expired", "session", parked.sess.name) | |
| 87 | + | return | |
| 83 | 88 | } | |
| 84 | 89 | d.mu.Unlock() | |
| 85 | 90 | } | |
| @@ -126,10 +131,12 @@ func (d *Daemon) resumeParkedLocked(h ports.Hello, tr ports.Transport, sz domain | |||
| 126 | 131 | sess.mu.Unlock() | |
| 127 | 132 | if !registered || active { | |
| 128 | 133 | d.removeParkedLocked(h.ResumeToken, parked) | |
| 134 | + | d.log.Warn("resume rejected", "session", sess.name, "registered", registered, "active", active) | |
| 129 | 135 | return nil, nil, false, &protoErr{ports.ErrNoSuchSession, "resume token is no longer valid"} | |
| 130 | 136 | } | |
| 131 | 137 | ac := parked.ac | |
| 132 | 138 | if ac.clientID != h.ClientID { | |
| 139 | + | d.log.Warn("resume rejected", "session", sess.name, "err", "client id mismatch") | |
| 133 | 140 | return nil, nil, false, &protoErr{ports.ErrNoSuchSession, "resume token is no longer valid"} | |
| 134 | 141 | } | |
| 135 | 142 | delete(d.parked, h.ResumeToken) | |
| @@ -143,5 +150,6 @@ func (d *Daemon) resumeParkedLocked(h ports.Hello, tr ports.Transport, sz domain | |||
| 143 | 150 | sess.mu.Lock() | |
| 144 | 151 | sess.client = ac | |
| 145 | 152 | sess.mu.Unlock() | |
| 153 | + | d.log.Info("client resumed", "session", sess.name) | |
| 146 | 154 | return sess, ac, true, nil | |
| 147 | 155 | } | |
| @@ -43,6 +43,7 @@ func (d *Daemon) prepareParkAttachment(sess *session, ac *attachedClient) bool { | |||||
| 43 | if ac.resumeToken == 0 { | 43 | if ac.resumeToken == 0 { | ||
| 44 | ac.resumeToken = d.nextResumeTokenLocked() | 44 | ac.resumeToken = d.nextResumeTokenLocked() | ||
| 45 | } | 45 | } | ||
| 46 | + | d.log.Info("parking client prepared", "session", sess.name) | |||
| 46 | return true | 47 | return true | ||
| 47 | } | 48 | } | ||
| 48 | 49 | ||||
| @@ -65,6 +66,7 @@ func (d *Daemon) parkAttachment(sess *session, ac *attachedClient) bool { | |||||
| 65 | ac.parked = true | 66 | ac.parked = true | ||
| 66 | d.parked[token] = parked | 67 | d.parked[token] = parked | ||
| 67 | d.mu.Unlock() | 68 | d.mu.Unlock() | ||
| 69 | + | d.log.Info("client parked for resume", "session", sess.name, "grace", resumeParkGrace) | |||
| 68 | 70 | ||||
| 69 | go func(token uint64, parked *parkedAttachment) { | 71 | go func(token uint64, parked *parkedAttachment) { | ||
| 70 | select { | 72 | select { | ||
| @@ -80,6 +82,9 @@ func (d *Daemon) expireParked(token uint64, parked *parkedAttachment) { | |||||
| 80 | d.mu.Lock() | 82 | d.mu.Lock() | ||
| 81 | if d.parked[token] == parked { | 83 | if d.parked[token] == parked { | ||
| 82 | d.removeParkedLocked(token, parked) | 84 | d.removeParkedLocked(token, parked) | ||
| 85 | + | d.mu.Unlock() | |||
| 86 | + | d.log.Warn("parked client expired", "session", parked.sess.name) | |||
| 87 | + | return | |||
| 83 | } | 88 | } | ||
| 84 | d.mu.Unlock() | 89 | d.mu.Unlock() | ||
| 85 | } | 90 | } | ||
| @@ -126,10 +131,12 @@ func (d *Daemon) resumeParkedLocked(h ports.Hello, tr ports.Transport, sz domain | |||||
| 126 | sess.mu.Unlock() | 131 | sess.mu.Unlock() | ||
| 127 | if !registered || active { | 132 | if !registered || active { | ||
| 128 | d.removeParkedLocked(h.ResumeToken, parked) | 133 | d.removeParkedLocked(h.ResumeToken, parked) | ||
| 134 | + | d.log.Warn("resume rejected", "session", sess.name, "registered", registered, "active", active) | |||
| 129 | return nil, nil, false, &protoErr{ports.ErrNoSuchSession, "resume token is no longer valid"} | 135 | return nil, nil, false, &protoErr{ports.ErrNoSuchSession, "resume token is no longer valid"} | ||
| 130 | } | 136 | } | ||
| 131 | ac := parked.ac | 137 | ac := parked.ac | ||
| 132 | if ac.clientID != h.ClientID { | 138 | if ac.clientID != h.ClientID { | ||
| 139 | + | d.log.Warn("resume rejected", "session", sess.name, "err", "client id mismatch") | |||
| 133 | return nil, nil, false, &protoErr{ports.ErrNoSuchSession, "resume token is no longer valid"} | 140 | return nil, nil, false, &protoErr{ports.ErrNoSuchSession, "resume token is no longer valid"} | ||
| 134 | } | 141 | } | ||
| 135 | delete(d.parked, h.ResumeToken) | 142 | delete(d.parked, h.ResumeToken) | ||
| @@ -143,5 +150,6 @@ func (d *Daemon) resumeParkedLocked(h ports.Hello, tr ports.Transport, sz domain | |||||
| 143 | sess.mu.Lock() | 150 | sess.mu.Lock() | ||
| 144 | sess.client = ac | 151 | sess.client = ac | ||
| 145 | sess.mu.Unlock() | 152 | sess.mu.Unlock() | ||
| 153 | + | d.log.Info("client resumed", "session", sess.name) | |||
| 146 | return sess, ac, true, nil | 154 | return sess, ac, true, nil | ||
| 147 | } | 155 | } | ||
M internal/usecase/daemon/session.go +23 -6
| @@ -47,12 +47,14 @@ type session struct { | |||
| 47 | 47 | ctx context.Context | |
| 48 | 48 | cancel context.CancelFunc | |
| 49 | 49 | ||
| 50 | - | mu sync.Mutex // guards tabs, active, and client | |
| 51 | - | tabs []*tab | |
| 52 | - | active int | |
| 53 | - | client *attachedClient | |
| 54 | - | cwd string | |
| 55 | - | createdAt int64 | |
| 50 | + | mu sync.Mutex // guards tabs, active, client, and clipboard queue state | |
| 51 | + | tabs []*tab | |
| 52 | + | active int | |
| 53 | + | client *attachedClient | |
| 54 | + | clipboardQueue []clipboardForward | |
| 55 | + | clipboardWorkerRunning bool | |
| 56 | + | cwd string | |
| 57 | + | createdAt int64 | |
| 56 | 58 | } | |
| 57 | 59 | ||
| 58 | 60 | // tab is a pane layout container; pane owns PTY/screen/scrollback/render scheduling state. | |
| @@ -83,6 +85,7 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||
| 83 | 85 | tbSize := tabSize(sz) | |
| 84 | 86 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | |
| 85 | 87 | if err != nil { | |
| 88 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "kind", "session") | |
| 86 | 89 | return nil, fmt.Errorf("daemon: spawning session %q: %w", name, err) | |
| 87 | 90 | } | |
| 88 | 91 | ||
| @@ -112,6 +115,8 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||
| 112 | 115 | delete(d.stopped, name) | |
| 113 | 116 | } | |
| 114 | 117 | d.sessions[id] = sess | |
| 118 | + | d.log.Info("session created", "session", name, "id", id, "ephemeral", ephemeral) | |
| 119 | + | d.log.Info("tab created", "session", name, "tab", 0) | |
| 115 | 120 | d.startTabGoroutines(sess, tb) | |
| 116 | 121 | return sess, nil | |
| 117 | 122 | } | |
| @@ -159,6 +164,7 @@ func (d *Daemon) createSessionAndSwitch(from *session, ac *attachedClient, name | |||
| 159 | 164 | newSess.client = ac | |
| 160 | 165 | newSess.mu.Unlock() | |
| 161 | 166 | ac.setSession(newSess) | |
| 167 | + | d.log.Info("client attached", "session", newSess.name, "resume", ac.resumeCapable) | |
| 162 | 168 | d.mu.Unlock() | |
| 163 | 169 | ||
| 164 | 170 | d.firstPaint(newSess, ac, sz) | |
| @@ -174,6 +180,7 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||
| 174 | 180 | sess.mu.Unlock() | |
| 175 | 181 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | |
| 176 | 182 | if err != nil { | |
| 183 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "kind", "tab") | |
| 177 | 184 | return fmt.Errorf("daemon: spawning tab for session %q: %w", name, err) | |
| 178 | 185 | } | |
| 179 | 186 | tb := newTab(pty, tbSize) | |
| @@ -201,7 +208,9 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||
| 201 | 208 | sess.mu.Lock() | |
| 202 | 209 | sess.tabs = append(sess.tabs, tb) | |
| 203 | 210 | sess.active = len(sess.tabs) - 1 | |
| 211 | + | tabIndex := sess.active | |
| 204 | 212 | sess.mu.Unlock() | |
| 213 | + | d.log.Info("tab created", "session", name, "tab", tabIndex) | |
| 205 | 214 | d.startTabGoroutines(sess, tb) | |
| 206 | 215 | d.mu.Unlock() | |
| 207 | 216 | return nil | |
| @@ -268,6 +277,9 @@ func (d *Daemon) startTabGoroutines(sess *session, tb *tab) { | |||
| 268 | 277 | } | |
| 269 | 278 | ||
| 270 | 279 | func (d *Daemon) startPaneGoroutines(sess *session, tb *tab, p *pane) { | |
| 280 | + | if p != nil { | |
| 281 | + | d.log.Info("pane created", "session", sess.name, "pane", p.id) | |
| 282 | + | } | |
| 271 | 283 | d.sessWg.Add(2) | |
| 272 | 284 | go d.ptyReader(sess, tb, p) | |
| 273 | 285 | go d.scheduler(sess, tb, p) | |
| @@ -371,7 +383,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||
| 371 | 383 | return | |
| 372 | 384 | } | |
| 373 | 385 | if len(sess.tabs) == 1 { | |
| 386 | + | name := sess.name | |
| 374 | 387 | sess.mu.Unlock() | |
| 388 | + | d.log.Info("tab closed", "session", name, "last", true) | |
| 375 | 389 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | |
| 376 | 390 | return | |
| 377 | 391 | } | |
| @@ -383,7 +397,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||
| 383 | 397 | sess.active-- | |
| 384 | 398 | } | |
| 385 | 399 | ac := sess.client | |
| 400 | + | name := sess.name | |
| 386 | 401 | sess.mu.Unlock() | |
| 402 | + | d.log.Info("tab closed", "session", name) | |
| 387 | 403 | ||
| 388 | 404 | d.clearDestroyedTabPreview(tb) | |
| 389 | 405 | if tb.cancel != nil { | |
| @@ -434,6 +450,7 @@ func (d *Daemon) killSession(sess *session, reason uint8, purge bool) error { | |||
| 434 | 450 | d.closing = true | |
| 435 | 451 | } | |
| 436 | 452 | d.mu.Unlock() | |
| 453 | + | d.log.Info("session closed", "session", stoppedName, "id", sess.id, "ephemeral", ephemeral, "purge", purge, "reason", reason) | |
| 437 | 454 | ||
| 438 | 455 | var purgeErr error | |
| 439 | 456 | if !ephemeral && purge { | |
| @@ -47,12 +47,14 @@ type session struct { | |||||
| 47 | ctx context.Context | 47 | ctx context.Context | ||
| 48 | cancel context.CancelFunc | 48 | cancel context.CancelFunc | ||
| 49 | 49 | ||||
| 50 | - | mu sync.Mutex // guards tabs, active, and client | 50 | + | mu sync.Mutex // guards tabs, active, client, and clipboard queue state |
| 51 | - | tabs []*tab | 51 | + | tabs []*tab |
| 52 | - | active int | 52 | + | active int |
| 53 | - | client *attachedClient | 53 | + | client *attachedClient |
| 54 | - | cwd string | 54 | + | clipboardQueue []clipboardForward |
| 55 | - | createdAt int64 | 55 | + | clipboardWorkerRunning bool |
| 56 | + | cwd string | |||
| 57 | + | createdAt int64 | |||
| 56 | } | 58 | } | ||
| 57 | 59 | ||||
| 58 | // tab is a pane layout container; pane owns PTY/screen/scrollback/render scheduling state. | 60 | // tab is a pane layout container; pane owns PTY/screen/scrollback/render scheduling state. | ||
| @@ -83,6 +85,7 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||||
| 83 | tbSize := tabSize(sz) | 85 | tbSize := tabSize(sz) | ||
| 84 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | 86 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | ||
| 85 | if err != nil { | 87 | if err != nil { | ||
| 88 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "kind", "session") | |||
| 86 | return nil, fmt.Errorf("daemon: spawning session %q: %w", name, err) | 89 | return nil, fmt.Errorf("daemon: spawning session %q: %w", name, err) | ||
| 87 | } | 90 | } | ||
| 88 | 91 | ||||
| @@ -112,6 +115,8 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||||
| 112 | delete(d.stopped, name) | 115 | delete(d.stopped, name) | ||
| 113 | } | 116 | } | ||
| 114 | d.sessions[id] = sess | 117 | d.sessions[id] = sess | ||
| 118 | + | d.log.Info("session created", "session", name, "id", id, "ephemeral", ephemeral) | |||
| 119 | + | d.log.Info("tab created", "session", name, "tab", 0) | |||
| 115 | d.startTabGoroutines(sess, tb) | 120 | d.startTabGoroutines(sess, tb) | ||
| 116 | return sess, nil | 121 | return sess, nil | ||
| 117 | } | 122 | } | ||
| @@ -159,6 +164,7 @@ func (d *Daemon) createSessionAndSwitch(from *session, ac *attachedClient, name | |||||
| 159 | newSess.client = ac | 164 | newSess.client = ac | ||
| 160 | newSess.mu.Unlock() | 165 | newSess.mu.Unlock() | ||
| 161 | ac.setSession(newSess) | 166 | ac.setSession(newSess) | ||
| 167 | + | d.log.Info("client attached", "session", newSess.name, "resume", ac.resumeCapable) | |||
| 162 | d.mu.Unlock() | 168 | d.mu.Unlock() | ||
| 163 | 169 | ||||
| 164 | d.firstPaint(newSess, ac, sz) | 170 | d.firstPaint(newSess, ac, sz) | ||
| @@ -174,6 +180,7 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||||
| 174 | sess.mu.Unlock() | 180 | sess.mu.Unlock() | ||
| 175 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | 181 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | ||
| 176 | if err != nil { | 182 | if err != nil { | ||
| 183 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "kind", "tab") | |||
| 177 | return fmt.Errorf("daemon: spawning tab for session %q: %w", name, err) | 184 | return fmt.Errorf("daemon: spawning tab for session %q: %w", name, err) | ||
| 178 | } | 185 | } | ||
| 179 | tb := newTab(pty, tbSize) | 186 | tb := newTab(pty, tbSize) | ||
| @@ -201,7 +208,9 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||||
| 201 | sess.mu.Lock() | 208 | sess.mu.Lock() | ||
| 202 | sess.tabs = append(sess.tabs, tb) | 209 | sess.tabs = append(sess.tabs, tb) | ||
| 203 | sess.active = len(sess.tabs) - 1 | 210 | sess.active = len(sess.tabs) - 1 | ||
| 211 | + | tabIndex := sess.active | |||
| 204 | sess.mu.Unlock() | 212 | sess.mu.Unlock() | ||
| 213 | + | d.log.Info("tab created", "session", name, "tab", tabIndex) | |||
| 205 | d.startTabGoroutines(sess, tb) | 214 | d.startTabGoroutines(sess, tb) | ||
| 206 | d.mu.Unlock() | 215 | d.mu.Unlock() | ||
| 207 | return nil | 216 | return nil | ||
| @@ -268,6 +277,9 @@ func (d *Daemon) startTabGoroutines(sess *session, tb *tab) { | |||||
| 268 | } | 277 | } | ||
| 269 | 278 | ||||
| 270 | func (d *Daemon) startPaneGoroutines(sess *session, tb *tab, p *pane) { | 279 | func (d *Daemon) startPaneGoroutines(sess *session, tb *tab, p *pane) { | ||
| 280 | + | if p != nil { | |||
| 281 | + | d.log.Info("pane created", "session", sess.name, "pane", p.id) | |||
| 282 | + | } | |||
| 271 | d.sessWg.Add(2) | 283 | d.sessWg.Add(2) | ||
| 272 | go d.ptyReader(sess, tb, p) | 284 | go d.ptyReader(sess, tb, p) | ||
| 273 | go d.scheduler(sess, tb, p) | 285 | go d.scheduler(sess, tb, p) | ||
| @@ -371,7 +383,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||||
| 371 | return | 383 | return | ||
| 372 | } | 384 | } | ||
| 373 | if len(sess.tabs) == 1 { | 385 | if len(sess.tabs) == 1 { | ||
| 386 | + | name := sess.name | |||
| 374 | sess.mu.Unlock() | 387 | sess.mu.Unlock() | ||
| 388 | + | d.log.Info("tab closed", "session", name, "last", true) | |||
| 375 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | 389 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | ||
| 376 | return | 390 | return | ||
| 377 | } | 391 | } | ||
| @@ -383,7 +397,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||||
| 383 | sess.active-- | 397 | sess.active-- | ||
| 384 | } | 398 | } | ||
| 385 | ac := sess.client | 399 | ac := sess.client | ||
| 400 | + | name := sess.name | |||
| 386 | sess.mu.Unlock() | 401 | sess.mu.Unlock() | ||
| 402 | + | d.log.Info("tab closed", "session", name) | |||
| 387 | 403 | ||||
| 388 | d.clearDestroyedTabPreview(tb) | 404 | d.clearDestroyedTabPreview(tb) | ||
| 389 | if tb.cancel != nil { | 405 | if tb.cancel != nil { | ||
| @@ -434,6 +450,7 @@ func (d *Daemon) killSession(sess *session, reason uint8, purge bool) error { | |||||
| 434 | d.closing = true | 450 | d.closing = true | ||
| 435 | } | 451 | } | ||
| 436 | d.mu.Unlock() | 452 | d.mu.Unlock() | ||
| 453 | + | d.log.Info("session closed", "session", stoppedName, "id", sess.id, "ephemeral", ephemeral, "purge", purge, "reason", reason) | |||
| 437 | 454 | ||||
| 438 | var purgeErr error | 455 | var purgeErr error | ||
| 439 | if !ephemeral && purge { | 456 | if !ephemeral && purge { | ||
M pkg/vt/screen.go +40 -7
| @@ -25,7 +25,11 @@ type screenState struct { | |||
| 25 | 25 | savedCursor cursorState | |
| 26 | 26 | } | |
| 27 | 27 | ||
| 28 | - | const maxEscapeBufferLen = 4096 | |
| 28 | + | // maxEscapeBufferLen must stay large enough for OSC 52 clipboard payloads | |
| 29 | + | // forwarded by internal/usecase/copy.OSC52MaxPayloadBytes after base64 | |
| 30 | + | // expansion plus the OSC wrapper. pkg/vt cannot import internal/usecase/copy, | |
| 31 | + | // so keep this value in sync if that payload cap changes. | |
| 32 | + | const maxEscapeBufferLen = 128 * 1024 | |
| 29 | 33 | ||
| 30 | 34 | type Screen struct { | |
| 31 | 35 | Frame renderer.Frame | |
| @@ -45,8 +49,14 @@ type Screen struct { | |||
| 45 | 49 | OnBell func() | |
| 46 | 50 | // OnNotify is called synchronously from Write for explicit terminal | |
| 47 | 51 | // notifications: OSC 9 (body only) and OSC 777 "notify" (title;body). | |
| 48 | - | // All other OSC payloads remain discarded. Nil disables it. | |
| 52 | + | // Other non-clipboard OSC payloads remain discarded. Nil disables it. | |
| 49 | 53 | OnNotify func(title, body string) | |
| 54 | + | // OnClipboard is called synchronously from Write for a complete OSC 52 | |
| 55 | + | // clipboard set request from the child. The OSC 52 selection field is | |
| 56 | + | // accepted but ignored; the callback receives only the raw base64 payload. | |
| 57 | + | // Clipboard queries (data == "?") and malformed payloads are ignored and | |
| 58 | + | // never invoke it. Nil disables it. | |
| 59 | + | OnClipboard func(b64 string) | |
| 50 | 60 | ||
| 51 | 61 | defaultFG renderer.RGB | |
| 52 | 62 | defaultBG renderer.RGB | |
| @@ -625,9 +635,14 @@ func appendOSCColorComponent(dst []byte, c uint8) []byte { | |||
| 625 | 635 | } | |
| 626 | 636 | ||
| 627 | 637 | // handleOSC inspects a complete OSC payload (between "ESC ]" and its | |
| 628 | - | // terminator). Only notification sequences are acted on; titles, clipboard | |
| 629 | - | // and every other OSC are still discarded. | |
| 638 | + | // terminator). Notification sequences (OSC 9, OSC 777 "notify") and clipboard | |
| 639 | + | // set requests (OSC 52) are acted on; titles and every other OSC are still | |
| 640 | + | // discarded. | |
| 630 | 641 | func (s *Screen) handleOSC(payload []byte) { | |
| 642 | + | if len(payload) >= len("52;") && payload[0] == '5' && payload[1] == '2' && payload[2] == ';' { | |
| 643 | + | s.handleOSC52(string(payload[len("52;"):])) | |
| 644 | + | return | |
| 645 | + | } | |
| 631 | 646 | if s.OnNotify == nil { | |
| 632 | 647 | return | |
| 633 | 648 | } | |
| @@ -654,6 +669,24 @@ func (s *Screen) handleOSC(payload []byte) { | |||
| 654 | 669 | } | |
| 655 | 670 | } | |
| 656 | 671 | ||
| 672 | + | // handleOSC52 parses the "<selection>;<data>" remainder of an OSC 52 | |
| 673 | + | // clipboard payload (selection may be empty; split on the first ";"). A | |
| 674 | + | // clipboard query (data == "?") is always ignored — vev never answers | |
| 675 | + | // clipboard queries. A payload with no second ";" is malformed and ignored. | |
| 676 | + | func (s *Screen) handleOSC52(rest string) { | |
| 677 | + | idx := strings.IndexByte(rest, ';') | |
| 678 | + | if idx < 0 { | |
| 679 | + | return | |
| 680 | + | } | |
| 681 | + | data := rest[idx+1:] | |
| 682 | + | if data == "?" { | |
| 683 | + | return | |
| 684 | + | } | |
| 685 | + | if s.OnClipboard != nil { | |
| 686 | + | s.OnClipboard(data) | |
| 687 | + | } | |
| 688 | + | } | |
| 689 | + | ||
| 657 | 690 | func consumeSTString(data []byte) (consumed int, partial bool) { | |
| 658 | 691 | for i := 2; i < len(data); i++ { | |
| 659 | 692 | if data[i] == 0x1b && i+1 < len(data) && data[i+1] == '\\' { | |
| @@ -1022,11 +1055,11 @@ func resizeFrame(old renderer.Frame, newW, newH, cursorRow int, evict func([]ren | |||
| 1022 | 1055 | next := renderer.NewFrame(newW, newH) | |
| 1023 | 1056 | shift := clamp(cursorRow-(newH-1), 0, max(old.Height-newH, 0)) | |
| 1024 | 1057 | if evict != nil { | |
| 1025 | - | for y := 0; y < shift; y++ { | |
| 1058 | + | for y := range shift { | |
| 1026 | 1059 | evict(old.Row(y)) | |
| 1027 | 1060 | } | |
| 1028 | 1061 | } | |
| 1029 | - | for dy := 0; dy < newH; dy++ { | |
| 1062 | + | for dy := range newH { | |
| 1030 | 1063 | sy := dy + shift | |
| 1031 | 1064 | if sy >= old.Height { | |
| 1032 | 1065 | break | |
| @@ -1126,7 +1159,7 @@ func (s *Screen) clearScreenMode(mode int) { | |||
| 1126 | 1159 | s.clampCursor() | |
| 1127 | 1160 | switch mode { | |
| 1128 | 1161 | case 1: | |
| 1129 | - | for y := 0; y <= s.Row && y < s.Frame.Height; y++ { | |
| 1162 | + | for y := range min(s.Row+1, s.Frame.Height) { | |
| 1130 | 1163 | end := s.Frame.Width | |
| 1131 | 1164 | if y == s.Row { | |
| 1132 | 1165 | end = min(s.Col+1, s.Frame.Width) | |
| @@ -25,7 +25,11 @@ type screenState struct { | |||||
| 25 | savedCursor cursorState | 25 | savedCursor cursorState | ||
| 26 | } | 26 | } | ||
| 27 | 27 | ||||
| 28 | - | const maxEscapeBufferLen = 4096 | 28 | + | // maxEscapeBufferLen must stay large enough for OSC 52 clipboard payloads |
| 29 | + | // forwarded by internal/usecase/copy.OSC52MaxPayloadBytes after base64 | |||
| 30 | + | // expansion plus the OSC wrapper. pkg/vt cannot import internal/usecase/copy, | |||
| 31 | + | // so keep this value in sync if that payload cap changes. | |||
| 32 | + | const maxEscapeBufferLen = 128 * 1024 | |||
| 29 | 33 | ||||
| 30 | type Screen struct { | 34 | type Screen struct { | ||
| 31 | Frame renderer.Frame | 35 | Frame renderer.Frame | ||
| @@ -45,8 +49,14 @@ type Screen struct { | |||||
| 45 | OnBell func() | 49 | OnBell func() | ||
| 46 | // OnNotify is called synchronously from Write for explicit terminal | 50 | // OnNotify is called synchronously from Write for explicit terminal | ||
| 47 | // notifications: OSC 9 (body only) and OSC 777 "notify" (title;body). | 51 | // notifications: OSC 9 (body only) and OSC 777 "notify" (title;body). | ||
| 48 | - | // All other OSC payloads remain discarded. Nil disables it. | 52 | + | // Other non-clipboard OSC payloads remain discarded. Nil disables it. |
| 49 | OnNotify func(title, body string) | 53 | OnNotify func(title, body string) | ||
| 54 | + | // OnClipboard is called synchronously from Write for a complete OSC 52 | |||
| 55 | + | // clipboard set request from the child. The OSC 52 selection field is | |||
| 56 | + | // accepted but ignored; the callback receives only the raw base64 payload. | |||
| 57 | + | // Clipboard queries (data == "?") and malformed payloads are ignored and | |||
| 58 | + | // never invoke it. Nil disables it. | |||
| 59 | + | OnClipboard func(b64 string) | |||
| 50 | 60 | ||||
| 51 | defaultFG renderer.RGB | 61 | defaultFG renderer.RGB | ||
| 52 | defaultBG renderer.RGB | 62 | defaultBG renderer.RGB | ||
| @@ -625,9 +635,14 @@ func appendOSCColorComponent(dst []byte, c uint8) []byte { | |||||
| 625 | } | 635 | } | ||
| 626 | 636 | ||||
| 627 | // handleOSC inspects a complete OSC payload (between "ESC ]" and its | 637 | // handleOSC inspects a complete OSC payload (between "ESC ]" and its | ||
| 628 | - | // terminator). Only notification sequences are acted on; titles, clipboard | 638 | + | // terminator). Notification sequences (OSC 9, OSC 777 "notify") and clipboard |
| 629 | - | // and every other OSC are still discarded. | 639 | + | // set requests (OSC 52) are acted on; titles and every other OSC are still |
| 640 | + | // discarded. | |||
| 630 | func (s *Screen) handleOSC(payload []byte) { | 641 | func (s *Screen) handleOSC(payload []byte) { | ||
| 642 | + | if len(payload) >= len("52;") && payload[0] == '5' && payload[1] == '2' && payload[2] == ';' { | |||
| 643 | + | s.handleOSC52(string(payload[len("52;"):])) | |||
| 644 | + | return | |||
| 645 | + | } | |||
| 631 | if s.OnNotify == nil { | 646 | if s.OnNotify == nil { | ||
| 632 | return | 647 | return | ||
| 633 | } | 648 | } | ||
| @@ -654,6 +669,24 @@ func (s *Screen) handleOSC(payload []byte) { | |||||
| 654 | } | 669 | } | ||
| 655 | } | 670 | } | ||
| 656 | 671 | ||||
| 672 | + | // handleOSC52 parses the "<selection>;<data>" remainder of an OSC 52 | |||
| 673 | + | // clipboard payload (selection may be empty; split on the first ";"). A | |||
| 674 | + | // clipboard query (data == "?") is always ignored — vev never answers | |||
| 675 | + | // clipboard queries. A payload with no second ";" is malformed and ignored. | |||
| 676 | + | func (s *Screen) handleOSC52(rest string) { | |||
| 677 | + | idx := strings.IndexByte(rest, ';') | |||
| 678 | + | if idx < 0 { | |||
| 679 | + | return | |||
| 680 | + | } | |||
| 681 | + | data := rest[idx+1:] | |||
| 682 | + | if data == "?" { | |||
| 683 | + | return | |||
| 684 | + | } | |||
| 685 | + | if s.OnClipboard != nil { | |||
| 686 | + | s.OnClipboard(data) | |||
| 687 | + | } | |||
| 688 | + | } | |||
| 689 | + | ||||
| 657 | func consumeSTString(data []byte) (consumed int, partial bool) { | 690 | func consumeSTString(data []byte) (consumed int, partial bool) { | ||
| 658 | for i := 2; i < len(data); i++ { | 691 | for i := 2; i < len(data); i++ { | ||
| 659 | if data[i] == 0x1b && i+1 < len(data) && data[i+1] == '\\' { | 692 | if data[i] == 0x1b && i+1 < len(data) && data[i+1] == '\\' { | ||
| @@ -1022,11 +1055,11 @@ func resizeFrame(old renderer.Frame, newW, newH, cursorRow int, evict func([]ren | |||||
| 1022 | next := renderer.NewFrame(newW, newH) | 1055 | next := renderer.NewFrame(newW, newH) | ||
| 1023 | shift := clamp(cursorRow-(newH-1), 0, max(old.Height-newH, 0)) | 1056 | shift := clamp(cursorRow-(newH-1), 0, max(old.Height-newH, 0)) | ||
| 1024 | if evict != nil { | 1057 | if evict != nil { | ||
| 1025 | - | for y := 0; y < shift; y++ { | 1058 | + | for y := range shift { |
| 1026 | evict(old.Row(y)) | 1059 | evict(old.Row(y)) | ||
| 1027 | } | 1060 | } | ||
| 1028 | } | 1061 | } | ||
| 1029 | - | for dy := 0; dy < newH; dy++ { | 1062 | + | for dy := range newH { |
| 1030 | sy := dy + shift | 1063 | sy := dy + shift | ||
| 1031 | if sy >= old.Height { | 1064 | if sy >= old.Height { | ||
| 1032 | break | 1065 | break | ||
| @@ -1126,7 +1159,7 @@ func (s *Screen) clearScreenMode(mode int) { | |||||
| 1126 | s.clampCursor() | 1159 | s.clampCursor() | ||
| 1127 | switch mode { | 1160 | switch mode { | ||
| 1128 | case 1: | 1161 | case 1: | ||
| 1129 | - | for y := 0; y <= s.Row && y < s.Frame.Height; y++ { | 1162 | + | for y := range min(s.Row+1, s.Frame.Height) { |
| 1130 | end := s.Frame.Width | 1163 | end := s.Frame.Width | ||
| 1131 | if y == s.Row { | 1164 | if y == s.Row { | ||
| 1132 | end = min(s.Col+1, s.Frame.Width) | 1165 | end = min(s.Col+1, s.Frame.Width) | ||
M pkg/vt/screen_test.go +64 -0
| @@ -157,6 +157,70 @@ func TestOnNotifySplitAcrossWrites(t *testing.T) { | |||
| 157 | 157 | require.Equal(t, 1, calls) | |
| 158 | 158 | } | |
| 159 | 159 | ||
| 160 | + | func TestOnClipboardBELTerminated(t *testing.T) { | |
| 161 | + | s := NewScreen(10, 2) | |
| 162 | + | var got string | |
| 163 | + | calls := 0 | |
| 164 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |
| 165 | + | s.Write([]byte("\x1b]52;c;aGVsbG8=\x07")) | |
| 166 | + | require.Equal(t, 1, calls) | |
| 167 | + | require.Equal(t, "aGVsbG8=", got) | |
| 168 | + | } | |
| 169 | + | ||
| 170 | + | func TestOnClipboardSTTerminated(t *testing.T) { | |
| 171 | + | s := NewScreen(10, 2) | |
| 172 | + | var got string | |
| 173 | + | calls := 0 | |
| 174 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |
| 175 | + | s.Write([]byte("\x1b]52;c;aGVsbG8=\x1b\\")) | |
| 176 | + | require.Equal(t, 1, calls) | |
| 177 | + | require.Equal(t, "aGVsbG8=", got) | |
| 178 | + | } | |
| 179 | + | ||
| 180 | + | func TestOnClipboardQueryIgnored(t *testing.T) { | |
| 181 | + | s := NewScreen(10, 2) | |
| 182 | + | calls := 0 | |
| 183 | + | s.OnClipboard = func(string) { calls++ } | |
| 184 | + | s.Write([]byte("\x1b]52;c;?\x07")) | |
| 185 | + | require.Equal(t, 0, calls) | |
| 186 | + | } | |
| 187 | + | ||
| 188 | + | func TestOnClipboardEmptySelection(t *testing.T) { | |
| 189 | + | s := NewScreen(10, 2) | |
| 190 | + | var got string | |
| 191 | + | calls := 0 | |
| 192 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |
| 193 | + | s.Write([]byte("\x1b]52;;aGVsbG8=\x07")) | |
| 194 | + | require.Equal(t, 1, calls) | |
| 195 | + | require.Equal(t, "aGVsbG8=", got) | |
| 196 | + | } | |
| 197 | + | ||
| 198 | + | func TestOnClipboardNilCallbackDoesNotPanic(t *testing.T) { | |
| 199 | + | s := NewScreen(10, 2) | |
| 200 | + | require.NotPanics(t, func() { | |
| 201 | + | s.Write([]byte("\x1b]52;c;aGVsbG8=\x07")) | |
| 202 | + | }) | |
| 203 | + | } | |
| 204 | + | ||
| 205 | + | func TestOnClipboardSplitAcrossWrites(t *testing.T) { | |
| 206 | + | s := NewScreen(10, 2) | |
| 207 | + | var got string | |
| 208 | + | calls := 0 | |
| 209 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |
| 210 | + | s.Write([]byte("\x1b]52;c;aGVs")) | |
| 211 | + | s.Write([]byte("bG8=\x07")) | |
| 212 | + | require.Equal(t, 1, calls) | |
| 213 | + | require.Equal(t, "aGVsbG8=", got) | |
| 214 | + | } | |
| 215 | + | ||
| 216 | + | func TestOnClipboardNoSecondSemicolonIgnored(t *testing.T) { | |
| 217 | + | s := NewScreen(10, 2) | |
| 218 | + | calls := 0 | |
| 219 | + | s.OnClipboard = func(string) { calls++ } | |
| 220 | + | s.Write([]byte("\x1b]52;c\x07")) // no second ";" -> no data field | |
| 221 | + | require.Equal(t, 0, calls) | |
| 222 | + | } | |
| 223 | + | ||
| 160 | 224 | // --------------------------------------------------------------------------- | |
| 161 | 225 | // Printable ASCII / UTF-8 | |
| 162 | 226 | // --------------------------------------------------------------------------- | |
| @@ -157,6 +157,70 @@ func TestOnNotifySplitAcrossWrites(t *testing.T) { | |||||
| 157 | require.Equal(t, 1, calls) | 157 | require.Equal(t, 1, calls) | ||
| 158 | } | 158 | } | ||
| 159 | 159 | ||||
| 160 | + | func TestOnClipboardBELTerminated(t *testing.T) { | |||
| 161 | + | s := NewScreen(10, 2) | |||
| 162 | + | var got string | |||
| 163 | + | calls := 0 | |||
| 164 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |||
| 165 | + | s.Write([]byte("\x1b]52;c;aGVsbG8=\x07")) | |||
| 166 | + | require.Equal(t, 1, calls) | |||
| 167 | + | require.Equal(t, "aGVsbG8=", got) | |||
| 168 | + | } | |||
| 169 | + | ||||
| 170 | + | func TestOnClipboardSTTerminated(t *testing.T) { | |||
| 171 | + | s := NewScreen(10, 2) | |||
| 172 | + | var got string | |||
| 173 | + | calls := 0 | |||
| 174 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |||
| 175 | + | s.Write([]byte("\x1b]52;c;aGVsbG8=\x1b\\")) | |||
| 176 | + | require.Equal(t, 1, calls) | |||
| 177 | + | require.Equal(t, "aGVsbG8=", got) | |||
| 178 | + | } | |||
| 179 | + | ||||
| 180 | + | func TestOnClipboardQueryIgnored(t *testing.T) { | |||
| 181 | + | s := NewScreen(10, 2) | |||
| 182 | + | calls := 0 | |||
| 183 | + | s.OnClipboard = func(string) { calls++ } | |||
| 184 | + | s.Write([]byte("\x1b]52;c;?\x07")) | |||
| 185 | + | require.Equal(t, 0, calls) | |||
| 186 | + | } | |||
| 187 | + | ||||
| 188 | + | func TestOnClipboardEmptySelection(t *testing.T) { | |||
| 189 | + | s := NewScreen(10, 2) | |||
| 190 | + | var got string | |||
| 191 | + | calls := 0 | |||
| 192 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |||
| 193 | + | s.Write([]byte("\x1b]52;;aGVsbG8=\x07")) | |||
| 194 | + | require.Equal(t, 1, calls) | |||
| 195 | + | require.Equal(t, "aGVsbG8=", got) | |||
| 196 | + | } | |||
| 197 | + | ||||
| 198 | + | func TestOnClipboardNilCallbackDoesNotPanic(t *testing.T) { | |||
| 199 | + | s := NewScreen(10, 2) | |||
| 200 | + | require.NotPanics(t, func() { | |||
| 201 | + | s.Write([]byte("\x1b]52;c;aGVsbG8=\x07")) | |||
| 202 | + | }) | |||
| 203 | + | } | |||
| 204 | + | ||||
| 205 | + | func TestOnClipboardSplitAcrossWrites(t *testing.T) { | |||
| 206 | + | s := NewScreen(10, 2) | |||
| 207 | + | var got string | |||
| 208 | + | calls := 0 | |||
| 209 | + | s.OnClipboard = func(b64 string) { got = b64; calls++ } | |||
| 210 | + | s.Write([]byte("\x1b]52;c;aGVs")) | |||
| 211 | + | s.Write([]byte("bG8=\x07")) | |||
| 212 | + | require.Equal(t, 1, calls) | |||
| 213 | + | require.Equal(t, "aGVsbG8=", got) | |||
| 214 | + | } | |||
| 215 | + | ||||
| 216 | + | func TestOnClipboardNoSecondSemicolonIgnored(t *testing.T) { | |||
| 217 | + | s := NewScreen(10, 2) | |||
| 218 | + | calls := 0 | |||
| 219 | + | s.OnClipboard = func(string) { calls++ } | |||
| 220 | + | s.Write([]byte("\x1b]52;c\x07")) // no second ";" -> no data field | |||
| 221 | + | require.Equal(t, 0, calls) | |||
| 222 | + | } | |||
| 223 | + | ||||
| 160 | // --------------------------------------------------------------------------- | 224 | // --------------------------------------------------------------------------- | ||
| 161 | // Printable ASCII / UTF-8 | 225 | // Printable ASCII / UTF-8 | ||
| 162 | // --------------------------------------------------------------------------- | 226 | // --------------------------------------------------------------------------- | ||