Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Chore: save failed events for debugging purposes #169

Open
amirRamirfatahi opened this issue Oct 17, 2024 · 4 comments
Open

Chore: save failed events for debugging purposes #169

amirRamirfatahi opened this issue Oct 17, 2024 · 4 comments
Assignees
@tipogi
Labels
bug Something isn't working enhancement New feature or request 🔮 nexus 👀 watcher

Comments

@amirRamirfatahi
Copy link
Collaborator

No description provided.

@amirRamirfatahi amirRamirfatahi self-assigned this Oct 17, 2024
@SHAcollision SHAcollision added enhancement New feature or request bug Something isn't working 🔮 nexus 👀 watcher labels Nov 18, 2024
@SHAcollision SHAcollision changed the title Save failed events for debugging purposes Chores: save failed events for debugging purposes Nov 18, 2024
@SHAcollision
Copy link
Collaborator

SHAcollision commented Nov 18, 2024 •
edited
Loading

To further complete this task definition.

We basically just need to catch watcher errors and output to console enough info to understand whether they are expected or not. Make a list out of the unexpected ones and start solving those bugs. This is a janitorial task: compile an Issue with unexpected errors, their logs and if possible, how to reproduce them.

@SHAcollision SHAcollision changed the title Chores: save failed events for debugging purposes Chore: save failed events for debugging purposes Nov 18, 2024
@SHAcollision SHAcollision mentioned this issue Nov 21, 2024
Closed
1 task
@tipogi
Copy link
Collaborator

tipogi commented Dec 5, 2024

Common Issues Encountered During Homeserver Synchronization

These are the main problems faced during the initial sync of the homeserver. Each issue is outlined with its symptoms, probable causes, and event logs.

A) Unindexed User Profile

The watcher processes a PUT event for a post before the user's profile (profile.json) has been indexed. This leads to an error when attempting to update the user's post count.

[2024-12-04T15:42:20Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/posts/0032FF17768KG
[2024-12-04T15:42:20Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/posts/0032FF17768KG", event_type: Put, resource_type: Post { author_id: PubkyId("e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no"), post_id: "0032FF17768KG" }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:65437), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 10, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-04T15:42:20Z DEBUG pubky_nexus::events] Handling PUT event for Post { author_id: PubkyId("e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no"), post_id: "0032FF17768KG" }
[2024-12-04T15:42:20Z DEBUG pubky_nexus::db::kv::index::json] Restored key: Post:Counts:e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no:0032FF17768KG with value: [{"tags":0,"replies":0,"reposts":0}]
[2024-12-04T15:42:20Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: posts in key: User:Counts:e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no by 1
[2024-12-04T15:42:20Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.posts, 0, 4294967295
[2024-12-04T15:42:20Z DEBUG pubky_nexus::db::kv::index::json] Redis Error: An error was signalled by the server - ResponseError: user_script:13: bad argument #1 to 'decode' (string expected, got boolean) script: 15843ccf7be8930761af5faf6a4e19e0387716f2, on @user_script:13.

The user's profile.json has not been processed yet, so the user key in Redis is not initialized. Subsequent attempts to update counts fail.

[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/posts/0032FF17768KG
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/follows/pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/follows/autysxcxegcktsk76gdawrr8fdehx8k7fhi18diqyy7i89e8pody
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/follows/operrr8wsbpr3ue9d4qj41ge1kcc6r7fdiy6o3ugjrrhi4y77rdo
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/follows/oaqt7xtjnm9sbit81nnhub5dqtwtmncesfqs7cfow5ks4gg4wmso
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/follows/au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/follows/o1gg96ewuojmopcjbz8895478wdtxtzzuxnfjjz8o8e77csa1ngo
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/last_read
[2024-12-03T14:03:23Z DEBUG pubky_nexus::events] New event: PUT pubky://o1gg96ewuojmopcjbz8895478wdtxtzzuxnfjjz8o8e77csa1ngo/pub/pubky.app/last_read
[2024-12-03T14:03:24Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/blobs/0032FF1C2PRN0
[2024-12-03T14:03:24Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/files/0032FF1C2WT0G
-> [2024-12-03T14:03:24Z DEBUG pubky_nexus::events] New event: PUT pubky://e4aakyixz9nqz4omn5z7mfedxsxrsoowyyus3ahebg55q3htg1no/pub/pubky.app/profile.json

B) Unresolved URI During Follow Events

A PUT event for a follow relationship fails because the followee's profile.json is not resolved and indexed.

[2024-12-05T04:35:14Z DEBUG pubky_nexus::events] New event: PUT pubky://oaqt7xtjnm9sbit81nnhub5dqtwtmncesfqs7cfow5ks4gg4wmso/pub/pubky.app/follows/pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy
[2024-12-05T04:35:14Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://oaqt7xtjnm9sbit81nnhub5dqtwtmncesfqs7cfow5ks4gg4wmso/pub/pubky.app/follows/pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy", event_type: Put, resource_type: Follow { follower_id: PubkyId("oaqt7xtjnm9sbit81nnhub5dqtwtmncesfqs7cfow5ks4gg4wmso"), followee_id: PubkyId("pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy") }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 4, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T04:35:14Z DEBUG pubky_nexus::events] Handling PUT event for Follow { follower_id: PubkyId("oaqt7xtjnm9sbit81nnhub5dqtwtmncesfqs7cfow5ks4gg4wmso"), followee_id: PubkyId("pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy") }
[2024-12-05T04:35:14Z DEBUG pubky_nexus::events::handlers::follow] Indexing new follow: oaqt7xtjnm9sbit81nnhub5dqtwtmncesfqs7cfow5ks4gg4wmso -> pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy
[2024-12-05T04:35:14Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: following in key: User:Counts:oaqt7xtjnm9sbit81nnhub5dqtwtmncesfqs7cfow5ks4gg4wmso by 1
[2024-12-05T04:35:14Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.following, 0, 4294967295
[2024-12-05T04:35:14Z INFO  pubky_nexus::db::kv::index::json] Redis result: 2
[2024-12-05T04:35:14Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: followers in key: User:Counts:pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy by 1
[2024-12-05T04:35:14Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.followers, 0, 4294967295
[2024-12-05T04:35:14Z DEBUG pubky_nexus::db::kv::index::json] Redis Error: An error was signalled by the server - ResponseError: new objects must be created at the root script: d00e585480cb8657493bbfe328365d6e63f49d4b, on @user_script:53.

The followee's key is not initialized in the graph or cache (homeserver unresolved error), so follow relationship updates cannot be indexed.

[2024-12-05T05:52:37Z DEBUG pubky_nexus::events] New event: PUT pubky://pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy/pub/pubky.app/profile.json
[2024-12-05T05:52:37Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy/pub/pubky.app/profile.json", event_type: Put, resource_type: User { user_id: PubkyId("pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy") }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 3, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T05:52:37Z DEBUG pubky_nexus::events] Handling PUT event for User { user_id: PubkyId("pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy") }
[2024-12-05T05:52:37Z ERROR pubky_nexus::events] Failed to fetch content at pubky://pxnu33x7jtpx9ar1ytsi4yxbp6a5o36gwhffs8zoxmbuptici1jy/pub/pubky.app/profile.json: Generic error: Could not resolve homeserver
->[2024-12-05T05:52:37Z ERROR pubky_nexus::events::processor] Error while handling event after 1 attempts: Generic error: Could not resolve homeserver

C) Post Deleted

A DEL event for a post fails because the post is not present in the graph or cache.

[2024-12-05T06:21:25Z DEBUG pubky_nexus::events] New event: DEL pubky://hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/pub/pubky.app/posts/0032GQY5QTD5G
[2024-12-05T06:21:25Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/pub/pubky.app/posts/0032GQY5QTD5G", event_type: Del, resource_type: Post { author_id: PubkyId("hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo"), post_id: "0032GQY5QTD5G" }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 101, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T06:21:25Z DEBUG pubky_nexus::events] Handling DEL event for Post { author_id: PubkyId("hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo"), post_id: "0032GQY5QTD5G" }
[2024-12-05T06:21:25Z DEBUG pubky_nexus::events::handlers::post] Deleting post: hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/0032GQY5QTD5G
[2024-12-05T06:21:25Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: posts in key: User:Counts:hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo by -1
[2024-12-05T06:21:25Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.posts, 0, 4294967295
[2024-12-05T06:21:25Z DEBUG pubky_nexus::db::kv::index::json] Redis Error: An error was signalled by the server - ResponseError: new objects must be created at the root script: d00e585480cb8657493bbfe328365d6e63f49d4b, on @user_script:53.

The post has already been deleted from both the homeserver, so the deletion event has no associated data to process in the graph or cache.

[2024-12-05T06:21:25Z DEBUG pubky_nexus::events] New event: PUT pubky://hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/pub/pubky.app/posts/0032GQY5QTD5G
[2024-12-05T06:21:25Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/pub/pubky.app/posts/0032GQY5QTD5G", event_type: Put, resource_type: Post { author_id: PubkyId("hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo"), post_id: "0032GQY5QTD5G" }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 101, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T06:21:25Z DEBUG pubky_nexus::events] Handling PUT event for Post { author_id: PubkyId("hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo"), post_id: "0032GQY5QTD5G" }
[2024-12-05T06:21:25Z DEBUG pkarr::client] Have fresh signed_packet in cache. expires_in=3600
[2024-12-05T06:21:25Z DEBUG pkarr::client] Have fresh signed_packet in cache. expires_in=3600
[2024-12-05T06:21:25Z DEBUG reqwest::connect] starting new connection: http://localhost:6287/
[2024-12-05T06:21:25Z ERROR pubky_nexus::events] Failed to fetch content at pubky://hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/pub/pubky.app/posts/0032GQY5QTD5G: error sending request for url (http://localhost:6287/hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/pub/pubky.app/posts/0032GQY5QTD5G)
[2024-12-05T06:21:25Z ERROR pubky_nexus::events::processor] Error while handling event after 1 attempts: error sending request for url (http://localhost:6287/hbdhm44esfm8pihqruq58pdymwdx1wxe8q1hkscotad6bcj4yceo/pub/pubky.app/posts/0032GQY5QTD5G)

D) Delete for Non-Existent Post

The user's profile was deleted from the client, which also resulted in the deletion of all associated content. When a new DEL event is received, the system cannot locate the user or the related post indexes, leading to processing failures

[2024-12-05T05:20:27Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GJVZ0NVZG
[2024-12-05T05:20:27Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GJVZ0NVZG", event_type: Del, resource_type: Post { author_id: PubkyId("bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako"), post_id: "0032GJVZ0NVZG" }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 73, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T05:20:27Z DEBUG pubky_nexus::events] Handling DEL event for Post { author_id: PubkyId("bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako"), post_id: "0032GJVZ0NVZG" }
[2024-12-05T05:20:27Z DEBUG pubky_nexus::events::handlers::post] Deleting post: bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/0032GJVZ0NVZG
[2024-12-05T05:20:27Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: posts in key: User:Counts:bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako by -1
[2024-12-05T05:20:27Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.posts, 0, 4294967295
[2024-12-05T05:20:27Z DEBUG pubky_nexus::db::kv::index::json] Redis Error: An error was signalled by the server - ResponseError: new objects must be created at the root script: d00e585480cb8657493bbfe328365d6e63f49d4b, on @user_script:53.

Events associated with the deletion of this profile and its related content

[2024-12-05T05:05:21Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/profile.json
[2024-12-05T05:05:21Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/blobs/0032GJVXBRAM0
[2024-12-05T05:05:21Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/files/0032GJVXHRB50
[2024-12-05T05:05:21Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GJVXBP4A0
-> [2024-12-05T05:05:21Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GJVZ0NVZG
[2024-12-05T05:05:21Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/last_read
-> [2024-12-05T05:05:21Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GJVZ0NVZG
[2024-12-05T05:05:48Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GPBGD1AF0
[2024-12-05T05:05:48Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/last_read
[2024-12-05T05:05:48Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/blobs/0032GPBKFTCRG
[2024-12-05T05:05:48Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/files/0032GPBKG1YYG
[2024-12-05T05:05:48Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/profile.json
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/last_read
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GPBGD1AF0
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GJVXBP4A0
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/last_read
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/files/0032GPBKG1YYG
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/files/0032GJVXHRB50
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/blobs/0032GPBKFTCRG
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/blobs/0032GJVXBRAM0
==> [2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: DEL pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/profile.json
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/posts/0032GQ1MZVZRG
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/last_read
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/last_read
[2024-12-05T05:06:14Z DEBUG pubky_nexus::events] New event: PUT pubky://bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako/pub/pubky.app/last_read

E) Incrementing Parent Post Counts

When performing a sync from scratch, if a new post references a parent post that has already been deleted, the system is unable to update the replies field in the Post:Counts index.

This issue does not arise with a fully synced homeserver because Nexus retains a placeholder for the deleted parent post, marked as [DELETED], allowing the system to handle such events even if the post no longer exists on the homeserver.

[2024-12-05T06:20:34Z DEBUG pubky_nexus::events] New event: PUT pubky://au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo/pub/pubky.app/posts/0032GPBQBEAKG
[2024-12-05T06:20:34Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo/pub/pubky.app/posts/0032GPBQBEAKG", event_type: Put, resource_type: Post { author_id: PubkyId("au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo"), post_id: "0032GPBQBEAKG" }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 77, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T06:20:34Z DEBUG pubky_nexus::events] Handling PUT event for Post { author_id: PubkyId("au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo"), post_id: "0032GPBQBEAKG" }
[2024-12-05T06:20:34Z DEBUG pubky_nexus::events::handlers::post] Indexing new post: au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo/0032GPBQBEAKG
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Set key: Post:Counts:au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo:0032GPBQBEAKG with optional expiration: None
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: posts in key: User:Counts:au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo by 1
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.posts, 0, 4294967295
[2024-12-05T06:20:34Z INFO  pubky_nexus::db::kv::index::json] Redis result: 11
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: replies in key: User:Counts:au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo by 1
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.replies, 0, 4294967295
[2024-12-05T06:20:34Z INFO  pubky_nexus::db::kv::index::json] Redis result: 21
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: replies in key: Post:Counts:bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako:0032GPBGD1AF0 by 1
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.replies, 0, 4294967295
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Redis Error: An error was signalled by the server - ResponseError: new objects must be created at the root script: d00e585480cb8657493bbfe328365d6e63f49d4b, on @user_script:53.
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Set key: Post:Relationships:au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo:0032GPBQBEAKG with optional expiration: None
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Set key: Post:Details:au1h984texykfj8sz5ggac5ffft3rzaqecgjii3tfec54fk4fbgo:0032GPBQBEAKG with optional expiration: None

F) Cannot Tag

A similar issue that occurs with posts can also happen with tags. If a deleted profile (e.g., ...ako) is tagged, and its profile.json is missing from the homeserver, the profile will not exist in the graph or cache when the system attempts to update the associated key.

[2024-12-05T06:20:34Z DEBUG pubky_nexus::events] New event: PUT pubky://anxom4ktdphs8qhrymhceghz39bonecg9hz8yd819hkcsniken9y/pub/pubky.app/tags/PCW8WKZ1JD49T604VXR673DF0W
[2024-12-05T06:20:34Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://anxom4ktdphs8qhrymhceghz39bonecg9hz8yd819hkcsniken9y/pub/pubky.app/tags/PCW8WKZ1JD49T604VXR673DF0W", event_type: Put, resource_type: Tag { user_id: PubkyId("anxom4ktdphs8qhrymhceghz39bonecg9hz8yd819hkcsniken9y"), tag_id: "PCW8WKZ1JD49T604VXR673DF0W" }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 77, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T06:20:34Z DEBUG pubky_nexus::events] Handling PUT event for Tag { user_id: PubkyId("anxom4ktdphs8qhrymhceghz39bonecg9hz8yd819hkcsniken9y"), tag_id: "PCW8WKZ1JD49T604VXR673DF0W" }
[2024-12-05T06:20:34Z DEBUG pubky_nexus::events::handlers::tag] Indexing new tag: anxom4ktdphs8qhrymhceghz39bonecg9hz8yd819hkcsniken9y -> PCW8WKZ1JD49T604VXR673DF0W
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: tagged in key: User:Counts:bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako by 1
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.tagged, 0, 4294967295
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Redis Error: An error was signalled by the server - ResponseError: new objects must be created at the root script: d00e585480cb8657493bbfe328365d6e63f49d4b, on @user_script:53.
[2024-12-05T06:20:34Z DEBUG pubky_nexus::db::kv::index::json] Controlled Error of user: "bhowdjfdk9idbtmabzm7oo8sbmdztm68eown4iyq7s1jcmrdoako"

G) Homeserver Resolution Failure

If the homeserver cannot be resolved, the system is unable to retrieve the event content, preventing further processing.

[2024-12-05T06:22:42Z DEBUG pubky_nexus::events] New event: PUT pubky://sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo/pub/pubky.app/posts/0032GXAT3GNC0
[2024-12-05T06:22:42Z DEBUG mainline::rpc] No values target=Id(bd3b08ec425db143add0647058ffb99a36ce68ac) salt=None from=202.120.16.213:16881 responder_id=Id(bd100d21e739066789b55fa0f2036db7d031c152) from_version=Some([76, 84, 1, 47])
[2024-12-05T06:22:42Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo/pub/pubky.app/posts/0032GXAT3GNC0", event_type: Put, resource_type: Post { author_id: PubkyId("sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo"), post_id: "0032GXAT3GNC0" }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 136, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T06:22:42Z DEBUG pubky_nexus::events] Handling PUT event for Post { author_id: PubkyId("sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo"), post_id: "0032GXAT3GNC0" }
[[2024-12-05T06:22:42Z DEBUG pubky_nexus::events::handlers::post] Indexing new post: sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo/0032GXAT3GNC0
[2024-12-05T06:22:42Z DEBUG pubky_nexus::db::kv::index::json] Set key: Post:Counts:sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo:0032GXAT3GNC0 with optional expiration: None
[2024-12-05T06:22:42Z DEBUG pubky_nexus::db::kv::index::json] Modifiying field: posts in key: User:Counts:sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo by 1
[2024-12-05T06:22:42Z DEBUG pubky_nexus::db::kv::index::json] Other params: $.posts, 0, 4294967295
[2024-12-05T06:22:42Z DEBUG pubky_nexus::db::kv::index::json] Redis Error: An error was signalled by the server - ResponseError: new objects must be created at the root script: d00e585480cb8657493bbfe328365d6e63f49d4b, on @user_script:53.

The user profile was not resolved so, the profile is not indexed

PUT pubky://sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo/pub/pubky.app/profile.json
[2024-12-05T06:18:52Z DEBUG pubky_nexus::events::processor] Processing event: Event { uri: "pubky://sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo/pub/pubky.app/profile.json", event_type: Put, resource_type: User { user_id: PubkyId("sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo") }, pubky_client: PubkyClient { http: Client { cookie_store: true, accepts: Accepts, proxies: [Proxy(System({}), None)], referer: true, default_headers: {"accept": "*/*", "user-agent": "pubky/0.3.0"} }, pkarr: PkarrClientAsync(PkarrClient { address: Some(0.0.0.0:6881), sender: Sender, cache: InMemoryPkarrCache { inner: Mutex { data: LruCache { len: 64, cap: 1000 }, poisoned: false, .. } }, minimum_ttl: 300, maximum_ttl: 86400 }) } }
[2024-12-05T06:18:52Z DEBUG pubky_nexus::events] Handling PUT event for User { user_id: PubkyId("sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo") }
[2024-12-05T06:18:52Z ERROR pubky_nexus::events] Failed to fetch content at pubky://sazaz5yowshbkfbsqi4n47rbyn8xbmokmu8kft59iyjazjxo4jeo/pub/pubky.app/profile.json: Generic error: Could not resolve homeserver
-> [2024-12-05T06:18:52Z ERROR pubky_nexus::events::processor] Error while handling event after 1 attempts: Generic error: Could not resolve homeserver

@tipogi tipogi mentioned this issue Dec 5, 2024
Closed
@tipogi
Copy link
Collaborator

tipogi commented Dec 5, 2024

Event retry system

This design draft outlines a system to store events that fail to sync with Nexus, enabling them to be retried in a future time window while maintaining the chronological order of events from the homeserver.

Design

A HashMap will be added to the watcher service to store the unsynced events. Events will be organized as follows:

  • KEY: The user's unique identifier (pubky).
  • VALUE: A LinkedList that preserves the chronological order of the events. Each node in the LinkedList will contain the following structure:
struct EventUnit {
    uri: String,              // URI of the resource
    event_type: EventType,    // Type of event (e.g., PUT, DEL)
    timestamp: u64,           // Unix timestamp when the event was received
    dependency: Option<String>, // Optional parent URI for dependency tracking
    retry_count: u32,         // Number of retries attempted
}

In certain scenarios (yet to be identified), it may be sufficient to use a single LinkedList instead of a HashMap. However, the HashMap provides the ability to efficiently organize events by user_id (or pubky), which might be necessary for user-specific resolution.

Steps

  1. Watcher Polls Events: The watcher begins polling events from the endpoint homeserver_pubky/events/?cursor={}
  2. Process Events: Loop through the received events and query the PkarrRelay service to retrieve the content of each event.
  3. Handle Not Resolved Events: If an event cannot be resolved (e.g., due to missing dependencies, network issues, ...), add it to the HashMap.
  4. Repeat Process: Continue processing events, adding unresolved ones to the retry system.
  5. Retry Sync: After a predefined time interval, loop through the HashMap and retry syncing the missing events.

event-validator

@tipogi
Copy link
Collaborator

tipogi commented Dec 5, 2024 •
edited
Loading

Other observations

These considerations apply when performing a full sync from scratch. In certain cases, it may be possible to avoid adding failed events to the HashMap. The following points outline handling strategies for specific event types:

Handling DEL Events:

  • For each DEL event, verify whether the associated user (pubky) and resource (post_id, tag_id, bookmark_id, etc.) exist in the system before attempting deletion.
  • Skip adding the event to the HashMap if the resources to be deleted are already missing.

Handling PUT or DEL Events for profile.json:

  • Create or update the user node (graph) with minimal (just pubky) information even the we could not resolve the URI.
  • For deletions, set the user data to a placeholder state with [DELETED] as the name, consistent with the current practice.

Handling PUT Events for Other Resources:

For PUT events (e.g., post creation, tag creation) where the user (pubky) is not yet present in the graph:

  • Add a new empty user with the given pubky. Like these the user counts would not be affected. We could use the pubky itself as the placeholder name.
  • If a subsequent PUT event for profile.json is received, update the user’s information with the provided data.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tipogi tipogi

Labels
bug Something isn't working enhancement New feature or request 🔮 nexus 👀 watcher
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@amirRamirfatahi @tipogi @SHAcollision