c-relay/docs/subscription_matching_debug_plan.md

# Subscription Matching Debug Plan

## Problem
The relay is not matching kind 1059 (NIP-17 gift wrap) events to subscriptions, even though a subscription exists with `kinds:[1059]` filter. The log shows:
```
Event broadcast complete: 0 subscriptions matched
```

But we have this subscription:
```
sub:3	146.70.187.119	0x78edc9b43210	8m 27s	kinds:[1059], since:10/23/2025, 4:27:59 PM, limit:50
```

## Investigation Strategy

### 1. Add Debug Output to `event_matches_filter()` (lines 386-564)
Add debug logging at each filter check to trace the matching logic:

- **Entry point**: Log the event kind and filter being tested
- **Kinds filter check** (lines 392-415): Log whether kinds filter exists, the event kind value, and each filter kind being compared
- **Authors filter check** (lines 417-442): Log if authors filter exists and matching results
- **IDs filter check** (lines 444-469): Log if IDs filter exists and matching results
- **Since filter check** (lines 471-482): Log the event timestamp vs filter since value
- **Until filter check** (lines 484-495): Log the event timestamp vs filter until value
- **Tag filters check** (lines 497-561): Log tag filter matching details
- **Exit point**: Log whether the overall filter matched

### 2. Add Debug Output to `event_matches_subscription()` (lines 567-581)
Add logging to show:
- How many filters are in the subscription
- Which filter (if any) matched
- Overall subscription match result

### 3. Add Debug Output to `broadcast_event_to_subscriptions()` (lines 584-726)
Add logging to show:
- The event being broadcast (kind, id, created_at)
- Total number of active subscriptions being checked
- How many subscriptions matched after the first pass

### 4. Key Areas to Focus On

Based on the code analysis, the most likely issues are:

1. **Kind matching logic** (lines 392-415): The event kind might not be extracted correctly, or the comparison might be failing
2. **Since timestamp** (lines 471-482): The subscription has a `since` filter - if the event timestamp is before this, it won't match
3. **Event structure**: The event JSON might not have the expected structure

### 5. Specific Debug Additions

#### In `event_matches_filter()` at line 386:
```c
// Add at start of function
cJSON* event_kind_obj = cJSON_GetObjectItem(event, "kind");
cJSON* event_id_obj = cJSON_GetObjectItem(event, "id");
cJSON* event_created_at_obj = cJSON_GetObjectItem(event, "created_at");

DEBUG_TRACE("FILTER_MATCH: Testing event kind=%d id=%.8s created_at=%ld",
    event_kind_obj ? (int)cJSON_GetNumberValue(event_kind_obj) : -1,
    event_id_obj && cJSON_IsString(event_id_obj) ? cJSON_GetStringValue(event_id_obj) : "null",
    event_created_at_obj ? (long)cJSON_GetNumberValue(event_created_at_obj) : 0);
```

#### In kinds filter check (after line 392):
```c
if (filter->kinds && cJSON_IsArray(filter->kinds)) {
    DEBUG_TRACE("FILTER_MATCH: Checking kinds filter with %d kinds", cJSON_GetArraySize(filter->kinds));

    cJSON* event_kind = cJSON_GetObjectItem(event, "kind");
    if (!event_kind || !cJSON_IsNumber(event_kind)) {
        DEBUG_WARN("FILTER_MATCH: Event has no valid kind field");
        return 0;
    }

    int event_kind_val = (int)cJSON_GetNumberValue(event_kind);
    DEBUG_TRACE("FILTER_MATCH: Event kind=%d", event_kind_val);

    int kind_match = 0;
    cJSON* kind_item = NULL;
    cJSON_ArrayForEach(kind_item, filter->kinds) {
        if (cJSON_IsNumber(kind_item)) {
            int filter_kind = (int)cJSON_GetNumberValue(kind_item);
            DEBUG_TRACE("FILTER_MATCH: Comparing event kind %d with filter kind %d", event_kind_val, filter_kind);
            if (filter_kind == event_kind_val) {
                kind_match = 1;
                DEBUG_TRACE("FILTER_MATCH: Kind matched!");
                break;
            }
        }
    }

    if (!kind_match) {
        DEBUG_TRACE("FILTER_MATCH: No kind match, filter rejected");
        return 0;
    }
    DEBUG_TRACE("FILTER_MATCH: Kinds filter passed");
}
```

#### In since filter check (after line 472):
```c
if (filter->since > 0) {
    cJSON* event_created_at = cJSON_GetObjectItem(event, "created_at");
    if (!event_created_at || !cJSON_IsNumber(event_created_at)) {
        DEBUG_WARN("FILTER_MATCH: Event has no valid created_at field");
        return 0;
    }
    
    long event_timestamp = (long)cJSON_GetNumberValue(event_created_at);
    DEBUG_TRACE("FILTER_MATCH: Checking since filter: event_ts=%ld filter_since=%ld",
        event_timestamp, filter->since);

    if (event_timestamp < filter->since) {
        DEBUG_TRACE("FILTER_MATCH: Event too old (before since), filter rejected");
        return 0;
    }
    DEBUG_TRACE("FILTER_MATCH: Since filter passed");
}
```

#### At end of `event_matches_filter()` (before line 563):
```c
DEBUG_TRACE("FILTER_MATCH: All filters passed, event matches!");
return 1; // All filters passed
```

#### In `event_matches_subscription()` at line 567:
```c
int event_matches_subscription(cJSON* event, subscription_t* subscription) {
    if (!event || !subscription || !subscription->filters) {
        return 0;
    }

    DEBUG_TRACE("SUB_MATCH: Testing subscription '%s'", subscription->id);

    int filter_num = 0;
    subscription_filter_t* filter = subscription->filters;
    while (filter) {
        filter_num++;
        DEBUG_TRACE("SUB_MATCH: Testing filter #%d", filter_num);

        if (event_matches_filter(event, filter)) {
            DEBUG_TRACE("SUB_MATCH: Filter #%d matched! Subscription '%s' matches",
                filter_num, subscription->id);
            return 1; // Match found (OR logic)
        }
        filter = filter->next;
    }

    DEBUG_TRACE("SUB_MATCH: No filters matched for subscription '%s'", subscription->id);
    return 0; // No filters matched
}
```

#### In `broadcast_event_to_subscriptions()` at line 584:
```c
int broadcast_event_to_subscriptions(cJSON* event) {
    if (!event) {
        return 0;
    }
    
    // Log event details
    cJSON* event_kind = cJSON_GetObjectItem(event, "kind");
    cJSON* event_id = cJSON_GetObjectItem(event, "id");
    cJSON* event_created_at = cJSON_GetObjectItem(event, "created_at");
    
    DEBUG_TRACE("BROADCAST: Event kind=%d id=%.8s created_at=%ld",
        event_kind ? (int)cJSON_GetNumberValue(event_kind) : -1,
        event_id && cJSON_IsString(event_id) ? cJSON_GetStringValue(event_id) : "null",
        event_created_at ? (long)cJSON_GetNumberValue(event_created_at) : 0);

    // ... existing expiration check code ...

    // After line 611 (before pthread_mutex_lock):
    pthread_mutex_lock(&g_subscription_manager.subscriptions_lock);

    int total_subs = 0;
    subscription_t* count_sub = g_subscription_manager.active_subscriptions;
    while (count_sub) {
        total_subs++;
        count_sub = count_sub->next;
    }
    DEBUG_TRACE("BROADCAST: Checking %d active subscriptions", total_subs);

    subscription_t* sub = g_subscription_manager.active_subscriptions;
    // ... rest of matching logic ...
```

## Expected Outcome

With these debug additions, we should see output like:
```
BROADCAST: Event kind=1059 id=abc12345 created_at=1729712279
BROADCAST: Checking 1 active subscriptions
SUB_MATCH: Testing subscription 'sub:3'
SUB_MATCH: Testing filter #1
FILTER_MATCH: Testing event kind=1059 id=abc12345 created_at=1729712279
FILTER_MATCH: Checking kinds filter with 1 kinds
FILTER_MATCH: Event kind=1059
FILTER_MATCH: Comparing event kind 1059 with filter kind 1059
FILTER_MATCH: Kind matched!
FILTER_MATCH: Kinds filter passed
FILTER_MATCH: Checking since filter: event_ts=1729712279 filter_since=1729708079
FILTER_MATCH: Since filter passed
FILTER_MATCH: All filters passed, event matches!
SUB_MATCH: Filter #1 matched! Subscription 'sub:3' matches
Event broadcast complete: 1 subscriptions matched
```

This will help us identify exactly where the matching is failing.