Duck the Sendspin stream while Alexa holds audio focus

docs/audio.md

@@ -398,6 +398,58 @@ one at a time, as there is one player.
   queue plays out; clearing it would need
   `SLAndroidSimpleBufferQueueItf::Clear`, which flushes the `AudioTrack`.
 
+## Ducking while Alexa holds focus
+
+- Alexa takes audio focus as `GAIN_TRANSIENT_MAY_DUCK` while she listens and
+  answers. Android 5.1 does not duck anything itself: a player has to hear the
+  focus change and lower its own level.
+- The player holds no focus, so it hears nothing. Holding focus would take a
+  resident Java process, about 25 MB on a Dot with about 110 MB free, and
+  `app_process` crashes on teardown (above).
+- The Sendspin volume is `STREAM_MUSIC`, which her speech plays on too, so the
+  duck cannot be a stream volume. It is a gain on the stream's own samples,
+  applied after placement, so timing and sync are untouched.
+- `system_server` logs every focus change, and `alexa.FocusWatcher` follows
+  `logcat -s MediaFocusControl`:
+
+```
+I/MediaFocusControl(  601):  AudioFocus  requestAudioFocus() from com.amazon.media.AmazonAudioManager@37705de9amazon.speech.util.AudioFocusHelper$2@22ab2a6e req=3flags=0x0
+I/MediaFocusControl(  601):  AudioFocus  abandonAudioFocus() from com.amazon.media.AmazonAudioManager@37705de9amazon.speech.util.AudioFocusHelper$2@22ab2a6e
+I/MediaFocusControl(  601): AudioFocus  removeFocusStackEntry(): removing entry for com.amazon.media.AmazonAudioManager@37705de9amazon.speech.util.AudioFocusHelper$2@22ab2a6e
+```
+
+- Her requests overlap. One "what time is it" took focus from 3 clients in
+  turn, each requesting before the last abandoned, over 10.3 seconds. So the
+  watcher keeps a set of holders, not a flag, and the stream stays ducked until
+  the set is empty.
+- `removeFocusStackEntry` logs whenever an entry leaves from below the top of
+  the stack: after an abandon, and also after a re-request, which moves the
+  client to the top. So a removal releases its client unless it comes straight
+  after that client's own request.
+- A client that dies holding focus is logged by its binder
+  (`android.os.BinderProxy@...`), which names no holder. Only the 15-minute
+  expiry releases it.
+
+| `req=` | request | stream level |
+|---|---|---|
+| 3 | `GAIN_TRANSIENT_MAY_DUCK` | 20% |
+| 2, 4 | `GAIN_TRANSIENT`, `GAIN_TRANSIENT_EXCLUSIVE` | 10% |
+| 1 | `GAIN` | 100%: a permanent taker plays beside the stream, as before |
+
+- The deepest holder wins. The levels match sendspinlite's on an Echo Show.
+- Nothing handles a permanent taker. If Alexa plays music herself, both streams
+  play at full level, as they did before. A gain cannot fix that: the stream
+  would need a pause the Sendspin layer can resume.
+- Her speech does duck over her own music, because the deepest holder wins. No
+  test covers a `req=1` and a `req=3` holder together, which is that pair.
+- The gain moves linearly, a full swing taking 50 ms down and 300 ms up: 100%
+  to 20% in 40 ms, and back in 240 ms. No click on either edge.
+- At full gain the samples are not touched, so an unducked stream is
+  bit-identical to before.
+- A stream opened while a holder is held starts at the ducked level.
+- It fails toward full level: each holder expires 15 minutes after its
+  request, and when logcat exits the set is cleared before the retry.
+
 ## Testing audio here
 
 - **Never test with a sustained pure tone.** A 20-second 440 Hz sine pulses

docs/pitfalls.md

@@ -72,6 +72,15 @@ covering whatever you are about to touch.
   "connection refused". `internal/alexa` reads `net.dns1` and `net.dns2` and
   builds its own resolver.
 
+## logcat followers
+
+- `internal/alexa` follows logcat in a child process for each watcher. A
+  restart kills the daemon before its deferred `Kill` runs, so each child used
+  to be left running under init: two more `logcat` processes per restart, for
+  the rest of the boot.
+- Each child is started with `Pdeathsig: SIGKILL`, so the kernel kills it when
+  the daemon goes. A daemon killed with `kill` left no `logcat` behind.
+
 ## The firewall
 
 - FireOS runs iptables with `INPUT policy DROP` and a port allowlist without

docs/usage.md

@@ -245,6 +245,8 @@ Sendspin identity.
 - Setting it from Home Assistant sets the level of the route in
   `output_device` exactly. It is silent: no key press, so no tick.
 - Music Assistant can set it over Sendspin too.
+- Sendspin ducks to 20% while Alexa listens and answers, and comes back when
+  she is done. docs/audio.md has how.
 - Android keeps a level per route: `volume` for the speaker, `jack_volume` for
   the socket, `bluetooth_volume` for a paired speaker. All 3 are reported
   whatever is connected.

internal/alexa/focus.go

@@ -0,0 +1,179 @@
+package alexa
+
+import (
+	"io"
+	"log"
+	"strings"
+	"sync"
+	"time"
+)
+
+const (
+	duckPercent     = 20
+	deepDuckPercent = 10
+	fullPercent     = 100
+	holdFor         = 15 * time.Minute
+
+	requestMark = "requestAudioFocus() from "
+	reqMark     = " req="
+	abandonMark = "abandonAudioFocus() from "
+	removeMark  = "removeFocusStackEntry(): removing entry for "
+)
+
+var focusArgv = []string{"/system/bin/logcat", "-T", "1", "-v", "brief", "-s", "MediaFocusControl"}
+
+type focusHolder struct {
+	req   int
+	until time.Time
+}
+
+type FocusWatcher struct {
+	OnLevel func(percent int)
+
+	notify    sync.Mutex
+	mu        sync.Mutex
+	requested string
+	holders   map[string]focusHolder
+	level     int
+	now       func() time.Time
+}
+
+func (w *FocusWatcher) clock() time.Time {
+	if w.now != nil {
+		return w.now()
+	}
+	return time.Now()
+}
+
+func (w *FocusWatcher) Run() {
+	go w.sweep()
+	keepFollowing("focus watcher", focusArgv, w.line, w.reset)
+}
+
+func (w *FocusWatcher) sweep() {
+	for range time.Tick(sweepEvery) {
+		w.expire()
+	}
+}
+
+func (w *FocusWatcher) read(r io.Reader) error {
+	return readLines(r, w.line)
+}
+
+func (w *FocusWatcher) line(line string) {
+	if i := strings.Index(line, requestMark); i >= 0 {
+		rest := line[i+len(requestMark):]
+		j := strings.LastIndex(rest, reqMark)
+		if j < 0 {
+			return
+		}
+		req, ok := leadingInt(rest[j+len(reqMark):])
+		if !ok {
+			return
+		}
+		client := strings.TrimSpace(rest[:j])
+		w.request(client, req)
+		w.requested = client
+		return
+	}
+	if i := strings.Index(line, abandonMark); i >= 0 {
+		w.requested = ""
+		w.release(strings.TrimSpace(line[i+len(abandonMark):]))
+		return
+	}
+	if i := strings.Index(line, removeMark); i >= 0 {
+		client := strings.TrimSpace(line[i+len(removeMark):])
+		requested := w.requested
+		w.requested = ""
+		if client == requested {
+			return
+		}
+		w.release(client)
+	}
+}
+
+func leadingInt(s string) (int, bool) {
+	n, digits := 0, 0
+	for digits < len(s) && digits < 9 && s[digits] >= '0' && s[digits] <= '9' {
+		n = n*10 + int(s[digits]-'0')
+		digits++
+	}
+	return n, digits > 0
+}
+
+func (w *FocusWatcher) request(client string, req int) {
+	if client == "" {
+		return
+	}
+	w.change(func() {
+		if w.holders == nil {
+			w.holders = map[string]focusHolder{}
+		}
+		w.holders[client] = focusHolder{req: req, until: w.clock().Add(holdFor)}
+	})
+}
+
+func (w *FocusWatcher) release(client string) {
+	if client == "" {
+		return
+	}
+	w.change(func() {
+		delete(w.holders, client)
+	})
+}
+
+func (w *FocusWatcher) expire() {
+	dropped := 0
+	w.change(func() {
+		now := w.clock()
+		for client, h := range w.holders {
+			if now.After(h.until) {
+				delete(w.holders, client)
+				dropped++
+			}
+		}
+	})
+	if dropped > 0 {
+		log.Printf("focus watcher: %d clients never abandoned audio focus, so their hold"+
+			" was dropped after %v", dropped, holdFor)
+	}
+}
+
+func (w *FocusWatcher) reset() {
+	w.requested = ""
+	w.change(func() {
+		clear(w.holders)
+	})
+}
+
+func (w *FocusWatcher) change(mutate func()) {
+	w.notify.Lock()
+	defer w.notify.Unlock()
+
+	w.mu.Lock()
+	mutate()
+	level := fullPercent
+	for _, h := range w.holders {
+		level = min(level, percentFor(h.req))
+	}
+	was := w.level
+	if was == 0 {
+		was = fullPercent
+	}
+	w.level = level
+	w.mu.Unlock()
+
+	if level != was && w.OnLevel != nil {
+		w.OnLevel(level)
+	}
+}
+
+func percentFor(req int) int {
+	switch req {
+	case 3:
+		return duckPercent
+	case 2, 4:
+		return deepDuckPercent
+	}
+	return fullPercent
+}