v0.2.50 - Fix startup step-14 false-negative by adding sync self-skill retry validation and post-auth query REQ resend

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

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":[<agent_pubkey>],"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.

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);

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"