[bug] POST 401 to inbox endpoint

[jakecoffman]

Describe the bug with a clear and concise description of what the bug is.

First of all, wonderful project. I was able to set it up very quickly and easily.

I'm seeing this error in the logs: /users/jake/inbox HTTP/1.1" 401 23 "-" "http.rb/5.1.0 (Mastodon/4.0.0rc1; +https://mas.to/)"

It's coming from mas.to and mastodon.social.

Admittedly I'm not sure what the inbox endpoint does but I'm wondering if I'm missing follows or something?

What's your GoToSocial Version?

v0.5.2

GoToSocial Arch

amd64 binary

Browser version

No response

What happened?

I followed the install instructions, then setup nginx as a reverse proxy.

What you expected to happen?

No errors in the logs!

How to reproduce it?

No response

Anything else we need to know?

If you want to poke at my instance: @jake@social.jakecoffman.com

[jakecoffman]

I turned on debug logging and saw this:

timestamp="06/11/2022 18:27:19.652" func=federation.(*federator).AuthenticateFederatedRequest level=DEBUG msg="error dereferencing public key https://mas.to/users/ctyz#main-key: GET request to https://mas.to/users/ctyz#main-key failed (410): 410 Gone"
timestamp="06/11/2022 18:27:19.652" func=router.loggingMiddleware.func1 level=INFO latency=403.257689ms clientIP=65.21.125.235 userAgent="http.rb/5.1.0 (Mastodon/4.0.0rc1; +https://mas.to/)" method=POST statusCode=401 path=/users/jake/inbox msg="Unauthorized: wrote 23B"

It looks like these users don't exist so I'll chalk it up to mas.to doing something weird. Maybe these are users deleting their accounts or something?

[lzap]

I see ton of these, every single second. Is this part of the protocol?

$ journalctl | grep 'statusCode=401' | grep -o 'https://[a-z0-9.]*' | sort -u
https://androiddev.social
https://aus.social
https://awscommunity.social
https://c.im
https://climatejustice.social
https://darmstadt.social
https://dizl.de
https://dresden.network
https://econtwitter.net
https://epicyon.libreserver.org
https://floss.social
https://fosstodon.org
https://freeradical.zone
https://freiburg.social
https://hackers.town
https://hachyderm.io
https://chaos.social
https://ieji.de
https://indieweb.social
https://infosec.exchange
https://ioc.exchange
https://journa.host
https://kinky.business
https://livellosegreto.it
https://lor.sh
https://machteburch.social
https://mamot.fr
https://mapstodon.space
https://masthead.social
https://mas.to
https://masto.ai
https://mastodon.acc.sunet.se
https://mastodon.arch
https://mastodon.art
https://mastodon.bida.im
https://mastodon.cloud
https://mastodon.design
https://mastodon.gamedev.place
https://mastodon.green
https://mastodon.ie
https://mastodon.nl
https://mastodon.nz
https://mastodon.online
https://mastodon.pirateparty.be
https://mastodon.scot
https://mastodon.sdf.org
https://mastodontech.de
https://mastodon.technology
https://mastodon.uno
https://mastodon.world
https://mastodon.xyz
https://mastodon.zaclys.com
https://masto.nobigtech.es
https://masto.pt
https://mathstodon.xyz
https://metalhead.club
https://mstdn.fr
https://mstdn.io
https://mstdn.social
https://muensterland.social
https://noc.social
https://nrw.social
https://oslo.town
https://phpc.social
https://piaille.fr
https://pouet.chapril.org
https://qoto.org
https://scicomm.xyz
https://sfba.social
https://scholar.social
https://sigmoid.social
https://snabelen.no
https://socel.net
https://social.anoxinon.de
https://social.cologne
https://social.linux.pizza
https://social.m1nd.io
https://social.tchncs.de
https://sueden.social
https://systerserver.town
https://tech.lgbt
https://todon.nl
https://toot.community
https://toot.dice.quest
https://toot.site
https://toot.wales
https://troet.cafe
https://twingyeo.kr
https://writing.exchange
https://zirk.us

[lzap]

Ok @tsmethurst explained to me on chat (for the record):

That occurs when a mastodon user has been deleted: gts tries to fetch the user's public key to verify the delete, but it's already gone. We'll fix it in a future release, but it's known and doesn't break anything, don't worry :)

[tsmethurst]

For anyone else reading this now, this was fixed by #1005 and should be in a release soon (tm)

[phikal]

I am encountering a very similar issue, but it appears to affect all accounts, even though which are not deleted. The issue perplexes me, so I am posting the log here in case someone else can read out any information that would explain the issue:

timestamp="15/11/2022 14:41:53.805" func=router.loggingMiddleware.func1 level=INFO latency=5.36785ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/accounts/01J7BVZNB8VCRZHP3B1WB9XCRM msg="OK: wrote 910B"
timestamp="15/11/2022 14:41:53.808" func=router.loggingMiddleware.func1 level=INFO latency=1.341573ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/accounts/relationships msg="OK: wrote 173B"
timestamp="15/11/2022 14:41:53.830" func=router.loggingMiddleware.func1 level=INFO latency=1.232717ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/filters msg="OK: wrote 26B"
timestamp="15/11/2022 14:41:53.833" func=router.loggingMiddleware.func1 level=INFO latency=1.020092ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/filters msg="OK: wrote 26B"
timestamp="15/11/2022 14:41:53.847" func=router.loggingMiddleware.func1 level=INFO latency=1.148469ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/filters msg="OK: wrote 26B"
timestamp="15/11/2022 14:41:53.873" func=router.loggingMiddleware.func1 level=INFO latency=4.211861ms clientIP=172.25.0.1 userAgent="Dalvik/2.1.0 (Linux; U; Android 13; FP4 Build/TP1A.220905.004.A2)" method=GET statusCode=200 path=/fileserver/01J7BVZNB8VCRZHP3B1WB9XCRM/attachment/original/01BP0J2NV1ETBKN2C521MPMCK6.jpeg msg="OK: wrote 216kiB"
timestamp="15/11/2022 14:41:53.901" func=router.loggingMiddleware.func1 level=INFO latency=2.424266ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/accounts/01J7BVZNB8VCRZHP3B1WB9XCRM/statuses msg="OK: wrote 26B"
timestamp="15/11/2022 14:41:53.905" func=router.loggingMiddleware.func1 level=INFO latency=2.188772ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/accounts/01J7BVZNB8VCRZHP3B1WB9XCRM/statuses msg="OK: wrote 26B"
timestamp="15/11/2022 14:41:53.934" func=router.loggingMiddleware.func1 level=INFO latency=4.459627ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=GET statusCode=200 path=/api/v1/accounts/01J7BVZNB8VCRZHP3B1WB9XCRM/statuses msg="OK: wrote 26B"
timestamp="15/11/2022 14:41:55.834" func=router.loggingMiddleware.func1 level=INFO latency=12.054688ms clientIP=172.25.0.1 userAgent="Tusky/19.0 Android/13 OkHttp/4.9.3" method=POST statusCode=200 path=/api/v1/accounts/01J7BVZNB8VCRZHP3B1WB9XCRM/follow msg="OK: wrote 176B"
timestamp="15/11/2022 14:41:55.836" func=processing.(*processor).ProcessFromClientAPI level=INFO activityType=Create objectType=Follow fromAccount=pkal msg="processing from client"
timestamp="15/11/2022 14:41:55.837" func=federation.(*federatingActor).Send level=INFO msg="federating actor: send activity Follow via outbox https://mb.amodernist.com/users/pkal/outbox"
timestamp="15/11/2022 14:41:55.842" func=transport.(*transport).do level=INFO pubKeyID=https://mb.amodernist.com/users/pkal/main-key method=POST url=https://emacs.ch/inbox msg="performing request"
timestamp="15/11/2022 14:41:56.073" func=router.loggingMiddleware.func1 level=INFO latency=1.717556ms clientIP=172.25.0.1 userAgent="http.rb/5.1.0 (Mastodon/4.0.2; +https://emacs.ch/)" method=GET statusCode=200 path=/users/pkal/main-key msg="OK: wrote 560B"
timestamp="15/11/2022 14:41:56.188" func=router.loggingMiddleware.func1 level=INFO latency=4.267501ms clientIP=172.25.0.1 userAgent="http.rb/5.1.0 (Mastodon/4.0.2; +https://emacs.ch/)" method=GET statusCode=200 path=/users/pkal msg="OK: wrote 899B"
timestamp="15/11/2022 14:41:56.409" func=concurrency.(*WorkerPool).Queue.func1 level=ERROR type=worker.Worker[messages.FromClientAPI] error="BatchDeliver: at least one failure: POST request to https://emacs.ch/inbox failed (401): 401 Unauthorized" msg="message processing error"