269 lines
11 KiB
Markdown
269 lines
11 KiB
Markdown
# Crash Fixes Reference
|
|
|
|
This document catalogues crashes that have been diagnosed and fixed in Didactyl.
|
|
Use it as a reference when investigating future crashes — the symptoms, root causes,
|
|
and investigation techniques described here may save significant debugging time.
|
|
|
|
---
|
|
|
|
## 1. Silent process exit on relay disconnect — SIGPIPE (v0.0.24)
|
|
|
|
**Date**: 2026-03-02
|
|
**Version**: v0.0.23 → fixed in v0.0.24
|
|
**Severity**: Critical — process terminates without any log output
|
|
**Files changed**: `src/main.c`
|
|
|
|
### Symptoms
|
|
|
|
- The process exits cleanly to the shell prompt with **no error message**.
|
|
- The `[didactyl] shutting down` log line does **not** appear.
|
|
- No coredump is generated.
|
|
- The last log lines show all relays transitioning from `connected → disconnected`
|
|
and then immediately `disconnected → connected`.
|
|
- The crash typically follows a period of network instability or DNS resolution
|
|
failure — for example, an LLM HTTP request failing with
|
|
`curl=Could not resolve hostname`.
|
|
|
|
### Root cause
|
|
|
|
`SIGPIPE` was never handled. The default OS action for `SIGPIPE` is to terminate
|
|
the process immediately — no signal handler runs, no cleanup occurs, no coredump
|
|
is written.
|
|
|
|
The TLS write path in `nostr_core_lib` uses `SSL_write()`, which internally calls
|
|
`write()` on the underlying socket. When a `wss://` relay drops its TCP connection
|
|
and the relay pool attempts to write to that socket, the kernel delivers `SIGPIPE`.
|
|
|
|
The plain-TCP path for `ws://` connections was already protected by using
|
|
`MSG_NOSIGNAL` on `send()` calls, but the TLS path had no equivalent protection.
|
|
|
|
### How it was diagnosed
|
|
|
|
1. **No crash message or coredump** ruled out `SIGSEGV`, `SIGABRT`, and OOM.
|
|
2. **No shutdown log** ruled out a graceful exit via the signal handler.
|
|
3. `dmesg` and `journalctl` showed no OOM-kill or segfault entries.
|
|
4. Searching the entire codebase for `SIGPIPE` or `SIG_IGN` returned zero results.
|
|
5. The websocket TLS transport was confirmed to use `SSL_write()` without
|
|
`MSG_NOSIGNAL` or any per-thread signal mask.
|
|
6. The timeline matched: relay disconnects occurred, the next poll cycle attempted
|
|
a write to a dead TLS socket, and the process vanished.
|
|
|
|
### Fix
|
|
|
|
Added `signal(SIGPIPE, SIG_IGN)` in `main()` alongside the existing `SIGINT` and
|
|
`SIGTERM` handlers:
|
|
|
|
```c
|
|
signal(SIGINT, signal_handler);
|
|
signal(SIGTERM, signal_handler);
|
|
signal(SIGPIPE, SIG_IGN); /* ← added */
|
|
```
|
|
|
|
This causes `SSL_write()` and any other write to a broken pipe to return `-1` with
|
|
`errno = EPIPE` instead of killing the process. The relay pool and libcurl already
|
|
handle write errors gracefully.
|
|
|
|
### How to recognise this class of bug in the future
|
|
|
|
- Process disappears without any log output or coredump.
|
|
- Happens after network disruption or relay disconnects.
|
|
- `ulimit -c` may be 0, but even with unlimited core size, `SIGPIPE` does not
|
|
produce a coredump by default.
|
|
- Any new network transport layer added to the project should be audited for
|
|
`SIGPIPE` protection.
|
|
|
|
---
|
|
|
|
## 2. Use-after-free in `execute_nostr_list_manage` — SIGSEGV (v0.0.24)
|
|
|
|
**Date**: 2026-03-01 (coredump), fixed 2026-03-02
|
|
**Version**: v0.0.23 → fixed in v0.0.24
|
|
**Severity**: Critical — segmentation fault during tool execution
|
|
**Files changed**: `src/tools.c`
|
|
|
|
### Symptoms
|
|
|
|
- `SIGSEGV` crash during execution of the `nostr_list_manage` tool.
|
|
- Coredump shows the crash at `src/tools.c:29` inside `json_error()`, but with
|
|
heavily corrupted stack frames — the real crash site is in
|
|
`execute_nostr_list_manage()`.
|
|
- The corrupted stack is characteristic of heap corruption from use-after-free.
|
|
|
|
### Root cause
|
|
|
|
In `execute_nostr_list_manage()`, the `action` pointer was obtained from the
|
|
`args` cJSON tree:
|
|
|
|
```c
|
|
cJSON* action = cJSON_GetObjectItemCaseSensitive(args, "action");
|
|
```
|
|
|
|
Later, `args` was freed:
|
|
|
|
```c
|
|
cJSON_Delete(args); /* frees the entire tree including action */
|
|
```
|
|
|
|
But `action->valuestring` was still accessed afterwards:
|
|
|
|
```c
|
|
cJSON_AddStringToObject(out, "action", action->valuestring); /* dangling pointer */
|
|
```
|
|
|
|
After `cJSON_Delete(args)`, the `action` pointer is dangling. Accessing
|
|
`action->valuestring` reads freed heap memory, which may contain arbitrary data
|
|
or may have been reallocated for another purpose.
|
|
|
|
### How it was diagnosed
|
|
|
|
1. The coredump was extracted from systemd-coredump storage:
|
|
```
|
|
zstd -d /var/lib/systemd/coredump/core.didactyl_static.*.zst -o /tmp/core.bin
|
|
gdb ./didactyl_static_x86_64_debug /tmp/core.bin -batch -ex "bt"
|
|
```
|
|
2. The backtrace showed `execute_nostr_list_manage` with corrupted frames.
|
|
3. Code review of the function identified the `cJSON_Delete(args)` call occurring
|
|
before the last use of `action->valuestring`.
|
|
|
|
### Fix
|
|
|
|
Deferred `cJSON_Delete(args)` until after `action->valuestring` has been consumed
|
|
by `cJSON_AddStringToObject()`. The free now occurs immediately after the last use:
|
|
|
|
```c
|
|
cJSON_AddStringToObject(out, "action", action->valuestring);
|
|
cJSON_Delete(args); /* ← moved here, after last use of action */
|
|
```
|
|
|
|
All early-return error paths before this point also received their own
|
|
`cJSON_Delete(args)` call to prevent leaks.
|
|
|
|
### How to recognise this class of bug in the future
|
|
|
|
- `SIGSEGV` with corrupted or nonsensical stack frames.
|
|
- Crash location reported by GDB does not match the actual buggy code — the
|
|
corruption happened earlier.
|
|
- Any function that calls `cJSON_Delete()` on a parent object should be audited
|
|
to ensure no child pointers are used afterwards.
|
|
- Pattern to watch for:
|
|
```c
|
|
cJSON* child = cJSON_GetObjectItemCaseSensitive(parent, "key");
|
|
/* ... */
|
|
cJSON_Delete(parent);
|
|
/* ... */
|
|
use(child->valuestring); /* BUG: child is dangling */
|
|
```
|
|
|
|
---
|
|
|
|
## 3. DM subscription not receiving incoming kind 4 events — INVESTIGATION (v0.0.24)
|
|
|
|
**Date**: 2026-03-02
|
|
**Version**: v0.0.24
|
|
**Severity**: High — agent does not respond to incoming DMs
|
|
**Status**: Under investigation — diagnostic logging added
|
|
**Files changed**: `src/nostr_handler.c`
|
|
|
|
### Symptoms
|
|
|
|
- The agent starts up normally, connects to relays, and can **send** kind 4 DMs.
|
|
- Incoming kind 4 messages posted to the same relays are never processed.
|
|
- No error messages appear in the log — the agent simply sits idle after sending
|
|
its startup DM.
|
|
- The last log lines show successful outbound DM publishing but no inbound event
|
|
processing.
|
|
|
|
### Possible root causes (under investigation)
|
|
|
|
1. **Events never reach `on_event()` callback** — The relay pool library only
|
|
calls `on_event()` when it receives an `EVENT` message matching the
|
|
subscription ID. If the subscription was silently closed, errored, or not
|
|
re-established after a relay reconnect, no events would be delivered. The
|
|
relay could also be rejecting the subscription filter.
|
|
|
|
2. **`since` filter timing mismatch** — `g_start_time` is set to `time(NULL)`
|
|
during `nostr_handler_init()` (early in startup), but the DM subscription
|
|
is created much later (after admin context subscription, startup event
|
|
reconciliation, and startup DM sending). If the sender's clock is behind
|
|
the server's clock, their `created_at` timestamp would be before
|
|
`g_start_time` and the relay would filter them out.
|
|
|
|
3. **Sender tier filtering** — If the sender's pubkey doesn't match the admin
|
|
pubkey and isn't in the WoT contact list, the message is classified as
|
|
`DIDACTYL_SENDER_STRANGER` and silently dropped (only a DEBUG_LOG at
|
|
level 4).
|
|
|
|
4. **Signature verification failure** — If `verify_signatures` is enabled and
|
|
the event has an invalid signature, it is dropped with only a WARN log.
|
|
|
|
5. **Pool-level deduplication** — The relay pool's `is_event_seen()` cache is
|
|
shared across all subscriptions. If an event ID was somehow marked as seen
|
|
by another subscription, it would be silently dropped.
|
|
|
|
### Diagnostic logging added
|
|
|
|
TRACE-level (level 5 / `--debug 5`) logs were added at every decision point
|
|
in the `on_event()` callback and the `nostr_handler_subscribe_dms()` setup:
|
|
|
|
| Log message prefix | What it tells you |
|
|
|---|---|
|
|
| `DEBUG on_event ENTRY` | Callback was called — events are reaching didactyl |
|
|
| `DEBUG on_event NULL guard` | Event, config, or callback pointer is NULL |
|
|
| `DEBUG on_event: missing required fields` | Event JSON is malformed |
|
|
| `DEBUG on_event: kind=N id=... from=...` | Event kind, ID, and sender pubkey |
|
|
| `DEBUG on_event: ignoring non-kind4` | Event is not kind 4 |
|
|
| `DEBUG on_event: no p-tag found` | Kind 4 event has no `p` tag |
|
|
| `DEBUG on_event: p-tag mismatch` | `p` tag doesn't match agent's pubkey |
|
|
| `DEBUG on_event: sender=... tier=N` | Sender tier classification |
|
|
| `DEBUG on_eose called` | EOSE received from relays |
|
|
| `DEBUG DM subscription filter` | Full subscription filter JSON |
|
|
| `DEBUG DM subscription g_start_time=...` | `since` timestamp and time delta |
|
|
| `DEBUG DM subscription sub=...` | Subscription pointer (confirms creation) |
|
|
|
|
### How to use the diagnostic logs
|
|
|
|
1. Build with `./build_static.sh --debug`
|
|
2. Run with `--debug 5` to enable TRACE output
|
|
3. Send a kind 4 DM to the agent
|
|
4. Check the output:
|
|
- **No `on_event ENTRY` lines** → problem is at the relay/subscription level
|
|
- **`on_event ENTRY` appears but processing stops** → the specific drop-point
|
|
log identifies the exact filter that rejected the event
|
|
5. Check the `DM subscription filter` log to verify the `since` timestamp and
|
|
`#p` tag are correct
|
|
|
|
### How to recognise this class of bug in the future
|
|
|
|
- Agent can send but not receive — asymmetric connectivity.
|
|
- No error messages in the log — silent event filtering.
|
|
- The subscription filter (`since`, `#p`, `kinds`) may not match what the
|
|
sender is actually publishing.
|
|
- Clock skew between sender and receiver can cause `since` filter mismatches.
|
|
- Relay reconnections may not automatically re-subscribe.
|
|
|
|
---
|
|
|
|
## General debugging checklist
|
|
|
|
When investigating a crash in Didactyl, work through these steps:
|
|
|
|
1. **Check for coredumps**: `ls /var/lib/systemd/coredump/ | grep didactyl`
|
|
2. **Check dmesg/journalctl**: `dmesg | grep -i 'didactyl\|oom\|segfault'`
|
|
3. **Check for the shutdown log line**: If `[didactyl] shutting down` is missing,
|
|
the process was killed by a signal that bypassed the handler.
|
|
4. **Check ulimit**: `ulimit -c` — if 0, coredumps are disabled.
|
|
5. **Extract and analyse coredumps**:
|
|
```bash
|
|
zstd -d /var/lib/systemd/coredump/core.didactyl*.zst -o /tmp/core.bin
|
|
gdb ./didactyl_static_x86_64_debug /tmp/core.bin -batch -ex "bt full"
|
|
```
|
|
6. **Common silent killers**:
|
|
- `SIGPIPE` — process writes to a broken socket/pipe
|
|
- `SIGKILL` — OOM killer or external kill
|
|
- `SIGBUS` — memory-mapped file issues
|
|
7. **Common crash causes**:
|
|
- Use-after-free on cJSON child pointers after parent deletion
|
|
- Buffer overflows in fixed-size stack buffers
|
|
- NULL pointer dereference on failed allocations
|
|
- Re-entrancy in callbacks during internal `nostr_relay_pool_poll()` calls
|