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:

// 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):

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

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

DEBUG_TRACE("FILTER_MATCH: All filters passed, event matches!");
return 1; // All filters passed

In event_matches_subscription() at line 567:

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:

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.