From 62da5f23e059c0d4f58b6acbef883f98e9a75ce2 Mon Sep 17 00:00:00 2001 From: Tobias Gesellchen Date: Sat, 5 Sep 2026 19:33:37 +0200 Subject: [PATCH] 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) --- pkg/client/client.go | 8 +- pkg/client/trace_temp.go | 69 ++++++++++ pkg/service/soundtouchweb/static/js/app.js | 4 + .../soundtouchweb/static/js/trace_temp.js | 119 ++++++++++++++++++ 4 files changed, 196 insertions(+), 4 deletions(-) create mode 100644 pkg/client/trace_temp.go create mode 100644 pkg/service/soundtouchweb/static/js/trace_temp.js diff --git a/pkg/client/client.go b/pkg/client/client.go index 9799ad95..38c9af6b 100644 --- a/pkg/client/client.go +++ b/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, } diff --git a/pkg/client/trace_temp.go b/pkg/client/trace_temp.go new file mode 100644 index 00000000..1c913997 --- /dev/null +++ b/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 +} diff --git a/pkg/service/soundtouchweb/static/js/app.js b/pkg/service/soundtouchweb/static/js/app.js index 11fd7022..1d2f423e 100644 --- a/pkg/service/soundtouchweb/static/js/app.js +++ b/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); diff --git a/pkg/service/soundtouchweb/static/js/trace_temp.js b/pkg/service/soundtouchweb/static/js/trace_temp.js new file mode 100644 index 00000000..b9b773ed --- /dev/null +++ b/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()'); +}