diff --git a/README.md b/README.md index 961e775..5e564d6 100644 --- a/README.md +++ b/README.md @@ -54,11 +54,11 @@ Skills compose by adoption-list order (`10123`) and trigger tags carry runtime e Didactyl will support local inference, which is very privacy preserving. Remote inference does however have it's advantages, and in those cases Didactyl supports using Bitcoin Lightning and eCash inference providers. -## Current Status — v0.2.38 +## Current Status — v0.2.39 **Active build — this project is barely working. Experiment at your own risk.** -> Last release update: v0.2.38 — Resolve NIP-17 gift wrap send failure investigation and docs +> Last release update: v0.2.39 — Add 15-minute relay-backed trigger reconciliation in trigger_manager_poll to recover missed self-skill events and re-register missing triggers - Connects to configured relays with auto-reconnect and relay state transition logging - Publishes configured startup events per relay as each relay becomes connected diff --git a/plans/cron_trigger_robustness.md b/plans/cron_trigger_robustness.md new file mode 100644 index 0000000..98a5a03 --- /dev/null +++ b/plans/cron_trigger_robustness.md @@ -0,0 +1,247 @@ +# Cron Trigger Pipeline: How It Works and How to Make It Robust + +## Current Architecture: Skill Events → Trigger Registration + +The pipeline has **two paths** for getting a cron trigger loaded, plus a **polling loop** that actually fires them. + +### Path 1: Bulk load at startup (EOSE-driven) + +```mermaid +sequenceDiagram + participant Main as main.c startup + participant NH as nostr_handler + participant Relays as Nostr Relays + participant TM as trigger_manager + + Main->>TM: trigger_manager_init - capacity=16, last_poll_at=0 + Main->>TM: trigger_manager_load_from_startup_events + Note over TM: Loads triggers from genesis startup_events
only dm triggers typically here + Main->>NH: nostr_handler_set_self_skill_eose_callback
registers on_self_skill_eose_load_triggers + Main->>NH: nostr_handler_subscribe_self_skills + NH->>Relays: REQ kinds 31123, 31124, 10123
authors = agent pubkey + Relays-->>NH: EVENT skill events arrive one by one + NH->>NH: on_self_skill_event for each
caches in g_self_skill_events
calls register_trigger_from_self_skill_event + Relays-->>NH: EOSE + NH->>NH: on_self_skill_eose sets g_self_skill_eose_received=1 + NH->>Main: calls on_self_skill_eose_load_triggers callback + Main->>TM: trigger_manager_load_from_skills
reads ALL cached skills via
nostr_handler_get_self_events_by_kind_json + Note over TM: For each skill with trigger+filter tags:
calls trigger_manager_add + Main->>Main: nostr_handler_wait_for_self_skill_eose returns 0 + Main->>Main: Startup step 14 passes + Main->>Main: Enter main poll loop +``` + +### Path 2: Live skill event (post-startup) + +```mermaid +sequenceDiagram + participant Relays as Nostr Relays + participant NH as nostr_handler + participant TM as trigger_manager + + Note over NH: Subscription stays open after EOSE + Relays-->>NH: New/updated skill EVENT arrives + NH->>NH: on_self_skill_event + NH->>NH: register_trigger_from_self_skill_event + Note over NH: Checks: kind 31123/31124?
Has trigger+filter tags?
Is adopted via kind 10123? + NH->>TM: trigger_manager_add or update + NH->>NH: self_skill_cache_upsert_event_locked +``` + +### Path 3: Cron polling in main loop + +```mermaid +sequenceDiagram + participant Main as main loop + participant TM as trigger_manager + participant Agent as agent.c + + loop Every iteration + Main->>TM: trigger_manager_poll + Note over TM: Throttled to once per 30 seconds + TM->>TM: For each trigger where type==CRON:
1. Validate cron_expr
2. Check cron_matches_now
3. Check last_cron_fire dedup - 50s guard + TM->>Agent: execute_llm_action with synthetic cron event + end +``` + +--- + +## The Six Failure Points + +I have identified six places where a cron trigger can silently fail to load or fire. They are ordered from most likely to least likely given the logs from laantungir.net. + +### 1. EOSE timeout kills startup entirely + +**Where:** [`main.c:1494–1515`](src/main.c:1494) + +The agent waits 15 seconds for self-skill EOSE. If relays are slow or the connection is flaky, this times out and **the entire agent process exits**: + +```c +const int self_skill_eose_timeout_ms = 15000; +if (nostr_handler_wait_for_self_skill_eose(self_skill_eose_timeout_ms) != 0) { + // ... prints error, cleans up, return 1 +} +``` + +From [`debug.log`](debug.log) line 670: +``` +[2026-04-06 16:16:49] [ERROR] startup checklist [14] Subscribe self-skill cache: failed + (self-skill EOSE not received within timeout) +``` + +**Impact:** If the agent crashes at startup, no triggers load at all. If systemd restarts it and it crashes again, you get a restart loop with zero cron execution. + +### 2. Adoption check gates live trigger registration + +**Where:** [`nostr_handler.c:1462`](src/nostr_handler.c:1462) + +When a skill event arrives live via [`on_self_skill_event()`](src/nostr_handler.c:2428), it calls [`register_trigger_from_self_skill_event()`](src/nostr_handler.c:1418) which checks: + +```c +if (!self_skill_is_adopted_local(kind_val, pubkey->valuestring, d_tag)) { + DEBUG_INFO("live self-skill trigger ignored (not adopted) d_tag=%s", d_tag); + return; +} +``` + +[`self_skill_is_adopted_local()`](src/nostr_handler.c:1366) scans `g_self_skill_events` for a kind 10123 event with an `["a", "31123::"]` tag. If the adoption event hasn't arrived yet (race condition — skill event arrives before adoption event), the trigger is silently skipped. + +**Critically:** The bulk load path in [`trigger_manager_load_from_skills()`](src/trigger_manager.c:818) does **NOT** check adoption at all — it loads every skill with trigger+filter tags. So the adoption gate only affects the live path. + +### 3. Bulk load is one-shot with `loaded_once` guard + +**Where:** [`main.c:42`](src/main.c:42) + +```c +if (ctx->loaded_once) { + DEBUG_TRACE("deferred trigger load skipped (already loaded once)"); + return; +} +``` + +The EOSE callback fires once, calls [`trigger_manager_load_from_skills()`](src/trigger_manager.c:818), sets `loaded_once = 1`, and never runs again. If a skill event arrives **after** EOSE but **before** the live path processes it, it falls into a gap: +- The bulk load already ran and won't run again +- The live [`register_trigger_from_self_skill_event()`](src/nostr_handler.c:1418) may reject it due to the adoption check + +### 4. Cron expression validation rejects silently at add time + +**Where:** [`trigger_manager.c:1106–1112`](src/trigger_manager.c:1106) + +```c +if (t->trigger_type == TRIGGER_TYPE_CRON) { + if (!cron_expr_is_valid(filter_json, normalized_cron, sizeof(normalized_cron))) { + DEBUG_WARN("trigger add rejected: invalid cron expression d_tag=%s expr=%s", ...); + memset(t, 0, sizeof(*t)); + return -1; + } +} +``` + +This does log a warning, but the caller in [`trigger_manager_load_from_skills()`](src/trigger_manager.c:896) just silently skips to the next skill. The `considered` count increments but `loaded` does not — the only evidence is in the log line `trigger manager loaded X trigger(s) from self skills (considered=Y)` where X < Y. + +The existing plan in [`fix_cron_triggers_not_firing.md`](plans/fix_cron_triggers_not_firing.md) documents that a bare `*` was being used instead of `* * * * *`, and that shorthand expansion was added. This has been fixed. + +### 5. Poll throttle delays first evaluation by up to 30 seconds + +**Where:** [`trigger_manager.c:1395`](src/trigger_manager.c:1395) + +```c +if (mgr->last_poll_at > 0 && (now - mgr->last_poll_at) < 30) { + return 0; +} +``` + +After init, `last_poll_at` starts at 0 (fixed from the original bug where it was `time(NULL)`), so the first poll runs immediately. But subsequent polls are throttled to every 30 seconds. For a daily cron this is fine, but it means the cron match window is checked at most twice per minute. + +### 6. Cron dedup guard can skip legitimate fires + +**Where:** [`trigger_manager.c:1422`](src/trigger_manager.c:1422) + +```c +if (t->last_cron_fire > 0 && (now - t->last_cron_fire) < 50) { + continue; +} +``` + +With a 30-second poll interval and a 50-second dedup window, a cron that matches at minute X will fire once and then be suppressed for the next poll. This is correct behavior for preventing double-fires within the same minute. But if the system clock jumps or NTP adjusts, this could cause unexpected skips. + +--- + +## Robustness Suggestions + +### A. Retry EOSE with backoff instead of hard abort + +**Current:** EOSE timeout → process exit. +**Proposed:** Retry 2–3 times with increasing timeout (15s, 30s, 60s). If all retries fail, start the agent in degraded mode with only startup-config triggers active, and schedule a background re-attempt. + +```mermaid +flowchart TD + SUB[Subscribe self-skills] --> WAIT{Wait for EOSE} + WAIT -->|Received| LOAD[Load triggers from skills] + WAIT -->|Timeout 15s| RETRY1{Retry 1 - 30s timeout} + RETRY1 -->|Received| LOAD + RETRY1 -->|Timeout| RETRY2{Retry 2 - 60s timeout} + RETRY2 -->|Received| LOAD + RETRY2 -->|Timeout| DEGRADED[Start in degraded mode
startup triggers only
schedule background retry] + LOAD --> READY[Agent READY] + DEGRADED --> READY +``` + +### B. Remove adoption gate from live trigger registration + +The bulk load path doesn't check adoption. The live path does. This inconsistency means a skill created via `skill_create` with `auto_adopt=true` might not register its trigger if the adoption event arrives on a different relay or with different timing. + +**Proposed:** Either: +1. Remove the adoption check from [`register_trigger_from_self_skill_event()`](src/nostr_handler.c:1462) to match the bulk path, OR +2. Add the adoption check to the bulk path too for consistency, but with a fallback: if adoption events haven't loaded yet, defer the check. + +Option 1 is simpler and more robust. The agent already only subscribes to its own pubkey's events, so all skills in the cache are self-authored. + +### C. Allow re-running bulk trigger load + +Remove the `loaded_once` guard or replace it with a debounced re-load. When new skill events arrive after EOSE, schedule a re-scan of all cached skills after a short delay (e.g., 5 seconds). This closes the gap between EOSE and late-arriving events. + +### D. Add a periodic trigger reconciliation + +Every N minutes (e.g., 5), compare the set of cached skills that have trigger+filter tags against the active trigger list. Register any missing triggers. This is a safety net that catches any trigger that was missed during startup. + +```c +// In trigger_manager_poll, after cron evaluation: +if (now - mgr->last_reconcile_at > 300) { + trigger_manager_load_from_skills(mgr); // idempotent via update path + mgr->last_reconcile_at = now; +} +``` + +### E. Log trigger registration summary at startup + +After the deferred trigger load, log not just the count but also which trigger types were loaded: + +``` +trigger manager loaded 3 trigger(s): dm=2 cron=1 webhook=0 chain=0 nostr-sub=0 +``` + +This makes it immediately obvious from the log whether a cron trigger was picked up. + +### F. Add an HTTP API endpoint for trigger status + +Expose `/api/triggers` that returns the same JSON as the `trigger_list` tool. This allows external monitoring (e.g., a health check script) to verify that expected cron triggers are loaded without going through the LLM. + +--- + +## Summary of What Happened on laantungir.net + +Based on the logs: + +1. The agent started successfully multiple times (startup step 14 passed with `skills=3 adoptions=1` or similar). +2. The deferred trigger load status shows **only dm-type triggers** were loaded — no cron triggers appear in any log entry. +3. On 2026-04-06, the agent failed at startup step 14 with EOSE timeout, meaning it never even got to trigger loading. +4. There is **zero** evidence of `cron trigger matched` or `cron trigger skipped` in any log file, confirming the cron trigger was never in the active trigger set. + +The most likely explanation: the cron skill event exists on relays but either: +- It was missing the `["trigger", "cron"]` and/or `["filter", ""]` tags when it was published +- It was not adopted (no kind 10123 event referencing it) and arrived via the live path where adoption is checked +- The cron expression was invalid and was silently rejected at add time +- The EOSE timeout prevented the agent from ever reaching the trigger loading phase + +Running `trigger_list` on the live server will definitively answer which of these is the case. diff --git a/src/main.h b/src/main.h index 0bee011..d2fa8fb 100644 --- a/src/main.h +++ b/src/main.h @@ -12,8 +12,8 @@ // Using DIDACTYL_ prefix to avoid conflicts with nostr_core_lib VERSION macros #define DIDACTYL_VERSION_MAJOR 0 #define DIDACTYL_VERSION_MINOR 2 -#define DIDACTYL_VERSION_PATCH 38 -#define DIDACTYL_VERSION "v0.2.38" +#define DIDACTYL_VERSION_PATCH 39 +#define DIDACTYL_VERSION "v0.2.39" // Agent metadata #define DIDACTYL_NAME "Didactyl" diff --git a/src/nostr_handler.c b/src/nostr_handler.c index 2616481..090b360 100644 --- a/src/nostr_handler.c +++ b/src/nostr_handler.c @@ -2512,7 +2512,7 @@ int nostr_handler_init(didactyl_config_t* config) { nostr_pool_reconnect_config_t reconnect = *nostr_pool_reconnect_config_default(); reconnect.enable_auto_reconnect = 1; reconnect.ping_interval_seconds = 20; - reconnect.pong_timeout_seconds = 10; + reconnect.pong_timeout_seconds = 30; g_pool = nostr_relay_pool_create(&reconnect); if (!g_pool) { diff --git a/src/trigger_manager.c b/src/trigger_manager.c index 2980af6..c3fefe8 100644 --- a/src/trigger_manager.c +++ b/src/trigger_manager.c @@ -589,6 +589,126 @@ static void parse_trigger_runtime_tags(cJSON* tags, } } +static int trigger_manager_reconcile_from_relays(trigger_manager_t* mgr) { + if (!mgr || !mgr->cfg) { + return -1; + } + + cJSON* filter = cJSON_CreateObject(); + cJSON* kinds = cJSON_CreateArray(); + cJSON* authors = cJSON_CreateArray(); + if (!filter || !kinds || !authors) { + cJSON_Delete(filter); + cJSON_Delete(kinds); + cJSON_Delete(authors); + return -1; + } + + cJSON_AddItemToArray(kinds, cJSON_CreateNumber(31123)); + cJSON_AddItemToArray(kinds, cJSON_CreateNumber(31124)); + cJSON_AddItemToObject(filter, "kinds", kinds); + cJSON_AddItemToArray(authors, cJSON_CreateString(mgr->cfg->keys.public_key_hex)); + cJSON_AddItemToObject(filter, "authors", authors); + cJSON_AddNumberToObject(filter, "limit", 300); + + char* events_json = nostr_handler_query_json(filter, 8000); + cJSON_Delete(filter); + if (!events_json) { + DEBUG_WARN("[didactyl] trigger reconcile skipped: relay query returned no data"); + return -1; + } + + cJSON* events = cJSON_Parse(events_json); + free(events_json); + if (!events || !cJSON_IsArray(events)) { + cJSON_Delete(events); + DEBUG_WARN("[didactyl] trigger reconcile skipped: invalid JSON from relay query"); + return -1; + } + + int considered = 0; + int loaded = 0; + + int event_count = cJSON_GetArraySize(events); + for (int i = 0; i < event_count; i++) { + cJSON* skill_event = cJSON_GetArrayItem(events, i); + cJSON* content = skill_event ? cJSON_GetObjectItemCaseSensitive(skill_event, "content") : NULL; + cJSON* tags = skill_event ? cJSON_GetObjectItemCaseSensitive(skill_event, "tags") : NULL; + if (!content || !cJSON_IsString(content) || !content->valuestring || !tags || !cJSON_IsArray(tags)) { + continue; + } + + cJSON* d = find_tag_value_string(tags, "d"); + cJSON* trigger = find_tag_value_string(tags, "trigger"); + cJSON* filter_j = find_tag_value_string(tags, "filter"); + cJSON* action = find_tag_value_string(tags, "action"); + + const char* d_tag = (d && cJSON_IsString(d) && d->valuestring) ? d->valuestring : NULL; + const char* trigger_s = (trigger && cJSON_IsString(trigger) && trigger->valuestring) ? trigger->valuestring : NULL; + const char* filter_s = (filter_j && cJSON_IsString(filter_j) && filter_j->valuestring) ? filter_j->valuestring : NULL; + const char* action_s = (action && cJSON_IsString(action) && action->valuestring) ? action->valuestring : "llm"; + + considered++; + if (!d_tag || d_tag[0] == '\0') { + continue; + } + + int trigger_supported = trigger_s && + (strcmp(trigger_s, "nostr-subscription") == 0 || + strcmp(trigger_s, "webhook") == 0 || + strcmp(trigger_s, "cron") == 0 || + strcmp(trigger_s, "chain") == 0 || + strcmp(trigger_s, "dm") == 0); + if (!trigger_supported || !filter_s || filter_s[0] == '\0') { + continue; + } + + if (strcmp(action_s, "template") == 0) { + DEBUG_WARN("[didactyl] trigger action template is deprecated; forcing llm for d_tag=%s", d_tag); + } + + const char* llm_s = NULL; + const char* tools_s = NULL; + int has_max_tokens = 0; + int max_tokens = 0; + int has_temperature = 0; + double temperature = 0.0; + int has_seed = 0; + int seed = 0; + parse_trigger_runtime_tags(tags, + &llm_s, + &tools_s, + &has_max_tokens, + &max_tokens, + &has_temperature, + &temperature, + &has_seed, + &seed); + + if (trigger_manager_add(mgr, + d_tag, + content->valuestring, + filter_s, + TRIGGER_ACTION_LLM, + trigger_s, + 1, + llm_s, + tools_s, + has_max_tokens, + max_tokens, + has_temperature, + temperature, + has_seed, + seed) == 0) { + loaded++; + } + } + + cJSON_Delete(events); + DEBUG_INFO("[didactyl] trigger reconcile complete: loaded=%d considered=%d", loaded, considered); + return 0; +} + static void apply_trigger_runtime_to_llm_config(const active_trigger_t* t, llm_config_t* cfg) { if (!t || !cfg) return; @@ -810,6 +930,7 @@ int trigger_manager_init(trigger_manager_t* mgr, didactyl_config_t* cfg) { } mgr->last_poll_at = 0; + mgr->last_reconcile_at = 0; DEBUG_INFO("[didactyl] trigger manager initialized (capacity=%d)", mgr->capacity); return 0; @@ -1447,6 +1568,11 @@ int trigger_manager_poll(trigger_manager_t* mgr) { } pthread_mutex_unlock(&mgr->mutex); + if (mgr->last_reconcile_at <= 0 || (now - mgr->last_reconcile_at) >= 900) { + mgr->last_reconcile_at = now; + (void)trigger_manager_reconcile_from_relays(mgr); + } + return fired; } diff --git a/src/trigger_manager.h b/src/trigger_manager.h index 93c9b7e..1a95f08 100644 --- a/src/trigger_manager.h +++ b/src/trigger_manager.h @@ -57,6 +57,7 @@ typedef struct trigger_manager { didactyl_config_t* cfg; pthread_mutex_t mutex; time_t last_poll_at; + time_t last_reconcile_at; } trigger_manager_t; int trigger_manager_init(trigger_manager_t* mgr, didactyl_config_t* cfg);