Merge pull request #15 from bnema/feature/logging-overhaul
feat(logging): add rotated component logs
19 files · +676 -117
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, uint8, string) error | |
| 301 | + | remoteDialer func(target, session string, log *slog.Logger) ports.Dialer | |
| 302 | + | runClient func(context.Context, ports.Dialer, ports.Terminal, 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(), 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(), 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(), 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(), 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, uint8, string) error | 302 | + | runClient func(context.Context, ports.Dialer, ports.Terminal, 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(), 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(), 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(), 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(), 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, intent uint8, name string) error { | |
| 404 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, 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, intent uint8, name string) error { | |
| 424 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, 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, intent uint8, name string) error { | 404 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, 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, intent uint8, name string) error { | 424 | + | runClient: func(_ context.Context, d ports.Dialer, _ ports.Terminal, 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
| @@ -118,8 +118,10 @@ const ( | |||
| 118 | 118 | // Run connects via dialer and runs the attach client. It owns the terminal | |
| 119 | 119 | // lifecycle above attach attempts so raw mode remains active while a live | |
| 120 | 120 | // client process redials a lost link. | |
| 121 | - | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent uint8, name string) (retErr error) { | |
| 122 | - | log := slog.Default().With("component", "client") | |
| 121 | + | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent uint8, name string, log *slog.Logger) (retErr error) { | |
| 122 | + | if log == nil { | |
| 123 | + | log = slog.Default() | |
| 124 | + | } | |
| 123 | 125 | ms := milestones{} | |
| 124 | 126 | ||
| 125 | 127 | defer func() { | |
| @@ -178,6 +180,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent u | |||
| 178 | 180 | if resumeToken == 0 || ctx.Err() != nil { | |
| 179 | 181 | return err | |
| 180 | 182 | } | |
| 183 | + | log.Warn("reconnect dial failed", "err", err, "backoff", backoff) | |
| 181 | 184 | drawStatus() | |
| 182 | 185 | if !reconnectSleep(ctx, backoff) { | |
| 183 | 186 | return ctx.Err() | |
| @@ -188,7 +191,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent u | |||
| 188 | 191 | } | |
| 189 | 192 | ms.dialed = true | |
| 190 | 193 | ||
| 191 | - | result := attachOnce(ctx, transport, term, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus) | |
| 194 | + | result := attachOnce(ctx, transport, term, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus, log) | |
| 192 | 195 | if result.welcomed { | |
| 193 | 196 | backoff = defaultReconnectBackoff.initial | |
| 194 | 197 | } | |
| @@ -204,6 +207,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent u | |||
| 204 | 207 | clearStatus() | |
| 205 | 208 | return result.err | |
| 206 | 209 | } | |
| 210 | + | log.Warn("reconnecting after attach error", "err", result.err, "backoff", backoff) | |
| 207 | 211 | drawStatus() | |
| 208 | 212 | if !reconnectSleep(ctx, backoff) { | |
| 209 | 213 | clearStatus() | |
| @@ -250,7 +254,7 @@ func shouldReconnect(err error) bool { | |||
| 250 | 254 | // | |
| 251 | 255 | // It is kept as a compatibility wrapper for callers that still own dialing. | |
| 252 | 256 | func Attach(ctx context.Context, transport ports.Transport, term ports.Terminal, intent uint8, name string) error { | |
| 253 | - | return Run(ctx, singleTransportDialer{transport: transport}, term, intent, name) | |
| 257 | + | return Run(ctx, singleTransportDialer{transport: transport}, term, intent, name, slog.Default()) | |
| 254 | 258 | } | |
| 255 | 259 | ||
| 256 | 260 | type singleTransportDialer struct{ transport ports.Transport } | |
| @@ -265,7 +269,7 @@ type attachResult struct { | |||
| 265 | 269 | err error | |
| 266 | 270 | } | |
| 267 | 271 | ||
| 268 | - | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func()) attachResult { | |
| 272 | + | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func(), log *slog.Logger) attachResult { | |
| 269 | 273 | // 1. Handshake: send Hello with our size and TERM. | |
| 270 | 274 | size, err := term.Size() | |
| 271 | 275 | if err != nil { | |
| @@ -305,6 +309,7 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||
| 305 | 309 | } | |
| 306 | 310 | resumeToken = welcome.ResumeToken | |
| 307 | 311 | ms.welcomed = true | |
| 312 | + | log.Debug("welcomed by daemon", "resume_token_present", resumeToken != 0) | |
| 308 | 313 | case ports.MsgError: | |
| 309 | 314 | em, derr := ports.UnmarshalErrorMsg(reply.Payload) | |
| 310 | 315 | if derr != nil { | |
| @@ -330,13 +335,13 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||
| 330 | 335 | sendCh := make(chan ports.Frame, sendQueueDepth) | |
| 331 | 336 | sendErrCh := make(chan error, 1) | |
| 332 | 337 | ||
| 333 | - | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh) | |
| 334 | - | go runStdin(loopCtx, cancel, term.In(), sendCh, trueColor) | |
| 335 | - | go runResize(loopCtx, term.ResizeEvents(), sendCh) | |
| 338 | + | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh, log) | |
| 339 | + | go runStdin(loopCtx, cancel, term.In(), sendCh, trueColor, log) | |
| 340 | + | go runResize(loopCtx, term.ResizeEvents(), sendCh, log) | |
| 336 | 341 | ||
| 337 | 342 | // 5. Output/main loop: the only goroutine that touches the terminal. | |
| 338 | 343 | recvCh := make(chan recvResult, 1) | |
| 339 | - | go runRecv(loopCtx, transport, recvCh) | |
| 344 | + | go runRecv(loopCtx, transport, recvCh, log) | |
| 340 | 345 | ||
| 341 | 346 | for { | |
| 342 | 347 | select { | |
| @@ -368,13 +373,21 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||
| 368 | 373 | if ferr := term.Flush(); ferr != nil { | |
| 369 | 374 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: flushing terminal: %w", ferr)} | |
| 370 | 375 | } | |
| 371 | - | ms.firstOutput = true | |
| 376 | + | if !ms.firstOutput { | |
| 377 | + | ms.firstOutput = true | |
| 378 | + | log.Debug("received first output") | |
| 379 | + | } | |
| 372 | 380 | case ports.MsgDetached: | |
| 373 | 381 | d, derr := ports.UnmarshalDetached(r.frame.Payload) | |
| 374 | 382 | if derr != nil { | |
| 375 | 383 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: decoding detached: %w", derr)} | |
| 376 | 384 | } | |
| 377 | 385 | ms.detached = true | |
| 386 | + | if d.Reason == ports.ReasonDetach { | |
| 387 | + | log.Info("detached cleanly", "reason", d.Reason) | |
| 388 | + | } else { | |
| 389 | + | log.Warn("detached by daemon", "reason", d.Reason) | |
| 390 | + | } | |
| 378 | 391 | return attachResult{resumeToken: resumeToken, welcomed: true, err: detachedResult(d.Reason)} | |
| 379 | 392 | case ports.MsgPong: | |
| 380 | 393 | // Liveness reply; nothing to do. | |
| @@ -395,7 +408,8 @@ type recvResult struct { | |||
| 395 | 408 | ||
| 396 | 409 | // runRecv reads frames until an error, forwarding each to the main loop. | |
| 397 | 410 | // It exits on the first error or when the loop context is cancelled. | |
| 398 | - | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult) { | |
| 411 | + | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult, log *slog.Logger) { | |
| 412 | + | defer log.Debug("receive pump exited") | |
| 399 | 413 | for { | |
| 400 | 414 | f, err := transport.Recv() | |
| 401 | 415 | select { | |
| @@ -412,7 +426,8 @@ func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResu | |||
| 412 | 426 | // runSender is the sole caller of transport.Send: serialising the input and | |
| 413 | 427 | // resize pumps through one goroutine keeps the transport's single-writer | |
| 414 | 428 | // contract intact. A send failure cancels the loop and is surfaced once. | |
| 415 | - | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error) { | |
| 429 | + | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error, log *slog.Logger) { | |
| 430 | + | defer log.Debug("sender pump exited") | |
| 416 | 431 | for { | |
| 417 | 432 | select { | |
| 418 | 433 | case f := <-in: | |
| @@ -445,7 +460,8 @@ func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.T | |||
| 445 | 460 | // exits. That is harmless here — Attach has already returned and restored | |
| 446 | 461 | // the terminal — and matches the standard pattern for stdin pumps; a | |
| 447 | 462 | // closable stdin duplicate could lift it later if ever needed. | |
| 448 | - | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, trueColor bool) { | |
| 463 | + | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, trueColor bool, log *slog.Logger) { | |
| 464 | + | defer log.Debug("stdin pump exited") | |
| 449 | 465 | buf := make([]byte, stdinBufSize) | |
| 450 | 466 | var scanner theme.Scanner | |
| 451 | 467 | var inputSeq uint64 | |
| @@ -501,7 +517,8 @@ func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out | |||
| 501 | 517 | // runResize forwards coalesced terminal resize events to the daemon. It | |
| 502 | 518 | // tolerates an already-closed resize channel (which the terminal adapter | |
| 503 | 519 | // hands back when restore ran before ResizeEvents was first called). | |
| 504 | - | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame) { | |
| 520 | + | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame, log *slog.Logger) { | |
| 521 | + | defer log.Debug("resize pump exited") | |
| 505 | 522 | for { | |
| 506 | 523 | select { | |
| 507 | 524 | case sz, ok := <-events: | |
| @@ -118,8 +118,10 @@ const ( | |||||
| 118 | // Run connects via dialer and runs the attach client. It owns the terminal | 118 | // Run connects via dialer and runs the attach client. It owns the terminal | ||
| 119 | // lifecycle above attach attempts so raw mode remains active while a live | 119 | // lifecycle above attach attempts so raw mode remains active while a live | ||
| 120 | // client process redials a lost link. | 120 | // client process redials a lost link. | ||
| 121 | - | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent uint8, name string) (retErr error) { | 121 | + | func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent uint8, name string, log *slog.Logger) (retErr error) { |
| 122 | - | log := slog.Default().With("component", "client") | 122 | + | if log == nil { |
| 123 | + | log = slog.Default() | |||
| 124 | + | } | |||
| 123 | ms := milestones{} | 125 | ms := milestones{} | ||
| 124 | 126 | ||||
| 125 | defer func() { | 127 | defer func() { | ||
| @@ -178,6 +180,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent u | |||||
| 178 | if resumeToken == 0 || ctx.Err() != nil { | 180 | if resumeToken == 0 || ctx.Err() != nil { | ||
| 179 | return err | 181 | return err | ||
| 180 | } | 182 | } | ||
| 183 | + | log.Warn("reconnect dial failed", "err", err, "backoff", backoff) | |||
| 181 | drawStatus() | 184 | drawStatus() | ||
| 182 | if !reconnectSleep(ctx, backoff) { | 185 | if !reconnectSleep(ctx, backoff) { | ||
| 183 | return ctx.Err() | 186 | return ctx.Err() | ||
| @@ -188,7 +191,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent u | |||||
| 188 | } | 191 | } | ||
| 189 | ms.dialed = true | 192 | ms.dialed = true | ||
| 190 | 193 | ||||
| 191 | - | result := attachOnce(ctx, transport, term, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus) | 194 | + | result := attachOnce(ctx, transport, term, attemptIntent, name, resumeToken, processClientID, &ms, enterRaw, clearStatus, log) |
| 192 | if result.welcomed { | 195 | if result.welcomed { | ||
| 193 | backoff = defaultReconnectBackoff.initial | 196 | backoff = defaultReconnectBackoff.initial | ||
| 194 | } | 197 | } | ||
| @@ -204,6 +207,7 @@ func Run(ctx context.Context, dialer ports.Dialer, term ports.Terminal, intent u | |||||
| 204 | clearStatus() | 207 | clearStatus() | ||
| 205 | return result.err | 208 | return result.err | ||
| 206 | } | 209 | } | ||
| 210 | + | log.Warn("reconnecting after attach error", "err", result.err, "backoff", backoff) | |||
| 207 | drawStatus() | 211 | drawStatus() | ||
| 208 | if !reconnectSleep(ctx, backoff) { | 212 | if !reconnectSleep(ctx, backoff) { | ||
| 209 | clearStatus() | 213 | clearStatus() | ||
| @@ -250,7 +254,7 @@ func shouldReconnect(err error) bool { | |||||
| 250 | // | 254 | // | ||
| 251 | // It is kept as a compatibility wrapper for callers that still own dialing. | 255 | // It is kept as a compatibility wrapper for callers that still own dialing. | ||
| 252 | func Attach(ctx context.Context, transport ports.Transport, term ports.Terminal, intent uint8, name string) error { | 256 | func Attach(ctx context.Context, transport ports.Transport, term ports.Terminal, intent uint8, name string) error { | ||
| 253 | - | return Run(ctx, singleTransportDialer{transport: transport}, term, intent, name) | 257 | + | return Run(ctx, singleTransportDialer{transport: transport}, term, intent, name, slog.Default()) |
| 254 | } | 258 | } | ||
| 255 | 259 | ||||
| 256 | type singleTransportDialer struct{ transport ports.Transport } | 260 | type singleTransportDialer struct{ transport ports.Transport } | ||
| @@ -265,7 +269,7 @@ type attachResult struct { | |||||
| 265 | err error | 269 | err error | ||
| 266 | } | 270 | } | ||
| 267 | 271 | ||||
| 268 | - | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func()) attachResult { | 272 | + | func attachOnce(ctx context.Context, transport ports.Transport, term ports.Terminal, intent uint8, name string, resumeToken uint64, clientID [16]byte, ms *milestones, enterRaw func() error, clearStatus func(), log *slog.Logger) attachResult { |
| 269 | // 1. Handshake: send Hello with our size and TERM. | 273 | // 1. Handshake: send Hello with our size and TERM. | ||
| 270 | size, err := term.Size() | 274 | size, err := term.Size() | ||
| 271 | if err != nil { | 275 | if err != nil { | ||
| @@ -305,6 +309,7 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||||
| 305 | } | 309 | } | ||
| 306 | resumeToken = welcome.ResumeToken | 310 | resumeToken = welcome.ResumeToken | ||
| 307 | ms.welcomed = true | 311 | ms.welcomed = true | ||
| 312 | + | log.Debug("welcomed by daemon", "resume_token_present", resumeToken != 0) | |||
| 308 | case ports.MsgError: | 313 | case ports.MsgError: | ||
| 309 | em, derr := ports.UnmarshalErrorMsg(reply.Payload) | 314 | em, derr := ports.UnmarshalErrorMsg(reply.Payload) | ||
| 310 | if derr != nil { | 315 | if derr != nil { | ||
| @@ -330,13 +335,13 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||||
| 330 | sendCh := make(chan ports.Frame, sendQueueDepth) | 335 | sendCh := make(chan ports.Frame, sendQueueDepth) | ||
| 331 | sendErrCh := make(chan error, 1) | 336 | sendErrCh := make(chan error, 1) | ||
| 332 | 337 | ||||
| 333 | - | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh) | 338 | + | go runSender(loopCtx, cancel, transport, sendCh, sendErrCh, log) |
| 334 | - | go runStdin(loopCtx, cancel, term.In(), sendCh, trueColor) | 339 | + | go runStdin(loopCtx, cancel, term.In(), sendCh, trueColor, log) |
| 335 | - | go runResize(loopCtx, term.ResizeEvents(), sendCh) | 340 | + | go runResize(loopCtx, term.ResizeEvents(), sendCh, log) |
| 336 | 341 | ||||
| 337 | // 5. Output/main loop: the only goroutine that touches the terminal. | 342 | // 5. Output/main loop: the only goroutine that touches the terminal. | ||
| 338 | recvCh := make(chan recvResult, 1) | 343 | recvCh := make(chan recvResult, 1) | ||
| 339 | - | go runRecv(loopCtx, transport, recvCh) | 344 | + | go runRecv(loopCtx, transport, recvCh, log) |
| 340 | 345 | ||||
| 341 | for { | 346 | for { | ||
| 342 | select { | 347 | select { | ||
| @@ -368,13 +373,21 @@ func attachOnce(ctx context.Context, transport ports.Transport, term ports.Termi | |||||
| 368 | if ferr := term.Flush(); ferr != nil { | 373 | if ferr := term.Flush(); ferr != nil { | ||
| 369 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: flushing terminal: %w", ferr)} | 374 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: flushing terminal: %w", ferr)} | ||
| 370 | } | 375 | } | ||
| 371 | - | ms.firstOutput = true | 376 | + | if !ms.firstOutput { |
| 377 | + | ms.firstOutput = true | |||
| 378 | + | log.Debug("received first output") | |||
| 379 | + | } | |||
| 372 | case ports.MsgDetached: | 380 | case ports.MsgDetached: | ||
| 373 | d, derr := ports.UnmarshalDetached(r.frame.Payload) | 381 | d, derr := ports.UnmarshalDetached(r.frame.Payload) | ||
| 374 | if derr != nil { | 382 | if derr != nil { | ||
| 375 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: decoding detached: %w", derr)} | 383 | return attachResult{resumeToken: resumeToken, welcomed: true, err: fmt.Errorf("vev: decoding detached: %w", derr)} | ||
| 376 | } | 384 | } | ||
| 377 | ms.detached = true | 385 | ms.detached = true | ||
| 386 | + | if d.Reason == ports.ReasonDetach { | |||
| 387 | + | log.Info("detached cleanly", "reason", d.Reason) | |||
| 388 | + | } else { | |||
| 389 | + | log.Warn("detached by daemon", "reason", d.Reason) | |||
| 390 | + | } | |||
| 378 | return attachResult{resumeToken: resumeToken, welcomed: true, err: detachedResult(d.Reason)} | 391 | return attachResult{resumeToken: resumeToken, welcomed: true, err: detachedResult(d.Reason)} | ||
| 379 | case ports.MsgPong: | 392 | case ports.MsgPong: | ||
| 380 | // Liveness reply; nothing to do. | 393 | // Liveness reply; nothing to do. | ||
| @@ -395,7 +408,8 @@ type recvResult struct { | |||||
| 395 | 408 | ||||
| 396 | // runRecv reads frames until an error, forwarding each to the main loop. | 409 | // runRecv reads frames until an error, forwarding each to the main loop. | ||
| 397 | // It exits on the first error or when the loop context is cancelled. | 410 | // It exits on the first error or when the loop context is cancelled. | ||
| 398 | - | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult) { | 411 | + | func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResult, log *slog.Logger) { |
| 412 | + | defer log.Debug("receive pump exited") | |||
| 399 | for { | 413 | for { | ||
| 400 | f, err := transport.Recv() | 414 | f, err := transport.Recv() | ||
| 401 | select { | 415 | select { | ||
| @@ -412,7 +426,8 @@ func runRecv(ctx context.Context, transport ports.Transport, out chan<- recvResu | |||||
| 412 | // runSender is the sole caller of transport.Send: serialising the input and | 426 | // runSender is the sole caller of transport.Send: serialising the input and | ||
| 413 | // resize pumps through one goroutine keeps the transport's single-writer | 427 | // resize pumps through one goroutine keeps the transport's single-writer | ||
| 414 | // contract intact. A send failure cancels the loop and is surfaced once. | 428 | // contract intact. A send failure cancels the loop and is surfaced once. | ||
| 415 | - | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error) { | 429 | + | func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.Transport, in <-chan ports.Frame, errCh chan<- error, log *slog.Logger) { |
| 430 | + | defer log.Debug("sender pump exited") | |||
| 416 | for { | 431 | for { | ||
| 417 | select { | 432 | select { | ||
| 418 | case f := <-in: | 433 | case f := <-in: | ||
| @@ -445,7 +460,8 @@ func runSender(ctx context.Context, cancel context.CancelFunc, transport ports.T | |||||
| 445 | // exits. That is harmless here — Attach has already returned and restored | 460 | // exits. That is harmless here — Attach has already returned and restored | ||
| 446 | // the terminal — and matches the standard pattern for stdin pumps; a | 461 | // the terminal — and matches the standard pattern for stdin pumps; a | ||
| 447 | // closable stdin duplicate could lift it later if ever needed. | 462 | // closable stdin duplicate could lift it later if ever needed. | ||
| 448 | - | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, trueColor bool) { | 463 | + | func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out chan<- ports.Frame, trueColor bool, log *slog.Logger) { |
| 464 | + | defer log.Debug("stdin pump exited") | |||
| 449 | buf := make([]byte, stdinBufSize) | 465 | buf := make([]byte, stdinBufSize) | ||
| 450 | var scanner theme.Scanner | 466 | var scanner theme.Scanner | ||
| 451 | var inputSeq uint64 | 467 | var inputSeq uint64 | ||
| @@ -501,7 +517,8 @@ func runStdin(ctx context.Context, cancel context.CancelFunc, in io.Reader, out | |||||
| 501 | // runResize forwards coalesced terminal resize events to the daemon. It | 517 | // runResize forwards coalesced terminal resize events to the daemon. It | ||
| 502 | // tolerates an already-closed resize channel (which the terminal adapter | 518 | // tolerates an already-closed resize channel (which the terminal adapter | ||
| 503 | // hands back when restore ran before ResizeEvents was first called). | 519 | // hands back when restore ran before ResizeEvents was first called). | ||
| 504 | - | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame) { | 520 | + | func runResize(ctx context.Context, events <-chan domain.Size, out chan<- ports.Frame, log *slog.Logger) { |
| 521 | + | defer log.Debug("resize pump exited") | |||
| 505 | for { | 522 | for { | ||
| 506 | select { | 523 | select { | ||
| 507 | case sz, ok := <-events: | 524 | case sz, ok := <-events: | ||
M internal/usecase/client/client_test.go +5 -5
| @@ -550,7 +550,7 @@ func TestRunRestoresRawModeAfterAttachError(t *testing.T) { | |||
| 550 | 550 | d := portsmocks.NewMockDialer(t) | |
| 551 | 551 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | |
| 552 | 552 | ||
| 553 | - | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "") | |
| 553 | + | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) | |
| 554 | 554 | require.Error(t, err) | |
| 555 | 555 | require.Equal(t, int32(1), restoreCount.Load(), "Run must restore raw mode after attachOnce errors") | |
| 556 | 556 | } | |
| @@ -570,7 +570,7 @@ func TestRunDoesNotEnterRawBeforePreWelcomeError(t *testing.T) { | |||
| 570 | 570 | d := portsmocks.NewMockDialer(t) | |
| 571 | 571 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | |
| 572 | 572 | ||
| 573 | - | err := client.Run(context.Background(), d, tm, ports.IntentAttach, "main") | |
| 573 | + | err := client.Run(context.Background(), d, tm, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) | |
| 574 | 574 | require.Error(t, err) | |
| 575 | 575 | var pe *client.ProtocolError | |
| 576 | 576 | require.True(t, errors.As(err, &pe), "want *client.ProtocolError, got %T", err) | |
| @@ -582,7 +582,7 @@ func TestRunPhaseASingleAttempt(t *testing.T) { | |||
| 582 | 582 | d.EXPECT().Dial(mock.Anything).Return(nil, dialErr).Once() | |
| 583 | 583 | tm := portsmocks.NewMockTerminal(t) | |
| 584 | 584 | ||
| 585 | - | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "") | |
| 585 | + | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) | |
| 586 | 586 | require.ErrorIs(t, err, dialErr) | |
| 587 | 587 | } | |
| 588 | 588 | ||
| @@ -671,7 +671,7 @@ func TestRunReconnectsWithRotatedTokenAndSameClientID(t *testing.T) { | |||
| 671 | 671 | tr3 := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(33)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonDetach}))}}} | |
| 672 | 672 | d := &sequenceDialer{trs: []ports.Transport{tr1, tr2, tr3}} | |
| 673 | 673 | ||
| 674 | - | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main") | |
| 674 | + | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) | |
| 675 | 675 | require.NoError(t, err) | |
| 676 | 676 | require.Equal(t, int32(3), d.calls.Load()) | |
| 677 | 677 | require.Equal(t, int32(1), term.rawCount.Load()) | |
| @@ -698,7 +698,7 @@ func TestRunDoesNotRetryTerminalDetachedError(t *testing.T) { | |||
| 698 | 698 | tr := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(11)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonSessionKilled}))}}} | |
| 699 | 699 | d := &sequenceDialer{trs: []ports.Transport{tr}} | |
| 700 | 700 | ||
| 701 | - | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main") | |
| 701 | + | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) | |
| 702 | 702 | require.Error(t, err) | |
| 703 | 703 | var de *client.DetachedError | |
| 704 | 704 | require.True(t, errors.As(err, &de)) | |
| @@ -550,7 +550,7 @@ func TestRunRestoresRawModeAfterAttachError(t *testing.T) { | |||||
| 550 | d := portsmocks.NewMockDialer(t) | 550 | d := portsmocks.NewMockDialer(t) | ||
| 551 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | 551 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | ||
| 552 | 552 | ||||
| 553 | - | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "") | 553 | + | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) |
| 554 | require.Error(t, err) | 554 | require.Error(t, err) | ||
| 555 | require.Equal(t, int32(1), restoreCount.Load(), "Run must restore raw mode after attachOnce errors") | 555 | require.Equal(t, int32(1), restoreCount.Load(), "Run must restore raw mode after attachOnce errors") | ||
| 556 | } | 556 | } | ||
| @@ -570,7 +570,7 @@ func TestRunDoesNotEnterRawBeforePreWelcomeError(t *testing.T) { | |||||
| 570 | d := portsmocks.NewMockDialer(t) | 570 | d := portsmocks.NewMockDialer(t) | ||
| 571 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | 571 | d.EXPECT().Dial(mock.Anything).Return(tr, nil).Once() | ||
| 572 | 572 | ||||
| 573 | - | err := client.Run(context.Background(), d, tm, ports.IntentAttach, "main") | 573 | + | err := client.Run(context.Background(), d, tm, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) |
| 574 | require.Error(t, err) | 574 | require.Error(t, err) | ||
| 575 | var pe *client.ProtocolError | 575 | var pe *client.ProtocolError | ||
| 576 | require.True(t, errors.As(err, &pe), "want *client.ProtocolError, got %T", err) | 576 | require.True(t, errors.As(err, &pe), "want *client.ProtocolError, got %T", err) | ||
| @@ -582,7 +582,7 @@ func TestRunPhaseASingleAttempt(t *testing.T) { | |||||
| 582 | d.EXPECT().Dial(mock.Anything).Return(nil, dialErr).Once() | 582 | d.EXPECT().Dial(mock.Anything).Return(nil, dialErr).Once() | ||
| 583 | tm := portsmocks.NewMockTerminal(t) | 583 | tm := portsmocks.NewMockTerminal(t) | ||
| 584 | 584 | ||||
| 585 | - | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "") | 585 | + | err := client.Run(context.Background(), d, tm, ports.IntentEphemeral, "", slog.New(slog.DiscardHandler)) |
| 586 | require.ErrorIs(t, err, dialErr) | 586 | require.ErrorIs(t, err, dialErr) | ||
| 587 | } | 587 | } | ||
| 588 | 588 | ||||
| @@ -671,7 +671,7 @@ func TestRunReconnectsWithRotatedTokenAndSameClientID(t *testing.T) { | |||||
| 671 | tr3 := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(33)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonDetach}))}}} | 671 | tr3 := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(33)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonDetach}))}}} | ||
| 672 | d := &sequenceDialer{trs: []ports.Transport{tr1, tr2, tr3}} | 672 | d := &sequenceDialer{trs: []ports.Transport{tr1, tr2, tr3}} | ||
| 673 | 673 | ||||
| 674 | - | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main") | 674 | + | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) |
| 675 | require.NoError(t, err) | 675 | require.NoError(t, err) | ||
| 676 | require.Equal(t, int32(3), d.calls.Load()) | 676 | require.Equal(t, int32(3), d.calls.Load()) | ||
| 677 | require.Equal(t, int32(1), term.rawCount.Load()) | 677 | require.Equal(t, int32(1), term.rawCount.Load()) | ||
| @@ -698,7 +698,7 @@ func TestRunDoesNotRetryTerminalDetachedError(t *testing.T) { | |||||
| 698 | tr := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(11)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonSessionKilled}))}}} | 698 | tr := &recordingTransport{recvs: []recvItem{{f: welcomeFrame(11)}, {f: frameOf(ports.MsgDetached, ports.MarshalDetached(ports.Detached{Reason: ports.ReasonSessionKilled}))}}} | ||
| 699 | d := &sequenceDialer{trs: []ports.Transport{tr}} | 699 | d := &sequenceDialer{trs: []ports.Transport{tr}} | ||
| 700 | 700 | ||||
| 701 | - | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main") | 701 | + | err := client.Run(context.Background(), d, term, ports.IntentAttach, "main", slog.New(slog.DiscardHandler)) |
| 702 | require.Error(t, err) | 702 | require.Error(t, err) | ||
| 703 | var de *client.DetachedError | 703 | var de *client.DetachedError | ||
| 704 | require.True(t, errors.As(err, &de)) | 704 | require.True(t, errors.As(err, &de)) | ||
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 | } | ||
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/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 +15 -0
| @@ -83,6 +83,7 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||
| 83 | 83 | tbSize := tabSize(sz) | |
| 84 | 84 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | |
| 85 | 85 | if err != nil { | |
| 86 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "kind", "session") | |
| 86 | 87 | return nil, fmt.Errorf("daemon: spawning session %q: %w", name, err) | |
| 87 | 88 | } | |
| 88 | 89 | ||
| @@ -112,6 +113,8 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||
| 112 | 113 | delete(d.stopped, name) | |
| 113 | 114 | } | |
| 114 | 115 | d.sessions[id] = sess | |
| 116 | + | d.log.Info("session created", "session", name, "id", id, "ephemeral", ephemeral) | |
| 117 | + | d.log.Info("tab created", "session", name, "tab", 0) | |
| 115 | 118 | d.startTabGoroutines(sess, tb) | |
| 116 | 119 | return sess, nil | |
| 117 | 120 | } | |
| @@ -159,6 +162,7 @@ func (d *Daemon) createSessionAndSwitch(from *session, ac *attachedClient, name | |||
| 159 | 162 | newSess.client = ac | |
| 160 | 163 | newSess.mu.Unlock() | |
| 161 | 164 | ac.setSession(newSess) | |
| 165 | + | d.log.Info("client attached", "session", newSess.name, "resume", ac.resumeCapable) | |
| 162 | 166 | d.mu.Unlock() | |
| 163 | 167 | ||
| 164 | 168 | d.firstPaint(newSess, ac, sz) | |
| @@ -174,6 +178,7 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||
| 174 | 178 | sess.mu.Unlock() | |
| 175 | 179 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | |
| 176 | 180 | if err != nil { | |
| 181 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "kind", "tab") | |
| 177 | 182 | return fmt.Errorf("daemon: spawning tab for session %q: %w", name, err) | |
| 178 | 183 | } | |
| 179 | 184 | tb := newTab(pty, tbSize) | |
| @@ -201,7 +206,9 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||
| 201 | 206 | sess.mu.Lock() | |
| 202 | 207 | sess.tabs = append(sess.tabs, tb) | |
| 203 | 208 | sess.active = len(sess.tabs) - 1 | |
| 209 | + | tabIndex := sess.active | |
| 204 | 210 | sess.mu.Unlock() | |
| 211 | + | d.log.Info("tab created", "session", name, "tab", tabIndex) | |
| 205 | 212 | d.startTabGoroutines(sess, tb) | |
| 206 | 213 | d.mu.Unlock() | |
| 207 | 214 | return nil | |
| @@ -268,6 +275,9 @@ func (d *Daemon) startTabGoroutines(sess *session, tb *tab) { | |||
| 268 | 275 | } | |
| 269 | 276 | ||
| 270 | 277 | func (d *Daemon) startPaneGoroutines(sess *session, tb *tab, p *pane) { | |
| 278 | + | if p != nil { | |
| 279 | + | d.log.Info("pane created", "session", sess.name, "pane", p.id) | |
| 280 | + | } | |
| 271 | 281 | d.sessWg.Add(2) | |
| 272 | 282 | go d.ptyReader(sess, tb, p) | |
| 273 | 283 | go d.scheduler(sess, tb, p) | |
| @@ -371,7 +381,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||
| 371 | 381 | return | |
| 372 | 382 | } | |
| 373 | 383 | if len(sess.tabs) == 1 { | |
| 384 | + | name := sess.name | |
| 374 | 385 | sess.mu.Unlock() | |
| 386 | + | d.log.Info("tab closed", "session", name, "last", true) | |
| 375 | 387 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | |
| 376 | 388 | return | |
| 377 | 389 | } | |
| @@ -383,7 +395,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||
| 383 | 395 | sess.active-- | |
| 384 | 396 | } | |
| 385 | 397 | ac := sess.client | |
| 398 | + | name := sess.name | |
| 386 | 399 | sess.mu.Unlock() | |
| 400 | + | d.log.Info("tab closed", "session", name) | |
| 387 | 401 | ||
| 388 | 402 | d.clearDestroyedTabPreview(tb) | |
| 389 | 403 | if tb.cancel != nil { | |
| @@ -434,6 +448,7 @@ func (d *Daemon) killSession(sess *session, reason uint8, purge bool) error { | |||
| 434 | 448 | d.closing = true | |
| 435 | 449 | } | |
| 436 | 450 | d.mu.Unlock() | |
| 451 | + | d.log.Info("session closed", "session", stoppedName, "id", sess.id, "ephemeral", ephemeral, "purge", purge, "reason", reason) | |
| 437 | 452 | ||
| 438 | 453 | var purgeErr error | |
| 439 | 454 | if !ephemeral && purge { | |
| @@ -83,6 +83,7 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||||
| 83 | tbSize := tabSize(sz) | 83 | tbSize := tabSize(sz) | ||
| 84 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | 84 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | ||
| 85 | if err != nil { | 85 | if err != nil { | ||
| 86 | + | d.log.Warn("pty spawn failed", "err", err, "session", name, "kind", "session") | |||
| 86 | return nil, fmt.Errorf("daemon: spawning session %q: %w", name, err) | 87 | return nil, fmt.Errorf("daemon: spawning session %q: %w", name, err) | ||
| 87 | } | 88 | } | ||
| 88 | 89 | ||||
| @@ -112,6 +113,8 @@ func (d *Daemon) createSessionLocked(name string, ephemeral bool, cwd string, sz | |||||
| 112 | delete(d.stopped, name) | 113 | delete(d.stopped, name) | ||
| 113 | } | 114 | } | ||
| 114 | d.sessions[id] = sess | 115 | d.sessions[id] = sess | ||
| 116 | + | d.log.Info("session created", "session", name, "id", id, "ephemeral", ephemeral) | |||
| 117 | + | d.log.Info("tab created", "session", name, "tab", 0) | |||
| 115 | d.startTabGoroutines(sess, tb) | 118 | d.startTabGoroutines(sess, tb) | ||
| 116 | return sess, nil | 119 | return sess, nil | ||
| 117 | } | 120 | } | ||
| @@ -159,6 +162,7 @@ func (d *Daemon) createSessionAndSwitch(from *session, ac *attachedClient, name | |||||
| 159 | newSess.client = ac | 162 | newSess.client = ac | ||
| 160 | newSess.mu.Unlock() | 163 | newSess.mu.Unlock() | ||
| 161 | ac.setSession(newSess) | 164 | ac.setSession(newSess) | ||
| 165 | + | d.log.Info("client attached", "session", newSess.name, "resume", ac.resumeCapable) | |||
| 162 | d.mu.Unlock() | 166 | d.mu.Unlock() | ||
| 163 | 167 | ||||
| 164 | d.firstPaint(newSess, ac, sz) | 168 | d.firstPaint(newSess, ac, sz) | ||
| @@ -174,6 +178,7 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||||
| 174 | sess.mu.Unlock() | 178 | sess.mu.Unlock() | ||
| 175 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | 179 | pty, err := d.ptys.Open(d.shell, d.shellArgs, d.childEnv(name), cwd, tbSize) | ||
| 176 | if err != nil { | 180 | if err != nil { | ||
| 181 | + | 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) | 182 | return fmt.Errorf("daemon: spawning tab for session %q: %w", name, err) | ||
| 178 | } | 183 | } | ||
| 179 | tb := newTab(pty, tbSize) | 184 | tb := newTab(pty, tbSize) | ||
| @@ -201,7 +206,9 @@ func (d *Daemon) createTab(sess *session, sz domain.Size) error { | |||||
| 201 | sess.mu.Lock() | 206 | sess.mu.Lock() | ||
| 202 | sess.tabs = append(sess.tabs, tb) | 207 | sess.tabs = append(sess.tabs, tb) | ||
| 203 | sess.active = len(sess.tabs) - 1 | 208 | sess.active = len(sess.tabs) - 1 | ||
| 209 | + | tabIndex := sess.active | |||
| 204 | sess.mu.Unlock() | 210 | sess.mu.Unlock() | ||
| 211 | + | d.log.Info("tab created", "session", name, "tab", tabIndex) | |||
| 205 | d.startTabGoroutines(sess, tb) | 212 | d.startTabGoroutines(sess, tb) | ||
| 206 | d.mu.Unlock() | 213 | d.mu.Unlock() | ||
| 207 | return nil | 214 | return nil | ||
| @@ -268,6 +275,9 @@ func (d *Daemon) startTabGoroutines(sess *session, tb *tab) { | |||||
| 268 | } | 275 | } | ||
| 269 | 276 | ||||
| 270 | func (d *Daemon) startPaneGoroutines(sess *session, tb *tab, p *pane) { | 277 | func (d *Daemon) startPaneGoroutines(sess *session, tb *tab, p *pane) { | ||
| 278 | + | if p != nil { | |||
| 279 | + | d.log.Info("pane created", "session", sess.name, "pane", p.id) | |||
| 280 | + | } | |||
| 271 | d.sessWg.Add(2) | 281 | d.sessWg.Add(2) | ||
| 272 | go d.ptyReader(sess, tb, p) | 282 | go d.ptyReader(sess, tb, p) | ||
| 273 | go d.scheduler(sess, tb, p) | 283 | go d.scheduler(sess, tb, p) | ||
| @@ -371,7 +381,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||||
| 371 | return | 381 | return | ||
| 372 | } | 382 | } | ||
| 373 | if len(sess.tabs) == 1 { | 383 | if len(sess.tabs) == 1 { | ||
| 384 | + | name := sess.name | |||
| 374 | sess.mu.Unlock() | 385 | sess.mu.Unlock() | ||
| 386 | + | d.log.Info("tab closed", "session", name, "last", true) | |||
| 375 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | 387 | _ = d.killSession(sess, ports.ReasonSessionKilled, false) | ||
| 376 | return | 388 | return | ||
| 377 | } | 389 | } | ||
| @@ -383,7 +395,9 @@ func (d *Daemon) closeTab(sess *session, tb *tab, repaint bool) { | |||||
| 383 | sess.active-- | 395 | sess.active-- | ||
| 384 | } | 396 | } | ||
| 385 | ac := sess.client | 397 | ac := sess.client | ||
| 398 | + | name := sess.name | |||
| 386 | sess.mu.Unlock() | 399 | sess.mu.Unlock() | ||
| 400 | + | d.log.Info("tab closed", "session", name) | |||
| 387 | 401 | ||||
| 388 | d.clearDestroyedTabPreview(tb) | 402 | d.clearDestroyedTabPreview(tb) | ||
| 389 | if tb.cancel != nil { | 403 | if tb.cancel != nil { | ||
| @@ -434,6 +448,7 @@ func (d *Daemon) killSession(sess *session, reason uint8, purge bool) error { | |||||
| 434 | d.closing = true | 448 | d.closing = true | ||
| 435 | } | 449 | } | ||
| 436 | d.mu.Unlock() | 450 | d.mu.Unlock() | ||
| 451 | + | d.log.Info("session closed", "session", stoppedName, "id", sess.id, "ephemeral", ephemeral, "purge", purge, "reason", reason) | |||
| 437 | 452 | ||||
| 438 | var purgeErr error | 453 | var purgeErr error | ||
| 439 | if !ephemeral && purge { | 454 | if !ephemeral && purge { | ||