From aeea7a8fea055b1b79fa99332576c0c22086d0a4 Mon Sep 17 00:00:00 2001 From: Moritz Graf Date: Wed, 7 Oct 2026 09:38:39 +0200 Subject: [PATCH] fix(openclaw): harden session compaction cron against stale token metadata and enable user compaction notices --- k8s/openclaw/TROUBLESHOOTING.md | 52 +++++++++++++++++++++++++++ k8s/openclaw/setup-compaction-cron.sh | 49 +++++++++++++++++++++---- 2 files changed, 94 insertions(+), 7 deletions(-) diff --git a/k8s/openclaw/TROUBLESHOOTING.md b/k8s/openclaw/TROUBLESHOOTING.md index 1286be4..fb4cb7a 100644 --- a/k8s/openclaw/TROUBLESHOOTING.md +++ b/k8s/openclaw/TROUBLESHOOTING.md @@ -27,6 +27,8 @@ This document captures fixed issues, operational quirks, and incident root-cause | **2026-10-05** | **State Deadlock & Session Corruption** | Telegram Topic 117 (`#Recherche`) wedged with `restart recovery claim changed` and `entry_valid = 0` after crash | `RESOLVED` | Repaired `session_nodes` and `session_windows` (restored `entry_valid = 1`, synced `updated_at`, cleared dead claim), purged 20 obsolete cron sessions (>498k tokens), and added `--max-lines 200` compaction fallback. | | **2026-10-06** | **Message Formatting & UX** | Subagents emitted raw HTML/XML comments (``) at the end of Telegram messages | `RESOLVED` | Removed obsolete `DOMAIN_STATE` State Bridge schema from all subagent prompts and Conductor config; replaced with clean Markdown output guardrails. | | **2026-10-06** | **Database Integrity & Reasoning Drop** | Pod stuck in `CrashLoopBackOff` (`quarantined_databases` on IT Guy DB FK check); Kochen topic dropped user message silently without text/tools | `RESOLVED` | Cleared 46 orphaned FK references across child tables, purged quarantine entry, unlocked wedged Topic 164 session, and hardened initContainer and nightly compaction script with automated SQLite self-healing. | +| **2026-10-07** | **Disk I/O & In-Pod Restart Bypass** | Koch agent unresponsive after interrupted turn; container crash loop / freeze on in-pod restart due to bypassed initContainers | `RESOLVED` | Pre-warmed SQLite page cache, unlocked wedged session, recorded nutrition intake directly into DuckDB/Markdown, configured persistent preflight self-healing via `NODE_OPTIONS`, and relaxed probe deadlines. | +| **2026-10-07** | **Compaction Latency & Live Stall** | Telegram `#Sport` (Topic 20) appeared unresponsive for >3 minutes after Moritz's message | `RESOLVED` | Identified 54s inline safeguard compaction + 35s prompt prep + 85s tool execution (181s total) caused by stale token metadata (`totalTokens: null`) slipping past nightly cron. Hardened `compact_sessions.py` with SQLite transcript inspection, lowered compaction threshold to 20k / 300KB, enabled `agents.defaults.compaction.notifyUser: true` for visible compaction notices on Telegram, and proactively compacted bloated sessions. | --- @@ -577,3 +579,53 @@ This document captures fixed issues, operational quirks, and incident root-cause - Set probe failure thresholds and timeouts with high tolerance on rotational HDD nodes. - Maintain page cache pre-warming for SQLite databases to convert slow random seek I/O into fast sequential streaming. +--- + +### Issue 19: Telegram Topic Latency & Inline Compaction Delays (Topic #Sport / Topic 20) + +- **Date**: 2026-10-07 +- **Severity**: Medium (User-facing perceived stall of 3m03s in Telegram topic `#Sport`) +- **Symptom**: + Moritz sent a message in Telegram Topic 20 (`#Sport`) asking to adapt an existing Sprint Interval Training (SIT) workout: + *„Hier ein Training dass wir vor einiger Zeit erstellt haben ich würde gerne die Intervalle etwas anpassen...“* + The bot appeared completely unresponsive, leading Moritz to report that the bot was again not answering. +- **Root Cause Analysis & Turn Breakdown**: + 1. **The Bot Was NOT Dead, But Executing with 181.8s Latency**: + - Message received at **07:15:11 UTC** (`messageId=2195`). + - Response delivered at **07:18:14 UTC** (`messageId=2197`, threadId=20) with the complete adapted Zwift `.zwo` workout file and direct download link. + - Total turn time: **181.8 seconds (3 minutes 3 seconds)** without any typing indicator or intermediate update. + 2. **Latency Component 1: Inline Safeguard Compaction (54s)**: + - The active session had accumulated 53,519 tokens (and >1.5 MB in `transcript_events`). + - Because this exceeded OpenClaw's internal `maxActiveTranscriptBytes: 400kb` limit, OpenClaw paused the turn from 07:15:17 to 07:16:12 (`durationMs=54168`) to run an inline LLM compaction via `openrouter/z-ai/glm-5.3-flash`, reducing the prompt window from 161 messages to 12. + - Because `agents.defaults.compaction.notifyUser` was `false`, Telegram showed zero typing activity or indication that compaction was underway. + 3. **Latency Component 2: System Prompt & Workspace Compilation (35s)**: + - Following a pod restart 40 minutes prior, the Linux page cache for the mechanical HDD was cold. Compiling the 56,912-character system prompt, bootstrap notes (`DREAMS.md`, `MEMORY.md`), and scanning tool search directories took 34.7s (07:16:13 to 07:16:48). + 4. **Latency Component 3: Multi-Step Tool Execution (85s)**: + - The Fitness agent executed 4 sequential tool turns: + 1. `write`: Wrote the updated Zwift XML file. + 2. `exec`: Located `publish_file.py` in mop-skills. + 3. `exec`: Hosted the workout on `hosting.haumdaucher.de`. + 4. `exec`: Corrected the URL slug to remove duplicate date and re-hosted. + - Each step involved sequential OpenRouter network round-trips to `z-ai/glm-5.3-flash`. + 5. **Why Nightly Compaction (03:30 CEST) Missed Topic 20**: + - `compact_sessions.py` retrieved session lists via `openclaw sessions --all-agents --json`. + - In OpenClaw, for sessions that have been inactive for several days (Topic 20 was last messaged on Sep 27), `totalTokens` is returned as `null` (`totalTokensFresh: false`). + - `compact_sessions.py` checked `tokens = s.get("totalTokens") or 0`. For inactive sessions, this evaluated to `0`, causing the cron to skip compaction (`skipped += 1`). + - Consequently, bloated transcripts sat uncompacted in SQLite until a user sent a message, triggering an unexpected 1-minute inline compaction delay during live chat. +- **Resolution**: + 1. **Direct SQLite Transcript Inspection in `compact_sessions.py`**: + - Enhanced `compact_sessions.py` with `get_session_metrics(agent, key, sid)` which queries `transcript_events` directly from each agent's SQLite database (`openclaw-agent.sqlite`). + - Compaction now triggers whenever `tokens >= 20000`, OR `transcript_bytes >= 300000`, OR `(tokens == 0 and ev_cnt >= 40)`. Stale sessions with `totalTokens: null` are guaranteed to be compacted overnight. + 2. **Compaction RPC Timeout & Fallback Tuning**: + - Increased gateway RPC timeout from 120s to 180s (`RPC_TIMEOUT_MS = 180000`) to prevent premature gateway timeouts on large transcripts. + - Changed the truncation fallback from `--max-lines 200` to `--max-lines 80`, ensuring that even fallback compactions effectively reduce the transcript. + - Handled `"Already compacted"` responses gracefully to prevent redundant retries. + 3. **Compaction User Notification Enabled**: + - Configured `agents.defaults.compaction.notifyUser: true` in `openclaw.json`. If inline compaction ever triggers during a live turn, OpenClaw now sends a status notice (`🧹 Compacting context...`) so the user is immediately aware of background maintenance rather than suspecting a crash. + 4. **Proactive Manual Compaction**: + - Ran the updated compaction workflow across all agent databases, reducing bloated sessions (Main: 49.7k → 3.2k, Koch: 47k → 4.5k, Hebamme: 43k → 8.4k, Fitness: 12.5k → 7.5k). +- **How to Avoid Recurrence**: + - Never rely solely on high-level CLI summary caches (`totalTokens`) for health/maintenance triggers when underlying datastores contain ground-truth metrics. + - Keep `notifyUser: true` enabled for long-running inline agent maintenance. + - Retain SQLite page cache pre-warming to minimize startup latency on spinning disk infrastructure. + diff --git a/k8s/openclaw/setup-compaction-cron.sh b/k8s/openclaw/setup-compaction-cron.sh index d81ad2b..0ccb056 100755 --- a/k8s/openclaw/setup-compaction-cron.sh +++ b/k8s/openclaw/setup-compaction-cron.sh @@ -36,9 +36,11 @@ import subprocess import sys import time -THRESHOLD_TOKENS = 25000 +THRESHOLD_TOKENS = 20000 +THRESHOLD_TRANSCRIPT_BYTES = 300000 +THRESHOLD_EVENT_COUNT = 40 CRON_MAX_AGE_HOURS = 48 -RPC_TIMEOUT_MS = 120000 +RPC_TIMEOUT_MS = 180000 def prewarm_page_cache(): print("=== Pre-warming SQLite databases into OS page cache ===") @@ -126,8 +128,30 @@ def prune_stale_cron_sessions(): print(f"Cron pruning complete: {total_pruned} sessions pruned, {total_tokens_reclaimed} tokens reclaimed.") +def get_session_metrics(agent, key, sid=None): + db_path = f"/home/node/.openclaw/agents/{agent}/agent/openclaw-agent.sqlite" + if not os.path.exists(db_path): + return 0, 0 + try: + con = sqlite3.connect(db_path, timeout=5.0) + cur = con.cursor() + if not sid: + row = cur.execute("SELECT current_session_id FROM session_nodes WHERE session_key=?", (key,)).fetchone() + sid = row[0] if row else None + if not sid: + con.close() + return 0, 0 + ev_cnt, ev_bytes = cur.execute( + "SELECT count(*), coalesce(sum(length(event_json)), 0) FROM transcript_events WHERE session_id=?", + (sid,) + ).fetchone() + con.close() + return ev_cnt, ev_bytes + except Exception: + return 0, 0 + def compact_active_sessions(): - print(f"=== Running OpenClaw Multi-Agent Compaction (threshold: {THRESHOLD_TOKENS} tokens, LLM summarization) ===") + print(f"=== Running OpenClaw Multi-Agent Compaction (threshold: {THRESHOLD_TOKENS} tokens / {THRESHOLD_TRANSCRIPT_BYTES//1024}KB, LLM summarization) ===") res = subprocess.run(["openclaw", "sessions", "--all-agents", "--json"], capture_output=True, text=True) if res.returncode != 0: print(f"Failed to list sessions: {res.stderr}") @@ -141,6 +165,7 @@ def compact_active_sessions(): key = s.get("key", "") agent = s.get("agentId") or "main" tokens = s.get("totalTokens") or 0 + sid = s.get("sessionId") # Target main sessions and all telegram sessions (topics and direct) is_target = ( @@ -149,8 +174,15 @@ def compact_active_sessions(): (key.startswith("agent:") and key.endswith(":main")) ) if is_target and not key.endswith(":heartbeat"): - if tokens >= THRESHOLD_TOKENS: - print(f"Compacting {agent} ({tokens} tokens) -> {key}...") + ev_cnt, ev_bytes = get_session_metrics(agent, key, sid) + needs_compaction = ( + tokens >= THRESHOLD_TOKENS or + ev_bytes >= THRESHOLD_TRANSCRIPT_BYTES or + (tokens == 0 and ev_cnt >= THRESHOLD_EVENT_COUNT) + ) + if needs_compaction: + stat_str = f"{tokens} tokens" if tokens else f"{ev_bytes//1024}KB / {ev_cnt} events" + print(f"Compacting {agent} ({stat_str}) -> {key}...") c_res = subprocess.run( ["openclaw", "sessions", "compact", key, "--agent", agent, "--timeout", str(RPC_TIMEOUT_MS)], capture_output=True, text=True @@ -158,10 +190,13 @@ def compact_active_sessions(): if c_res.returncode == 0: print(f" ✓ {c_res.stdout.strip()}") compacted += 1 + elif "Already compacted" in c_res.stderr or "Already compacted" in c_res.stdout: + print(f" ✓ Already compacted.") + skipped += 1 else: - print(f" ✗ {c_res.stderr.strip()}; retrying with --max-lines 200 fallback...") + print(f" ✗ {c_res.stderr.strip()}; retrying with --max-lines 80 fallback...") fb_res = subprocess.run( - ["openclaw", "sessions", "compact", key, "--agent", agent, "--max-lines", "200", "--timeout", str(RPC_TIMEOUT_MS)], + ["openclaw", "sessions", "compact", key, "--agent", agent, "--max-lines", "80", "--timeout", str(RPC_TIMEOUT_MS)], capture_output=True, text=True ) if fb_res.returncode == 0: