From 45d8f32dd1c7853580757bc0f5f1388b68f5f20a Mon Sep 17 00:00:00 2001 From: Didactyl User Date: Sat, 13 Jun 2026 07:35:10 -0400 Subject: [PATCH] v0.2.50 - Fix startup step-14 false-negative by adding sync self-skill retry validation and post-auth query REQ resend --- README.md | 4 +- plans/fix_self_skill_eose_race.md | 148 ++++++++++++++++++++++++++++++ src/main.c | 125 +++++++++++++++++-------- src/main.h | 4 +- 4 files changed, 240 insertions(+), 41 deletions(-) create mode 100644 plans/fix_self_skill_eose_race.md diff --git a/README.md b/README.md index a04baca..dba501f 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.49 +## Current Status — v0.2.50 **Active build — this project is barely working. Experiment at your own risk.** -> Last release update: v0.2.49 — Add startup-failure DM de-dup with marker, relay-state/needed-event diagnostics, and clear-on-READY rearm +> Last release update: v0.2.50 — Fix startup step-14 false-negative by adding sync self-skill retry validation and post-auth query REQ resend - 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/fix_self_skill_eose_race.md b/plans/fix_self_skill_eose_race.md new file mode 100644 index 0000000..fc2d58a --- /dev/null +++ b/plans/fix_self_skill_eose_race.md @@ -0,0 +1,148 @@ +# Fix: Self-Skill Startup Race (step 14 false-negative) + +## Symptom + +`didactyl.service` / `simon.service` intermittently fail startup at step 14: + +``` +startup checklist [14] Subscribe self-skill cache: failed (no skill events found after EOSE) +``` + +…even though the required events (kind 31123/31124 skills and kind 10123 adoption list) +demonstrably exist on `relay.laantungir.net` (verified with `nak`, returned in well under +a second). On other restarts the identical setup succeeds: `ok (skills=3 adoptions=1)`. +The failure is timing-dependent. + +## How startup relay polling works (mechanics) + +- Each startup step opens its **own** subscription (its own `REQ` + filter). Step 14's + filter is built in [`nostr_handler_subscribe_self_skills()`](src/nostr_handler.c:2800): + `{"kinds":[31123,31124,10123],"authors":[],"limit":300}`. +- That subscription is sent to **all** configured relays in parallel inside + [`nostr_relay_pool_subscribe()`](nostr_core_lib/nostr_core/core_relay_pool.c:967). +- This is the **async/streaming** path: events arrive over time via + [`on_self_skill_event()`](src/nostr_handler.c:2478) which upserts into the shared cache + `g_self_skill_events`, and an EOSE-complete callback + ([`on_self_skill_eose`](src/nostr_handler.c:2066)) flips `g_self_skill_eose_received`. +- Step 14 then immediately runs + [`nostr_handler_validate_self_skill_cache()`](src/nostr_handler.c:3089) against whatever + is in the cache at that instant. + +## Root cause + +The async EOSE-complete signal is decoupled from "did the relay that actually has the +events get queried and deliver yet." Two independent contributing factors: + +1. **Relay connection timing.** The self-skill subscription is registered shortly after + startup. If `relay.laantungir.net` is not yet fully connected when the subscription's + completion is computed, the empty relays (`damus`, `primal`) EOSE almost instantly and + the per-relay **timeout fallback** + ([`core_relay_pool.c:2128`](nostr_core_lib/nostr_core/core_relay_pool.c:2128)) marks the + remaining relay "done" after `relay_timeout_seconds` (=12) without ever receiving its + events. EOSE-complete fires with an empty cache → validation fails. +2. **Validation fires the instant completion is signaled**, with no re-check, so any race + where laantungir's events land microseconds later is lost. + +This matches the `<1s` `nak` observation: when laantungir is connected and queried, it +answers almost instantly; the failures are the cycles where it wasn't +connected/queried/processed before the async completion fired. + +### Why FIRST → FULL_SET alone does NOT fix it + +`maybe_complete_subscription_eose()` waits for **all** relays in both modes; the only +difference is the payload passed to the callback. The cache is filled by the EVENT +callback, not the EOSE payload. Changing the mode changes neither connection timing nor +when events are available. + +## Fix: use the synchronous query for the startup self-skill load + +There is already a correct, synchronous "collect all events until EOSE/timeout, then +return them" primitive used elsewhere at startup (e.g. kind-10002 discovery): + +- [`nostr_handler_query_json()`](src/nostr_handler.c:3395) → + [`nostr_relay_pool_query_sync()`](nostr_core_lib/nostr_core/core_relay_pool.c:1340). +- A self-skill-specific wrapper already exists and reuses it: + [`nostr_handler_refresh_self_skill_cache_from_relays()`](src/nostr_handler.c:3751), + which queries kinds 31123/31124/10123 for the agent author (and also pulls adopted + skills), populating the cache synchronously. + +The synchronous query is the architecturally correct tool for "give me the complete +current set before proceeding," which is exactly what step 14 needs. It also drives the +poll/receive loop itself +([`core_relay_pool.c:1405`](nostr_core_lib/nostr_core/core_relay_pool.c:1405)) until all +connected relays EOSE or the timeout elapses. + +### Important caveat to handle: connection readiness + +`nostr_relay_pool_query_sync()` only queries relays that are **connected at call time** +(`if (connected_count == 0) return NULL;` at +[`core_relay_pool.c:1392`](nostr_core_lib/nostr_core/core_relay_pool.c:1392)). If +`relay.laantungir.net` is still mid-connect when step 14 runs, a sync query could still +miss it. Therefore the fix must ensure the relay holding the events is connected (or wait +briefly for it) before/within the query. + +### Plan + +1. **Replace the step-14 async wait+validate with a synchronous load.** In + [`src/main.c`](src/main.c) step 14 (~line 1518), instead of relying solely on + `nostr_handler_wait_for_self_skill_eose()` + an immediate + `nostr_handler_validate_self_skill_cache()`: + - Keep registering the live subscription (so ongoing skill updates still stream in via + `on_self_skill_event`) — this is still wanted for runtime. + - For the startup *gate*, call + [`nostr_handler_refresh_self_skill_cache_from_relays(timeout_ms)`](src/nostr_handler.c:3751) + with a sensible timeout (e.g. 8000–10000 ms). This performs the synchronous, + connection-aware query and fills `g_self_skill_events`. + - Then run `nostr_handler_validate_self_skill_cache(&skills, &adoptions)`. + +2. **Wait for the self relay (laantungir) to be connected before the sync query.** Reuse + the existing relay-readiness helper pattern (`wait_for_connected_relays`) — but ensure + we wait specifically until the relay list discovered from kind 10002 (which includes + `relay.laantungir.net`) is connected, not just "any relay." If we already have a + connected-count wait, extend/bound it so the relay that owns the events has a fair + chance to connect before the sync query runs. + +3. **Bounded retry around the sync query.** If the first sync query returns an empty cache, + retry the sync query a small, bounded number of times (e.g. up to ~5–8s total), + pumping `nostr_handler_poll()` between attempts to let connections settle. Only fail + step 14 after the bounded retries still yield an empty cache. This converts a transient + connection-timing miss into a brief wait instead of a hard failure. + +4. **Keep the async subscription for runtime updates.** Do not remove the live + subscription; it's still responsible for picking up skill changes after startup. Only + the *startup gate* switches to the synchronous load for determinism. + +### Why this is the right layer + +- It uses the library's intended synchronous collect-all primitive rather than racing a + streaming subscription against an immediate validation. +- It is connection-aware and bounded, so a slow/late relay connect becomes a short wait, + not a false "no skill events" failure. +- It does not require modifying `nostr_core_lib` (though if desired, a follow-up could add + a `query_sync` variant that waits for a named relay to connect; not required here). + +## Interaction with the failure-DM throttle (already shipped) + +- On success, the READY path clears the throttle marker + ([`src/main.c`](src/main.c) `startup_failure_marker_clear`). No change needed. +- After this fix, step-14 failures should be genuinely rare (real outage / events truly + absent), and the (single, throttled) failure DM will carry relay states + needed event + kinds for accurate diagnosis. + +## Verification + +1. Build (`make`) clean, then `build_static.sh`. +2. Deploy to VM410; restart both services many times in a row and confirm step 14 reaches + `ok (skills=N adoptions=M)` **consistently** (no intermittent false negatives). +3. Inspect logs to confirm the synchronous query path is used and that, on a cold cycle, + it waits for `relay.laantungir.net` to connect and then returns the events. +4. Negative test: configure only empty relays (no skill events anywhere) and confirm step + 14 still fails after the bounded retries (no false positive), sending exactly one + throttled failure DM. +5. Confirm a normal successful startup still sends the startup DM and clears the marker. + +## Out of scope (possible follow-ups) + +- Adding a `nostr_core_lib` `query_sync` variant that explicitly waits for specific + relays to connect before issuing the REQ. +- Softening step 14 into a degraded-start mode. diff --git a/src/main.c b/src/main.c index 75b7f87..cdedb7a 100644 --- a/src/main.c +++ b/src/main.c @@ -1683,50 +1683,101 @@ int main(int argc, char** argv) { return 1; } - const int self_skill_eose_timeout_ms = 15000; - if (nostr_handler_wait_for_self_skill_eose(self_skill_eose_timeout_ms) != 0) { - startup_step_fail(14, - "Subscribe self-skill cache", - "self-skill EOSE not received within timeout"); - notify_admin_startup_failure(&cfg, - 14, - "Subscribe self-skill cache", - "self-skill EOSE not received within timeout"); - fprintf(stderr, - "Startup aborted: self-skill EOSE not received within %d ms\n", - self_skill_eose_timeout_ms); - fprintf(stderr, - "Check relay connectivity (connected=%d/%d) and ensure skill events exist on relays\n", - nostr_handler_connected_relay_count(), - cfg.relay_count); - fprintf(stderr, - "If this is a first run, use genesis to publish startup events\n"); - agent_cleanup(); - nostr_block_list_cleanup(); - trigger_manager_cleanup(&trigger_manager); - nostr_handler_cleanup(); - llm_cleanup(); - config_free(&cfg); - nostr_cleanup(); - return 1; - } - + const int self_skill_sync_attempt_timeout_ms = 4000; + const int self_skill_sync_total_budget_ms = 15000; + const int self_skill_retry_step_ms = 250; + int self_skill_waited_ms = 0; + int self_skill_refresh_attempts = 0; + int self_skill_refresh_rc = -1; + int self_skill_validate_rc = -1; int startup_skill_count = 0; int startup_adoption_count = 0; - if (nostr_handler_validate_self_skill_cache(&startup_skill_count, &startup_adoption_count) != 0) { + + while (self_skill_waited_ms <= self_skill_sync_total_budget_ms) { + int connected_relays = nostr_handler_connected_relay_count(); + if (connected_relays > 0) { + self_skill_refresh_attempts++; + self_skill_refresh_rc = + nostr_handler_refresh_self_skill_cache_from_relays(self_skill_sync_attempt_timeout_ms); + + if (self_skill_refresh_rc == 0) { + self_skill_validate_rc = + nostr_handler_validate_self_skill_cache(&startup_skill_count, &startup_adoption_count); + if (self_skill_validate_rc == 0) { + DEBUG_INFO("[didactyl] startup phase: self-skill sync+validate succeeded (attempt=%d connected=%d/%d skills=%d adoptions=%d)", + self_skill_refresh_attempts, + connected_relays, + cfg.relay_count, + startup_skill_count, + startup_adoption_count); + break; + } + + DEBUG_WARN("[didactyl] startup phase: self-skill sync returned no skill events yet (attempt=%d connected=%d/%d)", + self_skill_refresh_attempts, + connected_relays, + cfg.relay_count); + } else { + DEBUG_WARN("[didactyl] startup phase: self-skill sync refresh failed (attempt=%d connected=%d/%d)", + self_skill_refresh_attempts, + connected_relays, + cfg.relay_count); + } + } else { + DEBUG_INFO("[didactyl] startup phase: waiting for connected relay before self-skill sync refresh"); + } + + if (self_skill_waited_ms >= self_skill_sync_total_budget_ms) { + break; + } + + int step_ms = self_skill_retry_step_ms; + if (self_skill_waited_ms + step_ms > self_skill_sync_total_budget_ms) { + step_ms = self_skill_sync_total_budget_ms - self_skill_waited_ms; + } + if (step_ms <= 0) { + break; + } + + (void)nostr_handler_poll(step_ms); + self_skill_waited_ms += step_ms; + } + + if (self_skill_validate_rc != 0) { + const char* fail_detail = (self_skill_refresh_rc == 0) + ? "no skill events found after sync query retries" + : "self-skill sync query failed within timeout"; startup_step_fail(14, "Subscribe self-skill cache", - "no skill events found after EOSE"); + fail_detail); notify_admin_startup_failure(&cfg, 14, "Subscribe self-skill cache", - "no skill events found after EOSE"); - fprintf(stderr, - "Startup aborted: no skill events (kind 31123/31124) found in self-skill cache\n"); - fprintf(stderr, - "The agent requires at least one skill event to operate\n"); - fprintf(stderr, - "Run genesis to publish the default skill, or publish a skill manually\n"); + fail_detail); + if (self_skill_refresh_rc == 0) { + fprintf(stderr, + "Startup aborted: no skill events (kind 31123/31124) found in self-skill cache after sync query retries\n"); + fprintf(stderr, + "Attempts=%d connected=%d/%d\n", + self_skill_refresh_attempts, + nostr_handler_connected_relay_count(), + cfg.relay_count); + fprintf(stderr, + "The agent requires at least one skill event to operate\n"); + fprintf(stderr, + "Run genesis to publish the default skill, or publish a skill manually\n"); + } else { + fprintf(stderr, + "Startup aborted: failed to sync self-skill cache from connected relays within %d ms\n", + self_skill_sync_total_budget_ms); + fprintf(stderr, + "Attempts=%d connected=%d/%d\n", + self_skill_refresh_attempts, + nostr_handler_connected_relay_count(), + cfg.relay_count); + fprintf(stderr, + "Check relay connectivity and ensure required self-skill events exist on at least one connected relay\n"); + } agent_cleanup(); nostr_block_list_cleanup(); trigger_manager_cleanup(&trigger_manager); diff --git a/src/main.h b/src/main.h index daa3d03..13115ff 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 49 -#define DIDACTYL_VERSION "v0.2.49" +#define DIDACTYL_VERSION_PATCH 50 +#define DIDACTYL_VERSION "v0.2.50" // Agent metadata #define DIDACTYL_NAME "Didactyl"