laantungir/c-relay
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases 7 Wiki Activity

v0.7.39 - Set dm's back 2 days to adjust for timestamp ramdomization of giftwraps.

Browse Source
This commit is contained in:
Your Name
2025-10-23 18:43:45 -03:00
parent 079fb1b0f5
commit 3dc09d55fd
11 changed files with 322 additions and 54 deletions
Download Patch File Download Diff File Expand all files Collapse all files

209
docs/subscription_matching_debug_plan.md Normal file
View File

@@ -0,0 +1,209 @@
# 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.