Merge pull request 'fix(dankvoice): pin thinking off in rewrite, fix silent and timeout modes' (#33) from fix/32-dankvoice-latency into main

agent/extensions/dankvoice.ts

@@ -576,7 +576,18 @@ export function resolveRewriter(env: NodeJS.ProcessEnv, modelsYml: string, confi
   return resolveTinyRewriter(modelsYml, configYml);
 }
 
-/** The enhancer's rewrite step; never throws — null is its "couldn't". */
+/**
+ * The enhancer's rewrite step; never throws — null is its "couldn't".
+ *
+ * The `chat_template_kwargs.enable_thinking: false` field is load-bearing.
+ * The @tiny fleet model (frank-zealot, a Qwen35 hybrid) defaults to a
+ * reasoning pass that fills `reasoning_content` and leaves `content` empty.
+ * The harness injects this flag for the built-in vocalizer; a raw POST does
+ * not get it, so without it the rewrite spends its whole 6 s budget thinking
+ * (blowing the timeout → mechanical fallback) and, when it answers in time,
+ * returns an empty `content` that would mute the utterance. Measured: 6.9 s /
+ * empty content without the flag, 0.55 s / clean prose with it.
+ */
 export async function rewriteForSpeech(target: RewriteTarget, text: string): Promise<string | null> {
   try {
     const res = await fetch(target.chatUrl, {
@@ -589,6 +600,7 @@ export async function rewriteForSpeech(target: RewriteTarget, text: string): Pro
           { role: "user", content: text.slice(0, REWRITE_MAX_INPUT) },
         ],
         max_tokens: REWRITE_MAX_TOKENS,
+        chat_template_kwargs: { enable_thinking: false },
       }),
       signal: AbortSignal.timeout(REWRITE_TIMEOUT_MS),
     });
@@ -600,8 +612,24 @@ export async function rewriteForSpeech(target: RewriteTarget, text: string): Pro
     const message: unknown = first.message;
     if (!message || typeof message !== "object" || !("content" in message)) return null;
     const content: unknown = message.content;
-    if (typeof content === "string") return content.trim();
-    if (!Array.isArray(content)) return null;
+    const spoken = typeof content === "string" ? content.trim() : Array.isArray(content) ? textParts(content) : null;
+    if (spoken === null) return null;
+    if (spoken === "") {
+      // A reasoning-only reply means the endpoint ignored the thinking-off
+      // flag: the prose landed in reasoning_content, not content. That is a
+      // failed rewrite (fall back to mechanical text), NOT the enhancer's
+      // legitimate "" ("nothing worth saying") — which has no reasoning.
+      const reasoning = "reasoning_content" in message ? message.reasoning_content : undefined;
+      if (typeof reasoning === "string" && reasoning.trim().length > 0) return null;
+    }
+    return spoken;
+  } catch {
+    return null;
+  }
+}
+
+/** Concatenated text of a content-part array; undefined shape handled by caller. */
+function textParts(content: readonly unknown[]): string {
   const parts: string[] = [];
   for (const part of content) {
     if (part && typeof part === "object" && "type" in part && part.type === "text" && "text" in part && typeof part.text === "string") {
@@ -609,9 +637,6 @@ export async function rewriteForSpeech(target: RewriteTarget, text: string): Pro
     }
   }
   return parts.join(" ").trim();
-  } catch {
-    return null;
-  }
 }
 
 /** The text the assistant last actually said; tool-only messages do not count. */
@@ -1043,7 +1068,14 @@ export default function dankvoice(pi: ExtensionAPI) {
       persistSettings(ctx);
       return;
     }
-    await speak(ctx, `dankvoice: ${voiceLabel()} through ${cfg.player?.command ?? "no player"}, checking.`);
+    // Fire-and-forget on purpose: awaiting the playback chain here blocks
+    // the menu handler for the whole phrase and the harness reports the
+    // command as timed out. The point of the test is to hear it, not to
+    // block the menu on it.
+    ctx.ui.notify("dankvoice: speaking the test phrase", "info");
+    void speak(ctx, `dankvoice: ${voiceLabel()} through ${cfg.player?.command ?? "no player"}, checking.`).catch((error) =>
+      ctx.ui.notify(`dankvoice: ${error instanceof Error ? error.message : String(error)}`, "error"),
+    );
   }
 
   pi.registerCommand("say", {

omp-docs/core/dankvoice.md

@@ -142,6 +142,15 @@ supplies the `baseUrl`; the request is `POST {base}/chat/completions`. On
 this fleet that is **frank-zealot** (`llamacpp (dankclaw-3090)`,
 `:7771`) — the 6 s abort keeps a slow tiny model off the critical path.
 
+The request body pins `chat_template_kwargs: { enable_thinking: false }`,
+and that field is load-bearing: the harness injects it for managed roles,
+but a raw `fetch` gets the model's default — thinking on — so the Qwen35
+hybrid spends the budget on `reasoning_content` and answers `content: ""`
+(measured: 6.9 s / 6893 reasoning chars / empty content without the flag;
+0.55 s / 369 clean chars with it). For a hybrid endpoint, empty content
+beside non-empty `reasoning_content` means the flag was ignored — a failed
+rewrite (mechanical fallback), never the legitimate "nothing to say".
+
 Thinking blocks ride the same path: at `agent_end` the last assistant
 message's true `thinking` parts are narrated (rewritten first, as their own
 unit, before the answer), while blocks flagged `narration: true` — which
@@ -196,6 +205,14 @@ the choice persists in the settings file.
   prose segments (mechanical cleanup of that text yields at most 2), and a
   thinking+answer `agent_end` played thinking first. 22 green in
   `tests/dankvoice.bats`.
+* **Thinking-off fix (2026-10-19, Refs #32)** — replaying the exact rewrite
+  body against live frank-zealot: without `chat_template_kwargs.
+  enable_thinking: false` the reply arrives as 6893 `reasoning_content`
+  characters with `content: ""` in 6.9 s (twice the 6 s abort); with it,
+  369 clean characters in 0.55 s. Driver fixtures now pin the flag
+  (`thinkoff=false` on the recorded chat call), turn reasoning-only replies
+  into mechanical speech instead of silence, and time the menu's test
+  phrase (~0 ms handler). 26 green in `tests/dankvoice.bats`.
 
 ## Limits
 
@@ -232,6 +249,7 @@ the choice persists in the settings file.
 * Gitea issue #21 on `dank/command-center` (the work item this page ships with).
 * Gitea issue #23 on `dank/command-center` (the options-menu work item).
 * Gitea issue #27 on `dank/command-center` (the enhanced-narration work item).
+* Gitea issue #32 on `dank/command-center` (the latency/silence fix work item).
 
 ## See Also
 

omp-docs/log.md

@@ -16,6 +16,19 @@ lesson, a few lines. Full incident narratives are recoverable from git
 (`git log --follow omp-docs/log.md`); knowledge that outlives an entry lives
 on its concept page, linked here. Never re-expand an entry in place.
 
+## 2026-10-19 — dankvoice: silence and timeouts, root-caused (Refs #32)
+
+The humanizer's raw `fetch` to frank-zealot omitted `chat_template_kwargs.
+enable_thinking: false`, so the Qwen35 hybrid *thought* instead of answering:
+6.9 s of `reasoning_content`, `content: ""` — timing out the rewrite twice
+(12 s dead air) and, when it did answer inside the window, speaking silence.
+Root-caused by replaying the exact wire body against the live endpoint.
+Fix: pin the kwarg in the request body; treat empty-content-with-reasoning as
+failure (mechanical voice), not "nothing worth saying"; the menu's test phrase
+fires without blocking its handler. Lesson: the harness injects thinking-off
+for managed roles, but raw HTTP callers must set it themselves — 26/26 green
+with three red-captured regressions.
+
 ## 2026-10-19 — dankvoice: humanized narration and thinking aloud (Refs #27)
 
 Spoken units are rewritten by the `@tiny` role (frank-zealot) under the

tests/dankvoice.bats

@@ -14,8 +14,9 @@
 # (player fixture), DV_PWPLAY (stub aliased as pw-play), DV_WPCTL (the sink
 # name the fixture wpctl reports), DV_MODELS (models.yml fixture),
 # DANKVOICE_CONFIG (settings file), DV_PLAYER_BIN (player command override),
-# DV_SELECT (pipe-separated answers fed to ctx.ui.select in order), DV_MODE
-# (the harness mode reported to the extension).
+# DV_MODE (the harness mode reported to the extension), DV_REWRITE (fixture
+# behavior for the humanizer route: prose | echo | reasoning | stall, with
+# DV_STALL_MS).
 
 setup() {
   REPO="$(cd "$BATS_TEST_DIRNAME/.." && pwd)"
@@ -31,8 +32,10 @@ setup() {
   cat > "$DV_STUB" <<'SH'
 #!/usr/bin/env bash
 printf '%s\n' "$*" >> "$DV_STUB_LOG"
+if [ -n "${DV_TIMING_LOG:-}" ]; then printf 'START %s\n' "$(date +%s%3N)" >> "$DV_TIMING_LOG"; fi
 for arg in "$@"; do case "$arg" in *.wav) cp "$arg" "$DV_COPY" ;; esac; done
-sleep 0.1
+sleep "${DV_HOLD:-0.1}"
+if [ -n "${DV_TIMING_LOG:-}" ]; then printf 'END %s\n' "$(date +%s%3N)" >> "$DV_TIMING_LOG"; fi
 SH
   chmod +x "$DV_STUB"
 
@@ -84,14 +87,21 @@ import { dirname } from "node:path";
 
 const scenario = process.argv[2] ?? "speak";
 const AUDIO = Buffer.from([0x52, 0x49, 0x46, 0x46, 8, 0, 0, 0, 0x57, 0x41, 0x56, 0x45, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12]);
-const received: Array<{ url: string | undefined; body: string }> = [];
+const started = Date.now();
+interface Call {
+  url: string | undefined;
+  body: string;
+  at: number;
+}
+const received: Call[] = [];
 
 const server = createServer((req, res) => {
   const chunks: Buffer[] = [];
   req.on("data", (chunk: Buffer) => chunks.push(chunk));
   req.on("end", () => {
+    const at = Date.now() - started;
     const body = Buffer.concat(chunks).toString("utf8");
-    received.push({ url: req.url, body });
+    received.push({ url: req.url, body, at });
     if (req.url?.endsWith("/audio/voices")) {
       res.setHeader("content-type", "application/json");
       res.end(JSON.stringify(["narrator1", "narrator2"]));
@@ -103,11 +113,18 @@ const server = createServer((req, res) => {
       return;
     }
     if (process.env.DV_REWRITE && req.url?.endsWith("/chat/completions")) {
+      const respond = () => {
         res.setHeader("content-type", "application/json");
         const spoken = process.env.DV_REWRITE === "echo"
           ? String(JSON.parse(body).messages?.[1]?.content ?? "")
           : "Spoken, humanized words.";
-      res.end(JSON.stringify({ choices: [{ message: { content: spoken } }] }));
+        const verdict = process.env.DV_REWRITE === "reasoning"
+          ? { choices: [{ message: { content: "", reasoning_content: "Long internal deliberation that never reaches the reply field." } }] }
+          : { choices: [{ message: { content: spoken } }] };
+        res.end(JSON.stringify(verdict));
+      };
+      if (process.env.DV_REWRITE === "stall") setTimeout(respond, Number(process.env.DV_STALL_MS ?? 200));
+      else respond();
       return;
     }
     res.statusCode = 404;
@@ -219,6 +236,12 @@ if (!say) {
       await say.handler("on", ctx);
       await agentEnd?.({ messages: [{ role: "assistant", content: [{ type: "thinking", thinking: "Considering the wiring." }, { type: "text", text: "The answer is nine." }] }] }, ctx);
       break;
+    case "testphrase": {
+      const startedAt = Date.now();
+      await say.handler("menu", ctx);
+      console.log(`HANDLER_MS ${Date.now() - startedAt}`);
+      break;
+    }
     case "narration":
       await say.handler("on", ctx);
       await agentEnd?.({ messages: [{ role: "assistant", content: [{ type: "thinking", thinking: "Here is the result.", narration: true }] }] }, ctx);
@@ -239,7 +262,11 @@ for (const call of received) {
     }
     return "-";
   };
-  console.log(`CALL ${call.url} model=${field("model")} format=${field("response_format")} voice=${field("voice")} input=${field("input")}`);
+  const kwargs = parsed && typeof parsed === "object" && "chat_template_kwargs" in parsed
+    ? (parsed as { chat_template_kwargs?: { enable_thinking?: unknown } }).chat_template_kwargs
+    : undefined;
+  const think = kwargs && typeof kwargs === "object" && "enable_thinking" in kwargs ? String(kwargs.enable_thinking) : "absent";
+  console.log(`CALL ${call.url} model=${field("model")} format=${field("response_format")} voice=${field("voice")} input=${field("input")}${call.url?.endsWith("/chat/completions") ? ` thinkoff=${think}` : ""}`);
 }
 console.log(`CALLS ${received.filter((call) => call.url?.endsWith("/audio/speech")).length}`);
 const log = process.env.DV_STUB_LOG && existsSync(process.env.DV_STUB_LOG) ? readFileSync(process.env.DV_STUB_LOG, "utf8").trim() : "";
@@ -417,3 +444,29 @@ say_run() {
   DV_PLAYER_BIN="$DV_PWPLAY" say_run speak
   [[ "$output" == *"PLAYER --target $DV_WPCTL"* ]]
 }
+
+@test "the rewrite asks the humanizer with thinking explicitly off" {
+  DV_REWRITE=prose say_run rewrite
+  [[ "$output" == *"input=- thinkoff=false"* ]]
+}
+
+@test "an answer hiding in reasoning_content speaks the mechanical text, not silence" {
+  DV_REWRITE=reasoning say_run rewrite
+  [[ "$output" == *"input=The deploy failed because a secret was missing."* ]]
+  [[ "$output" == *"CALLS 1"* ]]
+  [[ "$output" == *"PLAYS 1"* ]]
+}
+
+@test "a rewrite slower than a breath but under the timeout still speaks" {
+  DV_REWRITE=stall DV_STALL_MS=300 say_run rewrite
+  [[ "$output" == *"input=Spoken, humanized words."* ]]
+  [[ "$output" == *"CALLS 1"* ]]
+}
+
+@test "the menu test phrase speaks in the background instead of blocking the menu" {
+  DV_REWRITE=stall DV_STALL_MS=1500 say_run testphrase "Speak a test phrase"
+  [[ "$output" == *"NOTIFY info dankvoice: speaking the test phrase"* ]]
+  local ms
+  ms=$(grep -o 'HANDLER_MS [0-9]*' <<<"$output" | cut -d' ' -f2)
+  [ -n "$ms" ] && [ "$ms" -lt 1200 ]
+}