[bug] intermittent trouble with inbound follow requests

[mirabilos]

[bug] intermittent trouble with inbound follow requests

[tsmethurst]

Hmm alright thanks! I'll keep my eyes peeled and see if the bug replicates on my instance at all, or if someone else reports it. For now It's v. difficult to tell if there's really something up here, or if people are just messing about following and unfollowing.

[tsmethurst]

Where in the DB are inbound follow requests stored

The follow_requests table stores both inbound and outbound ones.

Some users also send me a new follow request (I’m acknowledging every time) every couple of days. I wonder what’s up with that.

I have no idea, that's very strange. Maybe worth reaching out to those users and seeing what's going on there.

[mirabilos]

tobi dixit:

> Where in the DB are inbound follow requests stored The `follow_requests` table stores both inbound and outbound ones.

Ah okay, so then when I checked there just never were any inbound ones (which matches the Community → Follow Requests view). There’s this though: id | created_at | updated_at | notification_type | target_account_id | origin_account_id | status_id | read ----------------------------+-------------------------------+-------------------------------+-------------------+----------------------------+----------------------------+-----------+------ 01HJxxxxxxxxxxxxxxxxxxxxxx | 2023-12-28 23:33:17.001692+00 | 2023-12-28 23:33:17.001692+00 | follow_request | 01GSxxxxxxxxxxxxxxxxxxxxxx | 01H7xxxxxxxxxxxxxxxxxxxxxx | | f Does this help? Do you want to do more debugging for that?

> Some users also send me a new follow request (I’m acknowledging every > time) every couple of days. I wonder what’s up with that. I have no idea, that's very strange. Maybe worth reaching out to those users and seeing what's going on there.

Tried that, got no response, sorry. Again, I thought to file it in case someone has an idea, am aware this is going to be hard to track, and I have no expectation of magic fixes or something ☻ Thanks for your outstanding work so far, and for taking the time to respond to all those issues! bye, //mirabilos

[mirabilos]

OK, so the one where I only saw the notification but not the follow request was noted above, ping me if you want to continue debugging that.

---

I’ve got another incoming from the one who’s trying to follow me all the time, after I had boosted one of hist posts earlier today.

I see the incoming request:

timestamp="2024-01-15T21:38:20.451Z" func=server.glob..func1.Logger.func13.1 level=INFO latency="6.303972ms" userAgent="http.rb/5.1.1 (Mastodon/4.2.3; +https://norden.social/)" method=POST statusCode=202 path=/users/mirabilos/inbox clientIP=XXX pubKeyID=https://norden.social/users/XXX#main-key requestID=kpk0y3wd040016ey2t00 msg="Accepted: wrote 45B"

I see the follow request:

             id             |          created_at          |          updated_at          |                            uri                             |         account_id         |     target_account_id      | show_reblogs | notify
----------------------------+------------------------------+------------------------------+------------------------------------------------------------+----------------------------+----------------------------+--------------+--------
 01HM7GZ9MZFVAG20GPJ5KSHVJV | 2024-01-15 21:38:20.44813+00 | 2024-01-15 21:38:20.44813+00 | https://norden.social/d3cac7e0-e2d8-4bf8-b997-c157bfxxxxxx | 01JVNKXFBJ4DAVWPPAF3xxxxxx | 01GS55SW7VWYN3BFRYCXxxxxxx | t            | f
(1 row)

So lemme accept it…

timestamp="2024-01-15T22:23:37.148Z" func=server.glob..func1.Logger.func13.1 level=INFO latency="7.22µs" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/115.0" method=OPTIONS statusCode=204 path=/api/v1/follow_requests/01JVNKXFBJ4DAVWPPAF3xxxxxx/authorize clientIP=XXX requestID=qgd3j3wd0400118vvthg msg="No Content: wrote 0B"
timestamp="2024-01-15T22:23:37.364Z" func=bundb.queryHook.AfterQuery level=TRACE duration=672.81µs query=SELECT "token"."id", "token"."created_at", "token"."updated_at", "token"."client_id", "token"."user_id", "token"."redirect_uri", "token"."scope", "token"."code", "token"."code_challenge", "token"."code_challenge_method", "token"."code_create_at", "token"."code_expires_at", "token"."access", "token"."access_create_at", "token"."access_expires_at", "token"."refresh", "token"."refresh_create_at", "token"."refresh_expires_at" FROM "tokens" AS "token" WHERE ("access" = 'XxXxX')
timestamp="2024-01-15T22:23:37.364Z" func=api.(*Client).Route.TokenCheck.func1 level=TRACE requestID=jcdkj3wd04000s6jsrn0 msg="authenticated user xxx with bearer token, scope is read write follow push"
timestamp="2024-01-15T22:23:37.364Z" func=api.(*Client).Route.TokenCheck.func1 level=TRACE requestID=jcdkj3wd04000s6jsrn0 msg="authenticated client xxx with bearer token, scope is read write follow push"
timestamp="2024-01-15T22:23:37.366Z" func=bundb.queryHook.AfterQuery level=TRACE duration=1.062432ms query=SELECT "follow_request"."id", "follow_request"."created_at", "follow_request"."updated_at", "follow_request"."uri", "follow_request"."account_id", "follow_request"."target_account_id", "follow_request"."show_reblogs", "follow_request"."notify" FROM "follow_requests" AS "follow_request" WHERE ("account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') AND ("target_account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx')
timestamp="2024-01-15T22:23:37.366Z" func=bundb.queryHook.AfterQuery level=TRACE duration=742.912µs query=SELECT "account"."id", "account"."created_at", "account"."updated_at", "account"."fetched_at", "account"."username", "account"."domain", "account"."avatar_media_attachment_id", "account"."avatar_remote_url", "account"."header_media_attachment_id", "account"."header_remote_url", "account"."display_name", "account"."emojis", "account"."fields", "account"."fields_raw", "account"."note", "account"."note_raw", "account"."memorial", "account"."also_known_as", "account"."moved_to_account_id", "account"."bot", "account"."reason", "account"."locked", "account"."discoverable", "account"."privacy", "account"."sensitive", "account"."language", "account"."status_content_type", "account"."custom_css", "account"."uri", "account"."url", "account"."inbox_uri", "account"."shared_inbox_uri", "account"."outbox_uri", "account"."following_uri", "account"."followers_uri", "account"."featured_collection_uri", "account"."actor_type", "account"."private_key", "account"."public_key", "account"."public_key_uri", "account"."public_key_expires_at", "account"."sensitized_at", "account"."silenced_at", "account"."suspended_at", "account"."hide_collections", "account"."suspension_origin", "account"."enable_rss" FROM "accounts" AS "account" WHERE ("account"."id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx')
timestamp="2024-01-15T22:23:37.371Z" func=bundb.queryHook.AfterQuery level=TRACE duration=4.300221ms query=INSERT INTO "follows" AS "follow" ("id", "created_at", "updated_at", "uri", "account_id", "target_account_id", "show_reblogs", "notify") VALUES ('01HM7GZ9MZFVAG20GPJ5KSHVJV', DEFAULT, DEFAULT, 'https://norden.social/d3cac7e0-e2d8-4bf8-b997-c157bfxxxxxx', '01JVNKXFBJ4DAVWPPAF3xxxxxx', '01GS55SW7VWYN3BFRYCXxxxxxx', TRUE, FALSE) ON CONFLICT ("account_id","target_account_id") DO UPDATE set "uri" = 'https://norden.social/d3cac7e0-e2d8-4bf8-b997-c157bfxxxxxx' RETURNING "created_at", "updated_at"
timestamp="2024-01-15T22:23:37.372Z" func=bundb.queryHook.AfterQuery level=TRACE duration=679.17µs query=DELETE FROM "follow_requests" WHERE ("id" = '01HM7GZ9MZFVAG20GPJ5KSHVJV')
timestamp="2024-01-15T22:23:37.377Z" func=bundb.queryHook.AfterQuery level=TRACE duration=4.983362ms query=SELECT "id" FROM "notifications" WHERE ("notification_type" IN ('follow_request')) AND ("target_account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("origin_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx')
timestamp="2024-01-15T22:23:37.378Z" func=bundb.queryHook.AfterQuery level=TRACE duration=538.426µs query=SELECT "notification"."id", "notification"."created_at", "notification"."updated_at", "notification"."notification_type", "notification"."target_account_id", "notification"."origin_account_id", "notification"."status_id", "notification"."read" FROM "notifications" AS "notification" WHERE ("notification"."id" = '01HM7GZ9N7SWR61XJD4RV6XHYC')
timestamp="2024-01-15T22:23:37.379Z" func=bundb.queryHook.AfterQuery level=TRACE duration=817.045µs query=DELETE FROM "notifications" WHERE ("id" IN ('01HM7GZ9N7SWR61XJD4RV6XHYC'))
timestamp="2024-01-15T22:23:37.379Z" func=workers.(*Processor).ProcessFromClientAPI level=INFO activityType=Accept objectType=Follow fromAccount=XXXX model={ID=01HM7GZ9MZFVAG20GPJ5KSHVJV CreatedAt="2024-01-15 22:23:37.367937 +0000 UTC" UpdatedAt="2024-01-15 22:23:37.367937 +0000 UTC" URI=https://norden.social/d3cac7e0-e2d8-4bf8-b997-c157bfxxxxxx AccountID=01JVNKXFBJ4DAVWPPAF3xxxxxx Account={ID=01JVNKXFBJ4DAVWPPAF3xxxxxx CreatedAt="2022-12-17 09:22:14.596562 +0000 UTC" UpdatedAt="2024-01-15 16:01:13.158624 +0000 UTC" FetchedAt="2024-01-15 16:01:13.158612 +0000 UTC" Username=XXXX Domain=norden.social AvatarMediaAttachmentID=… AvatarMediaAttachment=nil AvatarRemoteURL=… HeaderMediaAttachmentID=… HeaderMediaAttachment=nil HeaderRemoteURL=… DisplayName=… EmojiIDs=nil Emojis=nil Fields=nil FieldsRaw=nil Note="………" NoteRaw="" Memorial=false AlsoKnownAs="" MovedToAccountID="" Bot=false Reason="" Locked=false Discoverable=true Privacy="" Sensitive=false Language=en StatusContentType="" CustomCSS="" URI=https://norden.social/users/XXXX URL=https://norden.social/@XXXX InboxURI=https://norden.social/users/XXXX/inbox SharedInboxURI=https://norden.social/inbox OutboxURI=https://norden.social/users/XXXX/outbox FollowingURI=https://norden.social/users/XXXX/following FollowersURI=https://norden.social/users/XXXX/followers FeaturedCollectionURI=https://norden.social/users/XXXX/collections/featured ActorType=Person PrivateKey=nil PublicKey={………} PublicKeyURI=https://norden.social/users/XXXX#main-key PublicKeyExpiresAt="0001-01-01 00:00:00 +0000 UTC" SensitizedAt="0001-01-01 00:00:00 +0000 UTC" SilencedAt="0001-01-01 00:00:00 +0000 UTC" SuspendedAt="0001-01-01 00:00:00 +0000 UTC" HideCollections=false SuspensionOrigin="" EnableRSS=false} TargetAccountID=01GS55SW7VWYN3BFRYCXxxxxxx TargetAccount={………
timestamp="2024-01-15T22:23:37.382Z" func=bundb.queryHook.AfterQuery level=TRACE duration=3.399594ms query=SELECT "follow"."id", "follow"."created_at", "follow"."updated_at", "follow"."uri", "follow"."account_id", "follow"."target_account_id", "follow"."show_reblogs", "follow"."notify" FROM "follows" AS "follow" WHERE ("account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("target_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx')
timestamp="2024-01-15T22:23:37.383Z" func=bundb.queryHook.AfterQuery level=TRACE duration=402.812µs query=SELECT "follow"."id", "follow"."created_at", "follow"."updated_at", "follow"."uri", "follow"."account_id", "follow"."target_account_id", "follow"."show_reblogs", "follow"."notify" FROM "follows" AS "follow" WHERE ("account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') AND ("target_account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx')
timestamp="2024-01-15T22:23:37.383Z" func=bundb.queryHook.AfterQuery level=TRACE duration=287.799µs query=SELECT "follow_request"."id", "follow_request"."created_at", "follow_request"."updated_at", "follow_request"."uri", "follow_request"."account_id", "follow_request"."target_account_id", "follow_request"."show_reblogs", "follow_request"."notify" FROM "follow_requests" AS "follow_request" WHERE ("account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("target_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx')
timestamp="2024-01-15T22:23:37.384Z" func=bundb.queryHook.AfterQuery level=TRACE duration=668.701µs query=SELECT "block"."id", "block"."created_at", "block"."updated_at", "block"."uri", "block"."account_id", "block"."target_account_id" FROM "blocks" AS "block" WHERE ("block"."account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("block"."target_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx')
timestamp="2024-01-15T22:23:37.385Z" func=bundb.queryHook.AfterQuery level=TRACE duration=328.03µs query=SELECT "block"."id", "block"."created_at", "block"."updated_at", "block"."uri", "block"."account_id", "block"."target_account_id" FROM "blocks" AS "block" WHERE ("block"."account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') AND ("block"."target_account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx')
timestamp="2024-01-15T22:23:37.386Z" func=bundb.queryHook.AfterQuery level=TRACE duration=492.905µs query=SELECT "account_note"."id", "account_note"."created_at", "account_note"."updated_at", "account_note"."account_id", "account_note"."target_account_id", "account_note"."comment" FROM "account_notes" AS "account_note" WHERE ("account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("target_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx')
timestamp="2024-01-15T22:23:37.386Z" func=server.glob..func1.Logger.func13.1 level=INFO latency="23.116771ms" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/115.0" method=POST statusCode=200 path=/api/v1/follow_requests/01JVNKXFBJ4DAVWPPAF3xxxxxx/authorize clientIP=XXX requestID=jcdkj3wd04000s6jsrn0 msg="OK: wrote 177B"
timestamp="2024-01-15T22:23:37.392Z" func=bundb.queryHook.AfterQuery level=TRACE duration=12.086487ms query=SELECT "notification"."id", "notification"."created_at", "notification"."updated_at", "notification"."notification_type", "notification"."target_account_id", "notification"."origin_account_id", "notification"."status_id", "notification"."read" FROM "notifications" AS "notification" WHERE ("notification_type" = 'follow_request') AND ("target_account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("origin_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') AND ("status_id" = '')
timestamp="2024-01-15T22:23:37.395Z" func=bundb.queryHook.AfterQuery level=TRACE duration=3.28392ms query=SELECT "notification"."id", "notification"."created_at", "notification"."updated_at", "notification"."notification_type", "notification"."target_account_id", "notification"."origin_account_id", "notification"."status_id", "notification"."read" FROM "notifications" AS "notification" WHERE ("notification_type" = 'follow') AND ("target_account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("origin_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') AND ("status_id" = '')
timestamp="2024-01-15T22:23:37.397Z" func=bundb.queryHook.AfterQuery level=TRACE duration=1.529437ms query=INSERT INTO "notifications" ("id", "created_at", "updated_at", "notification_type", "target_account_id", "origin_account_id", "status_id", "read") VALUES ('01HM7KJ6XKG5TVN4BKXS5V69G2', DEFAULT, DEFAULT, 'follow', '01GS55SW7VWYN3BFRYCXxxxxxx', '01JVNKXFBJ4DAVWPPAF3xxxxxx', DEFAULT, DEFAULT) RETURNING "created_at", "updated_at", "status_id", "read"
timestamp="2024-01-15T22:23:37.398Z" func=bundb.queryHook.AfterQuery level=TRACE duration=1.104513ms query=SELECT "media_attachment"."id", "media_attachment"."created_at", "media_attachment"."updated_at", "media_attachment"."status_id", "media_attachment"."url", "media_attachment"."remote_url", "media_attachment"."type", "media_attachment"."original_width", "media_attachment"."original_height", "media_attachment"."original_size", "media_attachment"."original_aspect", "media_attachment"."original_duration", "media_attachment"."original_framerate", "media_attachment"."original_bitrate", "media_attachment"."small_width", "media_attachment"."small_height", "media_attachment"."small_size", "media_attachment"."small_aspect", "media_attachment"."focus_x", "media_attachment"."focus_y", "media_attachment"."account_id", "media_attachment"."description", "media_attachment"."scheduled_status_id", "media_attachment"."blurhash", "media_attachment"."processing", "media_attachment"."file_path", "media_attachment"."file_content_type", "media_attachment"."file_file_size", "media_attachment"."file_updated_at", "media_attachment"."thumbnail_path", "media_attachment"."thumbnail_content_type", "media_attachment"."thumbnail_file_size", "media_attachment"."thumbnail_updated_at", "media_attachment"."thumbnail_url", "media_attachment"."thumbnail_remote_url", "media_attachment"."avatar", "media_attachment"."header", "media_attachment"."cached" FROM "media_attachments" AS "media_attachment" WHERE ("media_attachment"."id" = '01Q3AE0QZTBAXZ8N4FV1xxxxxx')
timestamp="2024-01-15T22:23:37.398Z" func=bundb.queryHook.AfterQuery level=TRACE duration=401.213µs query=SELECT "media_attachment"."id", "media_attachment"."created_at", "media_attachment"."updated_at", "media_attachment"."status_id", "media_attachment"."url", "media_attachment"."remote_url", "media_attachment"."type", "media_attachment"."original_width", "media_attachment"."original_height", "media_attachment"."original_size", "media_attachment"."original_aspect", "media_attachment"."original_duration", "media_attachment"."original_framerate", "media_attachment"."original_bitrate", "media_attachment"."small_width", "media_attachment"."small_height", "media_attachment"."small_size", "media_attachment"."small_aspect", "media_attachment"."focus_x", "media_attachment"."focus_y", "media_attachment"."account_id", "media_attachment"."description", "media_attachment"."scheduled_status_id", "media_attachment"."blurhash", "media_attachment"."processing", "media_attachment"."file_path", "media_attachment"."file_content_type", "media_attachment"."file_file_size", "media_attachment"."file_updated_at", "media_attachment"."thumbnail_path", "media_attachment"."thumbnail_content_type", "media_attachment"."thumbnail_file_size", "media_attachment"."thumbnail_updated_at", "media_attachment"."thumbnail_url", "media_attachment"."thumbnail_remote_url", "media_attachment"."avatar", "media_attachment"."header", "media_attachment"."cached" FROM "media_attachments" AS "media_attachment" WHERE ("media_attachment"."id" = '01PDZ6M5F2026ARVNPD6xxxxxx')
timestamp="2024-01-15T22:23:37.399Z" func=bundb.queryHook.AfterQuery level=TRACE duration=722.983µs query=SELECT "id" FROM "follows" WHERE ("target_account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') ORDER BY "id" DESC
timestamp="2024-01-15T22:23:37.399Z" func=bundb.queryHook.AfterQuery level=TRACE duration=260.678µs query=SELECT "id" FROM "follows" WHERE ("account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') ORDER BY "id" DESC
timestamp="2024-01-15T22:23:37.401Z" func=bundb.queryHook.AfterQuery level=TRACE duration=1.66519ms query=SELECT count(*) FROM "statuses" AS "status" WHERE ("status"."account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx')
timestamp="2024-01-15T22:23:37.402Z" func=bundb.queryHook.AfterQuery level=TRACE duration=440.433µs query=SELECT "status"."created_at" FROM "statuses" AS "status" WHERE ("status"."account_id" = '01JVNKXFBJ4DAVWPPAF3xxxxxx') ORDER BY "status"."id" DESC LIMIT 1
timestamp="2024-01-15T22:23:37.403Z" func=streaming.(*Module).writeToWSConn level=TRACE username=mirabilos streamID=01YXY1WXH39YWYWP2ZKE45A7YJ msg="writing message to websocket: &{Stream:[user] Event:notification Payload:{\"id\":\"01HM7KJ6XKG5TVN4BKXS5V69G2\",\"type\":\"follow\",………
timestamp="2024-01-15T22:23:37.403Z" func=federation.(*federatingActor).Send level=INFO requestID=jcdkj3wd04000s6jsrn0 msg="send activity Accept via outbox https://toot.mirbsd.org/users/mirabilos/outbox"
timestamp="2024-01-15T22:23:37.404Z" func=federatingdb.(*federatingDB).NewID level=DEBUG newID="{\"@context\":\"https://www.w3.org/ns/activitystreams\",\"actor\":\"https://toot.mirbsd.org/users/mirabilos\",\"object\":{\"actor\":\"https://norden.social/users/XXXX\",\"id\":\"https://norden.social/d3cac7e0-e2d8-4bf8-b997-c157bfxxxxxx\",\"object\":\"https://toot.mirbsd.org/users/mirabilos\",\"to\":\"https://toot.mirbsd.org/users/mirabilos\",\"type\":\"Follow\"},\"to\":\"https://norden.social/users/XXXX\",\"type\":\"Accept\"}" requestID=jcdkj3wd04000s6jsrn0 msg="entering NewID"
timestamp="2024-01-15T22:23:37.405Z" func=federatingdb.(*federatingDB).Create level=TRACE create="{\"@context\":\"https://www.w3.org/ns/activitystreams\",\"actor\":\"https://toot.mirbsd.org/users/mirabilos\",\"id\":\"https://toot.mirbsd.org/01HT1Z8PYX20DJEFVMWW6XZ6DH\",\"object\":{\"actor\":\"https://norden.social/users/XXXX\",\"id\":\"https://norden.social/d3cac7e0-e2d8-4bf8-b997-c157bfxxxxxx\",\"object\":\"https://toot.mirbsd.org/users/mirabilos\",\"to\":\"https://toot.mirbsd.org/users/mirabilos\",\"type\":\"Follow\"},\"to\":\"https://norden.social/users/XXXX\",\"type\":\"Accept\"}" requestID=jcdkj3wd04000s6jsrn0 msg="entering Create"
timestamp="2024-01-15T22:23:37.405Z" func=uris.IsUserPath level=DEBUG id="https://toot.mirbsd.org/users/mirabilos" requestID=jcdkj3wd04000s6jsrn0 msg="entering Get"
timestamp="2024-01-15T22:23:37.410Z" func=httpclient.(*Client).DoSigned level=INFO method=POST url=https://norden.social/inbox requestID=jcdkj3wd04000s6jsrn0 pubKeyID=https://toot.mirbsd.org/users/mirabilos/main-key msg="performing request"
timestamp="2024-01-15T22:23:37.427Z" func=server.glob..func1.Logger.func13.1 level=INFO latency="6.48µs" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/115.0" method=OPTIONS statusCode=204 path=/api/v1/follow_requests clientIP=XXX requestID=tcdkj3wd04001a8dbk5g msg="No Content: wrote 0B"
timestamp="2024-01-15T22:23:37.480Z" func=bundb.queryHook.AfterQuery level=TRACE duration=978.139µs query=SELECT "token"."id", "token"."created_at", "token"."updated_at", "token"."client_id", "token"."user_id", "token"."redirect_uri", "token"."scope", "token"."code", "token"."code_challenge", "token"."code_challenge_method", "token"."code_create_at", "token"."code_expires_at", "token"."access", "token"."access_create_at", "token"."access_expires_at", "token"."refresh", "token"."refresh_create_at", "token"."refresh_expires_at" FROM "tokens" AS "token" WHERE ("access" = 'XxXxX')
timestamp="2024-01-15T22:23:37.481Z" func=api.(*Client).Route.TokenCheck.func1 level=TRACE requestID=0we3j3wd04001n2csapg msg="authenticated user xxx with bearer token, scope is read write follow push"
timestamp="2024-01-15T22:23:37.481Z" func=api.(*Client).Route.TokenCheck.func1 level=TRACE requestID=0we3j3wd04001n2csapg msg="authenticated client xxx with bearer token, scope is read write follow push"
timestamp="2024-01-15T22:23:37.482Z" func=bundb.queryHook.AfterQuery level=TRACE duration=515.936µs query=SELECT "id" FROM "follow_requests" WHERE ("target_account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') ORDER BY "id" DESC
timestamp="2024-01-15T22:23:37.482Z" func=server.glob..func1.Logger.func13.1 level=INFO latency="2.358242ms" userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/115.0" method=GET statusCode=200 path=/api/v1/follow_requests clientIP=XXX requestID=0we3j3wd04001n2csapg msg="OK: wrote 26B"
timestamp="2024-01-15T22:23:37.545Z" func=server.glob..func1.Logger.func13.1 level=INFO latency="414.543µs" userAgent="http.rb/5.1.1 (Mastodon/4.2.3; +https://norden.social/)" method=GET statusCode=200 path=/users/mirabilos/main-key clientIP=XXX pubKeyID=https://norden.social/actor#main-key requestID=94e3j3wd04001yqzn39g msg="OK: wrote 557B"
timestamp="2024-01-15T22:23:37.593Z" func=federation.(*Federator).AuthenticateFederatedRequest level=TRACE requestedUsername=mirabilos pubKeyID=https://norden.social/actor#main-key requestID=f4e3j3wd040016kxatx0 msg="public key is remote, checking if we need to dereference"
timestamp="2024-01-15T22:23:37.596Z" func=bundb.queryHook.AfterQuery level=TRACE duration=1.984189ms query=SELECT "account"."id", "account"."created_at", "account"."updated_at", "account"."fetched_at", "account"."username", "account"."domain", "account"."avatar_media_attachment_id", "account"."avatar_remote_url", "account"."header_media_attachment_id", "account"."header_remote_url", "account"."display_name", "account"."emojis", "account"."fields", "account"."fields_raw", "account"."note", "account"."note_raw", "account"."memorial", "account"."also_known_as", "account"."moved_to_account_id", "account"."bot", "account"."reason", "account"."locked", "account"."discoverable", "account"."privacy", "account"."sensitive", "account"."language", "account"."status_content_type", "account"."custom_css", "account"."uri", "account"."url", "account"."inbox_uri", "account"."shared_inbox_uri", "account"."outbox_uri", "account"."following_uri", "account"."followers_uri", "account"."featured_collection_uri", "account"."actor_type", "account"."private_key", "account"."public_key", "account"."public_key_uri", "account"."public_key_expires_at", "account"."sensitized_at", "account"."silenced_at", "account"."suspended_at", "account"."hide_collections", "account"."suspension_origin", "account"."enable_rss" FROM "accounts" AS "account" WHERE ("account"."public_key_uri" = 'https://norden.social/actor#main-key')
timestamp="2024-01-15T22:23:37.596Z" func=federation.(*Federator).derefPubKey level=TRACE requestedUsername=mirabilos pubKeyID=https://norden.social/actor#main-key requestID=f4e3j3wd040016kxatx0 msg="public key cached and up to date, no dereference needed"
timestamp="2024-01-15T22:23:37.597Z" func=federation.verifyAuth level=TRACE requestedUsername=mirabilos pubKeyID=https://norden.social/actor#main-key requestID=f4e3j3wd040016kxatx0 msg="authenticated PASSED with rsa-sha256"
timestamp="2024-01-15T22:23:37.597Z" func=bundb.queryHook.AfterQuery level=TRACE duration=605.688µs query=SELECT "block"."id", "block"."created_at", "block"."updated_at", "block"."uri", "block"."account_id", "block"."target_account_id" FROM "blocks" AS "block" WHERE ("block"."account_id" = '01GS55SW7VWYN3BFRYCXxxxxxx') AND ("block"."target_account_id" = '01AF6ZDNTQTW5CJNNFAWHF2RVS')
timestamp="2024-01-15T22:23:37.599Z" func=server.glob..func1.Logger.func13.1 level=INFO latency="5.188656ms" userAgent="http.rb/5.1.1 (Mastodon/4.2.3; +https://norden.social/)" method=GET statusCode=200 path=/users/mirabilos clientIP=XXX pubKeyID=https://norden.social/actor#main-key requestID=f4e3j3wd040016kxatx0 msg="OK: wrote 2.25kiB"

I trimmed some identifiable or irrelevant (websocket comms) parts.

(interestingly enough, either GtS or my log receiver cuts off extremely long lines, such as within TargetAccount={… before trimming; I hope nothing of value was after that)

Does this help?

Looking at my followers afterwards, both that person and another user from that instance now follow me.

[tsmethurst]

Mmm I don't see anything wrong with those logs. Here's what's going on:

1. You accept the follow request in your client, which POSTs to /api/v1/follow_requests/01JVNKXFBJ4DAVWPPAF3xxxxxx/authorize
2. The follow request is converted to a follow and inserted into the follows table.
3. The follow request is deleted from the follow request table (since the request has now been accepted).
4. The accept message is passed through to the processor to process side effects asynchronously -- func=workers.(*Processor).ProcessFromClientAPI level=INFO activityType=Accept objectType=Follow
5. A check is performed to see if any previous notification exists for this follow request and follow. If a follow request notif existed, it would be removed. If a follow notif existed, I can't remember what would happen, but something sensible probably.
6. A notification gets created for the new follow.
7. The notification gets streamed via websockets.
8. An Accept activity gets created to send via your Outbox to the person who sent you the follow request -- send activity Accept via outbox https://toot.mirbsd.org/users/mirabilos/outbox
9. HTTP signature handshaking, yadda yadda.

That all looks OK to me!

[mirabilos]

tobi dixit:

Mmm I don't see anything wrong with those logs. Here's what's going on:

[… detailed breakdown …] Yeah, that’s what I figured; thanks for having a look and explaining.

That all looks OK to me!

Indeed. He’s also still following me as of today, according to the GtS database at least. We’ll see. Thanks, //mirabilos

[mirabilos]

And today (18th) again a follow request from that user.

I reached out to him and asked again.

[mirabilos]

Hah, and today the user is gone from my followers list again.

I also reached out to their instance admin. At this point I don’t think we can do anything to debug that from our sides.

[tsmethurst]

Honestly I think they may be just following and unfollowing you for whatever reason. I can't think of anything else that would remove the follow like that apart from either them unfollowing you, them blocking you, you blocking them, or your instance processing a delete message for their account.

[mirabilos]

OK.

Or redoing a failed account migration over and over? I saw multiple follow requests from migratory people, some time ago.

But, yeah. Unless they respond, I think that’s it for that.

---

Now the other issue, where I have notifications of follow requests but not the corresponding follow request in that table, do you want to follow up on/debug that?

[mirabilos]

Got another case where someone is sending me follow requests that only show up in notifications but not in follow requests.

[tsmethurst]

This could happen in cases where someone sends a Follow and then immediately sends an Undo on the follow (ie., they changed their mind). If this is what happened, you may be able to see this in the logs.

[mirabilos]

tobi dixit:

This could happen in cases where someone sends a Follow and then immediately sends an Undo on the follow (ie., they changed their mind).

Yes, but not twice?

If this is what happened, you may be able to see this in the logs.

Not really, follow/unfollow are just POST to …/inbox without any distinguishing features. I do see two instances of two very quick POSTs (two seconds apart) from that user in my logs, and nothing else. Hm, might still be even twice.

[tsmethurst]

Ah, so you do see a follow POST and then an unfollow POST? Or am I misinterpreting?

[mirabilos]

tobi dixit:

Ah, so you do see a follow POST and then an unfollow POST? Or am I misinterpreting?

I see two inbox POSTs, I have no idea whether they are follow, unfollow, or something else entirely.

[tsmethurst]

Ah right, what I mean is that you may in the logs be able to see something like "processing from fediAPI" or something along this lines, with a brief bit of information about what's being processed. Can't remember the exact format.

But tbh I you might just be getting follow (requested)/unfollow (requested) again. Not sure if there's actually a bug here.

[mirabilos]

tobi dixit:

Ah right, what I mean is that you may in the logs be able to see something like "processing from fediAPI" or something along this lines, with a brief bit of information about what's being processed. Can't remember the exact format.

Aah, on a separate line. Got it. The first request does have this following: timestamp="2024-01-29T16:57:12.913Z" func=workers.(*Processor).ProcessFromFediAPI level=INFO activityType=Create objectType=Follow toAccount=mirabilos requestID=sh6jenmd04000s82p3t0 msg="processing from fedi API" The second request has nothing following it (even a full 8s pause), though.