TEMPORARY: trace speaker HTTP and player WS/HTTP traffic

Not for merge. Measures the source-selection readback cost in PR #670
review finding 2.

Server side: an http.RoundTripper wrapper on the speaker client logs every
outgoing request with a sequence number, path, status and duration. One
hook catches get/post/postWithResponse/avtransport alike. Enabled by
AFTERTOUCH_TRACE_SPEAKER=1.

Browser side: wraps fetch and WebSocket to log the player's HTTP calls and
every speaker event frame, with __trace.mark()/__trace.report() to bracket
and summarise one interaction. Enabled by localStorage.aftertouchTrace='1'.

Both are off by default, so a stray build stays silent. Delete
pkg/client/trace_temp.go, static/js/trace_temp.js, and their two call sites
when done.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

pkg/client/client.go

@@ -218,9 +218,9 @@ func NewClient(config *Config) *Client {
 
 		return &Client{
 			baseURL: fmt.Sprintf("http://%s:%d", config.Host, port),
-			httpClient: &http.Client{
+			httpClient: installSpeakerTrace(&http.Client{
 				Timeout: config.Timeout,
-			},
+			}),
 			timeout:   config.Timeout,
 			userAgent: config.UserAgent,
 		}
@@ -248,9 +248,9 @@ func NewClient(config *Config) *Client {
 
 	return &Client{
 		baseURL: u.String(),
-		httpClient: &http.Client{
+		httpClient: installSpeakerTrace(&http.Client{
 			Timeout: config.Timeout,
-		},
+		}),
 		timeout:   config.Timeout,
 		userAgent: config.UserAgent,
 	}

pkg/client/trace_temp.go

@@ -0,0 +1,69 @@
+package client
+
+// TEMPORARY INSTRUMENTATION -- do not merge.
+//
+// Added to measure the source-selection readback cost described in PR #670
+// review finding 2 (three readbacks per source click, each running a full
+// UpdateDeviceStatus against the speaker). Delete this file, and the
+// traceTransport wiring in NewClient, once the measurement is done.
+//
+// Off unless AFTERTOUCH_TRACE_SPEAKER=1, so a stray build stays silent.
+
+import (
+	"fmt"
+	"log"
+	"net/http"
+	"os"
+	"strings"
+	"sync/atomic"
+	"time"
+)
+
+var (
+	traceSpeakerEnabled = os.Getenv("AFTERTOUCH_TRACE_SPEAKER") == "1"
+	traceSpeakerSeq     atomic.Int64
+	traceStart          = time.Now()
+)
+
+// traceTransport logs every outgoing speaker request with a sequence number,
+// the elapsed time since process start, and the round-trip duration.
+type traceTransport struct{ base http.RoundTripper }
+
+func (t *traceTransport) RoundTrip(req *http.Request) (*http.Response, error) {
+	base := t.base
+	if base == nil {
+		base = http.DefaultTransport
+	}
+
+	seq := traceSpeakerSeq.Add(1)
+	started := time.Now()
+	resp, err := base.RoundTrip(req)
+	elapsed := time.Since(started)
+
+	status := "ERR"
+	if resp != nil {
+		status = fmt.Sprintf("%d", resp.StatusCode)
+	}
+
+	detail := ""
+	if err != nil {
+		detail = " err=" + strings.ReplaceAll(err.Error(), "\n", " ")
+	}
+
+	log.Printf("[SPEAKER-TRACE] #%04d t=%8.3fs %-4s %-28s host=%-22s status=%-3s took=%6.1fms%s",
+		seq, time.Since(traceStart).Seconds(), req.Method, req.URL.Path,
+		req.URL.Host, status, float64(elapsed.Microseconds())/1000, detail)
+
+	return resp, err
+}
+
+// installSpeakerTrace wraps an http.Client's transport when tracing is on.
+func installSpeakerTrace(c *http.Client) *http.Client {
+	if !traceSpeakerEnabled || c == nil {
+		return c
+	}
+
+	c.Transport = &traceTransport{base: c.Transport}
+
+	return c
+}

pkg/service/soundtouchweb/static/js/app.js

@@ -18,6 +18,10 @@ import { Announcements } from './components/Announcements.js';
 import { api } from './api.js';
 import { isSoundTouch10StereoPair } from './stereoPresentation.mjs';
 import { removeDeviceAndRefresh } from './deviceRemoval.js';
+// TEMPORARY INSTRUMENTATION -- do not merge. See trace_temp.js.
+import { installTrace } from './trace_temp.js';
+
+installTrace();
 
 const html = htm.bind(h);
 

pkg/service/soundtouchweb/static/js/trace_temp.js

@@ -0,0 +1,119 @@
+// TEMPORARY INSTRUMENTATION -- do not merge.
+//
+// Counts the player's HTTP calls and the speaker events arriving over the
+// WebSocket, to measure the source-selection readback cost in PR #670 review
+// finding 2. Delete this file and its import in app.js once done.
+//
+// Off unless localStorage.aftertouchTrace === '1', so it costs nothing until
+// switched on. In the browser console:
+//
+//   localStorage.aftertouchTrace = '1'; location.reload();
+//   __trace.mark('click AUX');   // before each thing you want to bracket
+//   __trace.report();            // grouped counts since the last mark
+//   __trace.reset();
+//   delete localStorage.aftertouchTrace; location.reload();
+
+let enabled = false;
+try {
+    enabled = localStorage.getItem('aftertouchTrace') === '1';
+} catch (_) {
+    enabled = false;
+}
+
+const started = performance.now();
+const entries = [];
+let markLabel = 'start';
+let markAt = started;
+
+function since() {
+    return ((performance.now() - started) / 1000).toFixed(3);
+}
+
+function record(kind, detail, extra = {}) {
+    const entry = { kind, detail, at: performance.now(), mark: markLabel, ...extra };
+    entries.push(entry);
+    const offset = ((entry.at - markAt) / 1000).toFixed(3);
+    console.log(`[trace] t=${since()}s +${offset}s after "${markLabel}"  ${kind}  ${detail}`,
+        Object.keys(extra).length ? extra : '');
+}
+
+export function installTrace() {
+    if (!enabled) return;
+
+    const nativeFetch = globalThis.fetch.bind(globalThis);
+    globalThis.fetch = async (input, init) => {
+        const url = typeof input === 'string' ? input : input?.url ?? String(input);
+        const method = init?.method ?? (typeof input === 'object' ? input?.method : null) ?? 'GET';
+        const at = performance.now();
+        try {
+            const response = await nativeFetch(input, init);
+            record('HTTP', `${method} ${url}`, {
+                status: response.status,
+                ms: Math.round(performance.now() - at),
+            });
+            return response;
+        } catch (error) {
+            record('HTTP', `${method} ${url}`, { status: 'ERR', ms: Math.round(performance.now() - at) });
+            throw error;
+        }
+    };
+
+    const NativeWebSocket = globalThis.WebSocket;
+    globalThis.WebSocket = function TracedWebSocket(url, protocols) {
+        const socket = protocols === undefined
+            ? new NativeWebSocket(url) : new NativeWebSocket(url, protocols);
+        record('WS', `open ${url}`);
+        socket.addEventListener('message', event => {
+            let type = 'unparsed';
+            let deviceId = '';
+            let extra = {};
+            try {
+                const msg = JSON.parse(event.data);
+                type = msg.type ?? 'untyped';
+                deviceId = msg.deviceId ?? '';
+                // The two fields this investigation cares about.
+                const status = msg.data?.status ?? msg.data?.[deviceId]?.status;
+                if (status) {
+                    extra = {
+                        source: status.nowPlaying?.Source,
+                        revision: status.revision,
+                        nowPlayingRevision: status.nowPlayingRevision,
+                        epoch: status.epoch,
+                    };
+                }
+            } catch (_) { /* keep the frame counted even if it is not JSON */ }
+            record('WS', `${type}${deviceId ? ' ' + deviceId : ''}`, extra);
+        });
+        socket.addEventListener('close', () => record('WS', `close ${url}`));
+        return socket;
+    };
+    globalThis.WebSocket.prototype = NativeWebSocket.prototype;
+
+    globalThis.__trace = {
+        mark(label) {
+            markLabel = label;
+            markAt = performance.now();
+            console.log(`[trace] ---- mark: ${label} (t=${since()}s) ----`);
+        },
+        report() {
+            const scoped = entries.filter(e => e.mark === markLabel);
+            const byDetail = new Map();
+            for (const e of scoped) {
+                const key = `${e.kind}  ${e.detail}`;
+                byDetail.set(key, (byDetail.get(key) ?? 0) + 1);
+            }
+            console.log(`[trace] since "${markLabel}": ${scoped.length} events`);
+            console.table([...byDetail.entries()]
+                .sort((a, b) => b[1] - a[1])
+                .map(([what, count]) => ({ count, what })));
+            return scoped;
+        },
+        entries: () => entries,
+        reset() {
+            entries.length = 0;
+            markAt = performance.now();
+        },
+    };
+
+    console.log('[trace] AfterTouch player tracing on. __trace.mark(label) / __trace.report()');
+}