search

toddsundsted / ktistec

Single user ActivityPub (https://www.w3.org/TR/activitypub/) server.
GNU Affero General Public License v3.0
364 stars 20 forks source link

POSTs to my server inbox always require two attempts #110

Closed oztourer closed 3 weeks ago

oztourer commented 2 months ago

I see in my nginx logs that fediverse instances attempt to post to my ktistec instance using a URL which is not supported, receive from ktistec an error 409, and then post to the correct URL. The first attempt is always to /actors/<user>/inbox but on receiving HTTP error 409 the sending instance then tries /<user>/inbox and the POST succeeds. A redacted extract from nginx.log:

   <ip> - - [13/Aug/2024:12:54:33 +1000] "POST /actors/<user>/inbox HTTP/1.1" 409 
   <ip> - - [13/Aug/2024:12:54:38 +1000] "POST /<user>/inbox HTTP/1.1" 202

The sender does not appear to learn from this error and subsequent posts repeat the sequence of attempting both URLs.

I presume that both URLs are valid within the ActivityPub protocol, but is there a way to advertise the supported one through webfinger, or as a better option could ktistec accept the additional URL /actors/<user>/inbox as valid for POST?

toddsundsted commented 2 months ago

@oztourer is it possible to get the ktistec server logs for those requests. ktistec doesn't ever, to my knowledge, return a 202 status code. it does return a 409 when it has already received a posted activity (some servers seem to resend activities if ktistec takes to long to respond).

oztourer commented 2 months ago

It seems I have been misreading the nginx logs, which currently do not give the full URL. The log lines "POST /<user>/inbox" do not appear to relate to ktistec - I am also running a snac container which does not log these POSTs but as I do not see such entries in the ktistec log I think they must relate to snac. (Shoutout to ktistec: I use that almost exclusively now and should probably shut down the snac instance).

What is perhaps of interest is that the log pairs shown in my first post recur regularly as I have subscribed to many of the same users on both snac and ktistec. The paired POSTs come in at almost the same time and snac gives them all a 202 response but ktistec seems to have issues with many of them, assuming that error 409 is a fail. Here is a longer list of nginx log entries followed by the relevant section of the ktistec log. I am running everything in separate Docker containers and I have checked that their internal date/times are aligned. The nginx log entries are local time (UTC +1000), the ktistec logs are UTC. I can PM the actual logs if that would be useful.

nginx (mostly just the POST entries, including snac:

[13/Aug/2024:12:28:42 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "buzzrelay/0.1.0 (+https://relay.fedi.buzz)" 
[13/Aug/2024:12:29:10 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:29:14 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.1.1 (Mastodon/4.2.10; +https://social.vivaldi.net/)"
[13/Aug/2024:12:30:38 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:30:45 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:30:53 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 200 12 "-" "Mastodon/4.3.0-nightly.2024-08-12 (http.rb/5.2.0; +https://mastodon.social/)"
[13/Aug/2024:12:31:04 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "Mastodon/4.3.0-nightly.2024-08-12 (http.rb/5.2.0; +https://mastodon.social/)"
[13/Aug/2024:12:31:53 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 200 12 "-" "Mastodon/4.3.0-nightly.2024-08-12 (http.rb/5.2.0; +https://mastodon.social/)"
[13/Aug/2024:12:32:04 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "Mastodon/4.3.0-nightly.2024-08-12 (http.rb/5.2.0; +https://mastodon.social/)"
[13/Aug/2024:12:32:07 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:32:14 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:32:20 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "Mastodon/4.3.0-alpha.5 (http.rb/5.2.0; +https://aus.social/)"
[13/Aug/2024:12:33:44 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:33:50 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:35:17 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:35:22 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:36:45 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:36:51 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:39:23 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:39:29 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:39:34 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:39:40 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:41:01 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:41:07 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:42:16 +1000] "GET /api/v3/site HTTP/1.1" 404 25572 "-" "lemmy-stats-crawler"
[13/Aug/2024:12:42:16 +1000] "GET /nodeinfo/2.0.json HTTP/1.1" 404 25572 "-" "lemmy-stats-crawler"
[13/Aug/2024:12:42:16 +1000] "GET /api/v3/federated_instances HTTP/1.1" 404 25572 "-" "lemmy-stats-crawler"
[13/Aug/2024:12:42:18 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "facebookexternalua"
[13/Aug/2024:12:42:28 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:42:33 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:42:59 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 200 12 "-" "http.rb/5.1.1 (Mastodon/4.2.10; +https://mastodon.bsd.cafe/)"
[13/Aug/2024:12:43:59 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:44:05 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:45:30 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:45:35 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:46:56 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
[13/Aug/2024:12:47:02 +1000] "POST /gizmo/inbox HTTP/1.1" 202 5 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"
...
...
[13/Aug/2024:13:05:45 +1000] "GET / HTTP/1.1" 200 152 "-" "Poduptime/Production from https://fediverse.observer"
[13/Aug/2024:13:06:36 +1000] "POST /actors/gizmo/inbox HTTP/1.1" 409 18 "-" "http.rb/5.0.2 (Mastodon/3.4.9001; +https://red.niboe.info/)"

ktistec, most GETs removed. UTC timestamps, 10 hours off from nginx:

 2024-08-13 02:28:42 UTC 409 POST /actors/gizmo/inbox 5.59ms
 2024-08-13 02:28:54 UTC 200 GET /tags/darktable?page=3 234.68ms
 2024-08-13T02:28:53.978615Z NOTICE - database: Slow query [   192.316ms] -- SELECT "o"."type","o"."id","o"."blocked_at","o"."created_at","o"."updated_at","o"."deleted_at","o"."type","o"."iri","o"."visible","o"."published","o"."attributed_to_iri","o"."in_reply_to_iri","o"."replies_iri","o"."thread","o"."to","o"."cc","o"."name","o"."summary","o"."content","o"."media_type","o"."source","o"."attachments","o"."urls" FROM objects AS o JOIN tags AS t ON t.subject_iri = o.iri AND t.type = "Tag::Hashtag" JOIN actors AS a ON a.iri = o.attributed_to_iri WHERE t.name = ? AND o.created_at > ? AND o.published IS NOT NULL AND o.deleted_at IS NULL AND o.blocked_at IS NULL AND a.deleted_at IS NULL AND a.blocked_at IS NULL ORDER BY o.published DESC LIMIT ? OFFSET ? -- args: ["darktable", 1970-01-01 00:00:00.0 UTC, 11, 20]
 2024-08-13T02:28:53.978633Z NOTICE - database: [{0, "SEARCH t USING INDEX idx_tags_type_name (type=? AND name=?)"}, {0, "SEARCH o USING INDEX idx_objects_iri (iri=?)"}, {0, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "USE TEMP B-TREE FOR ORDER BY"}]
 2024-08-13 02:29:02 UTC 200 GET /apple-touch-icon.png 92.03µs
 2024-08-13 02:29:10 UTC 409 POST /actors/gizmo/inbox 5.96ms
 2024-08-13 02:30:36 UTC 200 GET /actors/gizmo 17.55ms
 2024-08-13 02:30:37 UTC 200 GET /search 748.02µs
 2024-08-13 02:30:38 UTC 409 POST /actors/gizmo/inbox 5.03ms
 2024-08-13 02:30:45 UTC 200 GET /search?query=https%3A%2F%2Fpkm.social%2Fusers%2Fzsviczian 1398.7ms
 2024-08-13 02:30:46 UTC 200 GET /apple-touch-icon.png 118.1µs
 2024-08-13 02:30:53 UTC 200 POST /actors/gizmo/inbox 134.37ms
 2024-08-13 02:31:37 UTC 200 GET /apple-touch-icon.png 83.6µs
 2024-08-13 02:31:40 UTC 200 GET /actors/gizmo 14.82ms
 2024-08-13 02:31:40 UTC 200 GET /favicon.ico 99.36µs
 2024-08-13 02:31:43 UTC 200 GET /actors/gizmo/following 8.48ms
 2024-08-13 02:31:53 UTC 200 POST /actors/gizmo/inbox 113.61ms
 2024-08-13 02:31:56 UTC 200 GET /apple-touch-icon.png 75.4µs
 2024-08-13 02:32:07 UTC 409 POST /actors/gizmo/inbox 6.28ms
 2024-08-13 02:32:23 UTC 200 GET /apple-touch-icon.png 71.57µs
 2024-08-13 02:32:28 UTC 200 GET /remote/actors/74288 9.95ms
 2024-08-13 02:32:45 UTC 200 GET /actors/gizmo/following?page=2 8.55ms
 2024-08-13 02:32:48 UTC 200 GET /apple-touch-icon.png 68.22µs
 2024-08-13 02:32:51 UTC 200 GET /actors/gizmo/following?page=3 6.4ms
 2024-08-13 02:33:44 UTC 409 POST /actors/gizmo/inbox 5.06ms
 2024-08-13 02:33:45 UTC 200 POST /remote/actors/7599/refresh 3.71ms
 2024-08-13 02:33:45 UTC 200 GET /stream/tags/darktable 291568.51ms
 2024-08-13 02:33:45 UTC 200 GET /stream/actor/homepage 189301.87ms
 2024-08-13 02:34:13 UTC 200 POST /remote/actors/10476/refresh 3.85ms
 2024-08-13 02:34:14 UTC 200 GET /stream/actor/homepage 61297.68ms
 2024-08-13 02:35:17 UTC 409 POST /actors/gizmo/inbox 5.12ms
 2024-08-13 02:35:32 UTC 200 GET /settings 1.41ms
 2024-08-13 02:35:32 UTC 200 GET /dist/settings.bundle.js 11.73ms
 2024-08-13 02:35:32 UTC 200 GET /uploads/099e330c/f6dc/4f7b/1.jpg 97.3µs
 2024-08-13 02:35:32 UTC 200 GET /uploads/5ffbeffa/ba05/483b/1.png 12.89ms
 Exception: Closed stream (IO::Error)
   from ???
   ...
   from ???
 2024-08-13T02:35:32.638897Z  ERROR - http.server: Unhandled exception on HTTP::Handler
 Closed stream (IO::Error)
   from ???
   ...
   from ???
 Exception: Closed stream (IO::Error)
   from ???
   ...
   from ???
 2024-08-13T02:35:32.645486Z  ERROR - http.server: Unhandled exception on HTTP::Handler
 Closed stream (IO::Error)
   from ???
   ...
   from ???
 2024-08-13 02:36:14 UTC 200 GET /stream/tags/darktable 156137.69ms
 2024-08-13 02:36:45 UTC 409 POST /actors/gizmo/inbox 4.9ms
 2024-08-13 02:37:14 UTC 200 GET /stream/actor/homepage?page=5 202177.29ms
 2024-08-13 02:39:23 UTC 409 POST /actors/gizmo/inbox 4.31ms
 2024-08-13 02:39:34 UTC 409 POST /actors/gizmo/inbox 4.49ms
 2024-08-13 02:41:01 UTC 409 POST /actors/gizmo/inbox 4.97ms
 2024-08-13 02:42:16 UTC 404 GET /api/v3/site 6.41ms
 2024-08-13 02:42:16 UTC 404 GET /nodeinfo/2.0.json 6.35ms
 2024-08-13 02:42:16 UTC 404 GET /api/v3/federated_instances 6.62ms
 2024-08-13 02:42:28 UTC 409 POST /actors/gizmo/inbox 4.5ms
 2024-08-13 02:42:59 UTC 200 POST /actors/gizmo/inbox 4089.09ms
 2024-08-13 02:43:59 UTC 409 POST /actors/gizmo/inbox 4.62ms
 2024-08-13 02:45:30 UTC 409 POST /actors/gizmo/inbox 7.29ms
 2024-08-13 02:46:56 UTC 409 POST /actors/gizmo/inbox 4.68ms
 2024-08-13 02:47:19 UTC 200 GET /.well-known/webfinger?resource=acct%3Agizmo%40fedi.weebyte.com 7.2ms
 2024-08-13 02:47:39 UTC 200 GET /actors/gizmo 9.91ms
 2024-08-13 02:47:39 UTC 200 GET /3rd/semantic-2.4.1.min.css 15.14ms
 Unhandled exception in spawn: Error while flushing data to the client (HTTP::Server::ClientError)
   from ???
   ...
   from ???
 Caused by: Error writing to socket (#<TCPSocket:0x7f154b0add20>): Broken pipe (IO::Error)
   from ???
   ...
   from ???
 2024-08-13 02:47:39 UTC 200 GET /3rd/themes/default/assets/fonts/Lato-Regular.woff2 107.78µs
 2024-08-13 02:47:39 UTC 200 GET /3rd/themes/default/assets/fonts/icons.woff2 196.58µs
 2024-08-13 02:48:27 UTC 409 POST /actors/gizmo/inbox 5.1ms
 2024-08-13 02:49:55 UTC 409 POST /actors/gizmo/inbox 5.1ms
 2024-08-13 02:51:02 UTC 200 GET /.well-known/webfinger?resource=acct:gizmo@fedi.weebyte.com 881.04µs
 ... more GETs ...
 2024-08-13 02:51:27 UTC 200 POST /actors/gizmo/inbox 94.23ms
 2024-08-13 02:51:39 UTC 200 GET /stream/actor/homepage 240007.33ms
 2024-08-13 02:51:51 UTC 200 GET /stream/actor/homepage 240011.5ms
 2024-08-13 02:52:13 UTC 400 POST /actors/gizmo/inbox 74.6ms
 2024-08-13 02:53:03 UTC 409 POST /actors/gizmo/inbox 4.48ms
  2024-08-13 02:53:53 UTC 200 POST /actors/gizmo/inbox 2746.45ms
 2024-08-13 02:54:33 UTC 409 POST /actors/gizmo/inbox 4.95ms
 2024-08-13 02:55:52 UTC 400 POST /actors/gizmo/inbox 1389.96ms
 2024-08-13 02:57:25 UTC 409 POST /actors/gizmo/inbox 4.64ms
 2024-08-13 02:57:43 UTC 400 POST /actors/gizmo/inbox 1038.62ms
 2024-08-13 02:57:43 UTC 404 GET /api/v3/site 6.83ms
 2024-08-13 02:57:43 UTC 404 GET /api/v3/federated_instances 6.74ms
 2024-08-13 02:57:43 UTC 404 GET /nodeinfo/2.0.json 5.97ms
 2024-08-13 02:57:43 UTC 404 GET /nodeinfo/2.1 5.61ms
 2024-08-13 02:58:54 UTC 409 POST /actors/gizmo/inbox 4.28ms
 2024-08-13 03:00:02 UTC 200 POST /actors/gizmo/inbox 4023.32ms
 2024-08-13 03:00:48 UTC 409 POST /actors/gizmo/inbox 5.69ms
 2024-08-13 03:00:57 UTC 409 POST /actors/gizmo/inbox 4.32ms
 2024-08-13 03:01:31 UTC 200 GET /.well-known/nodeinfo 6.95ms
 2024-08-13 03:01:31 UTC 200 GET /.well-known/nodeinfo/2.1 17.38ms
 2024-08-13 03:03:52 UTC 409 POST /actors/gizmo/inbox 4.6ms
 2024-08-13 03:05:05 UTC 200 POST /actors/gizmo/inbox 819.74ms
 2024-08-13 03:05:12 UTC 409 POST /actors/gizmo/inbox 4.81ms
 2024-08-13 03:05:43 UTC 200 GET /.well-known/nodeinfo 5.98ms
 2024-08-13 03:05:44 UTC 200 GET /.well-known/nodeinfo/2.1 10.39ms
 2024-08-13 03:05:45 UTC 200 GET / 587.09ms
 2024-08-13T03:05:45.704922Z NOTICE - database: Slow query [   580.269ms] -- SELECT "o"."type","o"."id","o"."blocked_at","o"."created_at","o"."updated_at","o"."deleted_at","o"."type","o"."iri","o"."visible","o"."published","o"."attributed_to_iri","o"."in_reply_to_iri","o"."replies_iri","o"."thread","o"."to","o"."cc","o"."name","o"."summary","o"."content","o"."media_type","o"."source","o"."attachments","o"."urls" FROM accounts AS c JOIN relationships AS r ON likelihood(r.from_iri = c.iri, 0.99) AND r.type = "Relationship::Content::Outbox" JOIN activities AS a ON a.iri = r.to_iri AND a.type IN ("ActivityPub::Activity::Announce", "ActivityPub::Activity::Create") JOIN objects AS o ON o.iri = a.object_iri JOIN actors AS t ON t.iri = o.attributed_to_iri WHERE o.visible = 1 AND likelihood(o.in_reply_to_iri IS NULL, 0.25) AND o.deleted_at IS NULL AND o.blocked_at IS NULL AND t.deleted_at IS NULL AND t.blocked_at IS NULL AND a.undone_at IS NULL ORDER BY r.id DESC LIMIT ? OFFSET ? -- args: [11, 0]
 2024-08-13T03:05:45.704945Z NOTICE - database: [{0, "SCAN c USING COVERING INDEX idx_accounts_iri"}, {0, "SEARCH r USING AUTOMATIC PARTIAL COVERING INDEX (from_iri=? AND type=?)"}, {0, "SEARCH a USING INDEX idx_activities_iri (iri=?)"}, {0, "SEARCH o USING INDEX idx_objects_iri (iri=?)"}, {0, "SEARCH t USING INDEX idx_actors_iri (iri=?)"}, {0, "USE TEMP B-TREE FOR ORDER BY"}]
 2024-08-13 03:06:36 UTC 409 POST /actors/gizmo/inbox 4.88ms

I have extended the log entries for ktistec to show one more of the occasional "database: Slow query" messages.

Some "unhandled exceptions" in the ktistec log but they are relatively far less frequent than the 409 errors.

oztourer commented 2 months ago

I have compared the stream of posts in the user interface, ktistec against snac, and they both seem to be complete. I guess the 400 and 409 responses are working as designed and therefore not an issue. I have not checked the code but snac may happily accept duplicate entries and still return a 202 response code. Different approaches with no consequences at the end user level. I would say that I have probably wasted your time here and the issue can be closed. Thanks for looking though.