190 lines
11 KiB
Markdown
190 lines
11 KiB
Markdown
# FIXED: DM Delivery Failure During Cron-Triggered Skills
|
||
|
||
> **Status: ✅ Fixed and deployed in v0.2.72 (2026-08-25/26)**
|
||
>
|
||
> Five fixes applied:
|
||
> 1. [`src/agent.c`](src/agent.c) — `nostr_handler_poll(0)` calls in the `agent_on_trigger()` turn loop and tool-execution loop keep websockets serviced during long-running triggered skills
|
||
> 2. [`src/nostr_handler.c`](src/nostr_handler.c) — self-healing retry in `nostr_handler_send_dm_with_role()`: if a publish is accepted by 0 relays, service the pool for 500ms and retry once
|
||
> 3. [`src/trigger_manager.c`](src/trigger_manager.c) — periodic trigger reconciliation (every 60s) from the local self-skill cache, closing the EOSE/adoption-gate race that prevented triggers from loading after restart
|
||
> 4. [`src/agent.c`](src/agent.c) + [`src/main.c`](src/main.c) + [`src/main.h`](src/main.h) — `systemd_notify_send("WATCHDOG=1")` pings inside the trigger execution loop. The service unit has `WatchdogSec=120` with `Type=notify`; the main loop's 10s ping cadence is suspended during blocking trigger executions, so systemd was killing the service mid-investigation (observed at 18:35:14). Pings now fire per-turn and per-tool-call.
|
||
> 5. [`nostr_core_lib/nostr_core/core_relay_pool.c`](nostr_core_lib/nostr_core/core_relay_pool.c) — dead-transport detection in `check_connection_health()`. When `nostr_ws_ping()` fails to send (remote closed the TCP connection), the ws client's cached state still claims CONNECTED (it only transitions on a clean WebSocket CLOSE frame), so the pool never marked the relay disconnected and never reconnected — the agent sat with zero TCP sockets for 13+ hours while reporting 3/3 connected (observed 2026-08-26: DMs silently ignored from 00:08 onward). The fix closes the stale client (`ws_client = NULL`) and marks the relay DISCONNECTED on ping-send failure or pong timeout, letting the reconnect logic perform a fresh connect.
|
||
>
|
||
> Verification (2026-08-25 21:51 UTC): webhook test fired → investigation ran ~2 minutes (past the old 120s kill window) → service stayed up (no restart) → investigation DM delivered `via 3 connected relay(s)`. All 3 triggers (dm, cron, webhook) register automatically after restart via reconciliation. The skills also needed to be adopted via `skill_adopt` — the original `skill_create` with `auto_adopt: true` had failed to publish the adoption event because publishing was broken at creation time.
|
||
>
|
||
> Post-fix-5 verification (2026-08-26 13:41 UTC): service restarted with the lib fix, 3/3 relays connected, 4 live TCP sockets confirmed via `ss`. The midnight health report and a real watchdog alert (load 3.69 at 04:01) both fired correctly on 2026-08-26 — the monitoring features work; the dead-socket bug was silently swallowing all inbound DMs.
|
||
|
||
## Symptom
|
||
|
||
The `server-health-report` cron skill fires correctly (confirmed at 00:00 and 12:00 UTC), gathers all metrics, and the LLM generates the report — but the DM never reaches the admin. The log shows a contradictory pair:
|
||
|
||
```
|
||
[12:01:22] kind 4 event published to wss://relay.damus.io (async) ← targeted
|
||
[12:01:22] kind 4 event published to wss://relay.primal.net (async)
|
||
[12:01:22] kind 4 event published to wss://relay.laantungir.net (async)
|
||
[12:01:22] sent DM 2af454bd2034a08f... to 1ec454734dcbf6fe... via 0 connected relay(s) ← actually sent to ZERO
|
||
```
|
||
|
||
Meanwhile the webhook test DM (22 hours earlier) succeeded: `via 3 connected relay(s)`.
|
||
|
||
## Root Cause Analysis
|
||
|
||
### The single-threaded main loop blocks websocket servicing
|
||
|
||
The main loop in [`main.c:2480`](src/main.c:2480) is single-threaded:
|
||
|
||
```c
|
||
while (g_running) {
|
||
(void)nostr_handler_poll(100); // services websockets
|
||
(void)trigger_manager_poll(&trigger_manager); // BLOCKS during trigger execution
|
||
if (http_api_started) {
|
||
(void)http_api_poll(0);
|
||
}
|
||
...
|
||
}
|
||
```
|
||
|
||
When a cron trigger fires, the call chain is:
|
||
|
||
```
|
||
trigger_manager_poll() [trigger_manager.c:1681]
|
||
→ execute_llm_action() [trigger_manager.c:903]
|
||
→ agent_on_trigger() [agent.c:1769]
|
||
→ multi-turn LLM loop (BLOCKING)
|
||
- 8 × local_shell_exec (up to 30s each)
|
||
- 3-4 × LLM HTTP round trips
|
||
→ nostr_dm_send tool call
|
||
```
|
||
|
||
The health report execution takes **50–72 seconds**. During this entire window, `nostr_handler_poll()` is never called — the websocket connections receive zero servicing.
|
||
|
||
### Two connection checks disagree
|
||
|
||
| Check | Location | Basis | Result during cron fire |
|
||
|-------|----------|-------|------------------------|
|
||
| `nostr_relay_pool_get_relay_status()` | [`nostr_handler.c:3304`](src/nostr_handler.c:3304) | `relay->status` — only updated during poll | **CONNECTED** (stale) |
|
||
| `nostr_ws_get_state()` | [`core_relay_pool.c:1714`](nostr_core_lib/nostr_core/core_relay_pool.c:1714) | live ws client state | **NOT CONNECTED** |
|
||
|
||
In [`nostr_handler_send_dm_with_role()`](src/nostr_handler.c:3225):
|
||
|
||
1. The relay-selection loop uses the **stale** `relay->status` → builds `connected_relays[]` with 3 entries → prints "kind 4 event published to ..." for each
|
||
2. [`nostr_relay_pool_publish_async()`](nostr_core_lib/nostr_core/core_relay_pool.c:1673) internally re-checks with the **live** `nostr_ws_get_state()` → all relays fail the check → every send is skipped → returns 0
|
||
3. The final log line prints the actual result: `via 0 connected relay(s)`
|
||
|
||
### Why the webhook test succeeded
|
||
|
||
The webhook test completed in ~23 seconds — under the ~30s threshold where the unserviced websockets degrade (relay-side ping timeouts, TCP buffer stalls). The cron health report takes 50–72 seconds, well past it.
|
||
|
||
### nostr_core_lib version check
|
||
|
||
The vendored lib is **v0.6.15** ([`nostr_core.h:5`](nostr_core_lib/nostr_core/nostr_core.h:5)), which is the latest per [`update_nostr_core_lib_nsigner.md`](plans/update_nostr_core_lib_nsigner.md). The lib's behavior is correct — it refuses to send on connections whose live state isn't CONNECTED. The bug is in didactyl's usage pattern: blocking the poll loop for a minute.
|
||
|
||
---
|
||
|
||
## Debugging Steps (in priority order)
|
||
|
||
### Step 1: Confirm the timing hypothesis — zero risk, 5 minutes
|
||
|
||
Create a minimal cron skill that fires every 5 minutes with ONE fast command and an immediate DM:
|
||
|
||
```json
|
||
{
|
||
"d": "dm-timing-test",
|
||
"trigger": "cron",
|
||
"filter": "*/5 * * * *",
|
||
"content": "Run `uptime` with local_shell_exec, then immediately DM the admin with the result using nostr_dm_send. Do nothing else."
|
||
}
|
||
```
|
||
|
||
- If the short skill's DM **arrives** → timing/blocking confirmed
|
||
- If it **also fails** → hypothesis wrong, go to Step 2 instrumentation
|
||
- Remove the test skill afterward (`skill_remove`)
|
||
|
||
### Step 2: Instrument the send path — confirms the state disagreement
|
||
|
||
Add temporary logging in [`nostr_handler_send_dm_with_role()`](src/nostr_handler.c:3225) before the publish:
|
||
|
||
```c
|
||
for (int i = 0; i < g_cfg->relay_count; i++) {
|
||
DEBUG_INFO("[didactyl] DM pre-check: relay=%s pool_status=%d",
|
||
g_cfg->relays[i],
|
||
nostr_relay_pool_get_relay_status(g_pool, g_cfg->relays[i]));
|
||
}
|
||
```
|
||
|
||
And in [`nostr_relay_pool_publish_async()`](nostr_core_lib/nostr_core/core_relay_pool.c:1673), log per-relay ws state and send result:
|
||
|
||
```c
|
||
DEBUG_INFO("[pool] publish_async relay=%s ws_state=%d",
|
||
relay_urls[i],
|
||
relay && relay->ws_client ? nostr_ws_get_state(relay->ws_client) : -1);
|
||
```
|
||
|
||
Expected output during a cron fire: `pool_status=2 (CONNECTED)` but `ws_state != CONNECTED` for all relays — proving the stale-vs-live disagreement.
|
||
|
||
### Step 3: The fix — poll websockets during trigger execution
|
||
|
||
Add non-blocking polls inside the [`agent_on_trigger()`](src/agent.c:1769) execution loop:
|
||
|
||
```c
|
||
// In agent_on_trigger(), at the top of the per-turn loop (before llm_chat_with_tools_messages):
|
||
(void)nostr_handler_poll(0); // non-blocking: service websocket I/O
|
||
|
||
// Also inside the tool-execution loop (after each tools_execute call),
|
||
// since local_shell_exec can block up to 30 seconds per call:
|
||
(void)nostr_handler_poll(0);
|
||
```
|
||
|
||
This keeps the websocket state fresh and the connections alive throughout long-running triggered skills. It also benefits DM-triggered conversations that run long tool loops.
|
||
|
||
**Files to change:**
|
||
- [`src/agent.c`](src/agent.c) — add poll calls in `agent_on_trigger()` (and consider the same for the DM conversation path in `agent_on_message()` if it has the same pattern)
|
||
|
||
### Step 4: Rebuild, redeploy, verify
|
||
|
||
```bash
|
||
./build_static.sh
|
||
./deploy_lt.sh
|
||
```
|
||
|
||
Then watch the next 12:00 UTC fire (or use the Step 1 test skill for faster iteration):
|
||
|
||
```bash
|
||
ssh ubuntu@laantungir.net "grep -E 'sent DM.*via' /home/simon/debug.log | tail -5"
|
||
```
|
||
|
||
Success criterion: `via 3 connected relay(s)` and the admin receives the report DM.
|
||
|
||
### Step 5 (optional hardening): surface send failures to the LLM
|
||
|
||
Currently `nostr_dm_send` returns `success: false` when `sent == 0`, but the LLM may not retry. Two options:
|
||
|
||
1. **Retry in the tool**: in [`nostr_handler_send_dm_with_role()`](src/nostr_handler.c:3225), if `sent == 0`, call `nostr_handler_poll(100)` a few times and retry the publish once — self-healing without LLM involvement
|
||
2. **Retry via LLM**: make the tool result error message explicit (`"DM not delivered: 0 relays accepted. Retry after servicing connections."`) so the LLM retries on the next turn
|
||
|
||
Option 1 is more robust; option 2 is simpler.
|
||
|
||
### Step 6 (optional): check upstream nostr_core_lib
|
||
|
||
The vendored v0.6.15 is current, but worth a quick check of the upstream repo for any post-0.6.15 changes to `core_relay_pool.c` — particularly whether `nostr_ws_get_state()` semantics changed or whether a queued-publish mechanism (send after reconnect) was added. If upstream added a publish queue, updating the vendored lib could make sends self-healing.
|
||
|
||
---
|
||
|
||
## Workarounds (if a code fix must wait)
|
||
|
||
1. **Split the skill into a chain**: `server-health-report` (gather metrics, write to file) → `chain` trigger → `server-health-report-send` (read file, DM admin). Each skill stays under ~30s, keeping websocket degradation below threshold. Fragile — depends on the exact timeout window.
|
||
2. **DM first, investigate later**: restructure the skill to send a brief DM immediately (before the long shell commands), then send findings. Only helps if the first DM goes out within ~30s of trigger fire.
|
||
|
||
Both are stopgaps — the real fix is Step 3.
|
||
|
||
---
|
||
|
||
## Verification Checklist
|
||
|
||
- [ ] Step 1 test skill DM arrives (timing hypothesis confirmed)
|
||
- [ ] Step 2 instrumentation shows pool_status=CONNECTED but ws_state≠CONNECTED during cron fire
|
||
- [ ] Step 3 fix applied: `nostr_handler_poll(0)` calls in `agent_on_trigger()` loops
|
||
- [ ] Rebuilt and deployed via `./build_static.sh` + `./deploy_lt.sh`
|
||
- [ ] Next cron fire logs `via 3 connected relay(s)`
|
||
- [ ] Admin receives the health report DM at 00:00/12:00 UTC
|
||
- [ ] Webhook alert path still works (regression check)
|