search

superseriousbusiness / gotosocial

Fast, fun, small ActivityPub server.
https://docs.gotosocial.org
GNU Affero General Public License v3.0
3.61k stars 304 forks source link

[bug] tons of duplicate key errors in postgresql log #1744

Open mirabilos opened 1 year ago

mirabilos commented 1 year ago

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

I have /var/log/postgresql on a small tmpfs, and there normally almost nothing is written.

Suddenly I get a logrotate message it’s full.

The logfile contains tons of duplicate key messages. Examples are:

2023-05-06 00:36:55.113 UTC [7332] gotosocial@gotosocial ERROR:  duplicate key value violates unique constraint "new_accounts_uri_key"
2023-05-06 00:36:55.113 UTC [7332] gotosocial@gotosocial DETAIL:  Key (uri)=(https://mastodon.world/users/not_julien) already exists.
2023-05-06 00:36:55.113 UTC [7332] gotosocial@gotosocial STATEMENT:  INSERT INTO "accounts" ("id", "created_at", "updated_at", "fetched_at", "username", "domain", "avatar_media_attachment_id", "avatar_remote_url", "header_media_attachment_id", "header_remote_url", "display_name", "emojis", "fields", "note", "note_raw", "memorial", "also_known_as", "moved_to_account_id", "bot", "reason", "locked", "discoverable", "privacy", "sensitive", "language", "status_content_type", "custom_css", "uri", "url", "inbox_uri", "shared_inbox_uri", "outbox_uri", "following_uri", "followers_uri", "featured_collection_uri", "actor_type", "private_key", "public_key", "public_key_uri", "sensitized_at", "silenced_at", "suspended_at", "hide_collections", "suspension_origin", "enable_rss") VALUES ('01GZQ7TZPEGSMAP68BT4T2PH71', '2023-05-06 00:36:54.681985+00:00', '2023-05-06 00:36:54.681985+00:00', '2023-05-06 00:36:54.681985+00:00', 'not_julien', 'mastodon.world', DEFAULT, DEFAULT, DEFAULT, DEFAULT, 'not_julien', NULL, 'null', '', '', FALSE, DEFAULT, DEFAULT, FALSE, '', FALSE, FALSE, DEFAULT, FALSE, DEFAULT, DEFAULT, DEFAULT, 'https://mastodon.world/users/not_julien', 'https://mastodon.world/@not_julien', 'https://mastodon.world/users/not_julien/inbox', 'https://mastodon.world/inbox', 'https://mastodon.world/users/not_julien/outbox', 'https://mastodon.world/users/not_julien/following', 'https://mastodon.world/users/not_julien/followers', 'https://mastodon.world/users/not_julien/collections/featured', 'Person', DEFAULT, '{"N":21002291953318658342995942118699486628069365136479364599262752412302027286075025656069981327247597691269774338847200788869230826574133892152192739554111168461837091941540009065558090246404966062556424377927587044087330077585667198364111692899441870325462115978474567985948251151761994038036241106160856690123311223166890055656715601044466088002570086700249804201490212806993154996561215063642630268019547220732965261012893032356626199781771290168664346516674400955270488641797089166253765844113721790746114994289033239450201150870596793169271862796125682624773714356712097737146159608441372065145988803115972650650009,"E":65537}', 'https://mastodon.world/users/not_julien#main-key', DEFAULT, DEFAULT, DEFAULT, FALSE, DEFAULT, FALSE) RETURNING "avatar_media_attachment_id", "avatar_remote_url", "header_media_attachment_id", "header_remote_url", "also_known_as", "moved_to_account_id", "privacy", "language", "status_content_type", "custom_css", "private_key", "sensitized_at", "silenced_at", "suspended_at", "suspension_origin"

(visually about ⅓ to ¼ of them, many different accounts)

2023-05-06 10:07:18.383 UTC [20275] gotosocial@gotosocial ERROR:  duplicate key value violates unique constraint "tombstones_uri_key"
2023-05-06 10:07:18.383 UTC [20275] gotosocial@gotosocial DETAIL:  Key (uri)=(https://mastodon.social/users/hamoush#main-key) already exists.
2023-05-06 10:07:18.383 UTC [20275] gotosocial@gotosocial STATEMENT:  INSERT INTO "tombstones" ("id", "created_at", "updated_at", "domain", "uri") VALUES ('01GZR8FDAX1RA3DBH7CCYDA3G5', DEFAULT, DEFAULT, 'mastodon.social', 'https://mastodon.social/users/hamoush#main-key') RETURNING "created_at", "updated_at"

(visually about ⅔ to ¾ of them, also all different users)

What's your GoToSocial Version?

0.8.1 git-4dbf9a2

GoToSocial Arch

amd64 binary

What happened?

see above

What you expected to happen?

heeeeeeelp, my log’s filling!

How to reproduce it?

unsure, it really went up in volume today, but apparently the issue was present on 2023-05-04 already, possibly farther back but I don’t archive logs

2023-05-04 had only about 900 lines whereas 2023-05-06 had 10k lines until 17:53:15.256 UTC when the tmpfs was full

Anything else we need to know?

I’m archiving the one from 2023-05-05 but otherwise delete them and restart so normal operation can continue

tsmethurst commented 1 year ago

Hmm, that's very strange... you weren't running two GtS process at once by any chance were you? :thinking: Did you change anything else in those two days?

mirabilos commented 1 year ago

No, never; I only run this from DJB dæmontools.

I didn’t change a thing recently, but perhaps the issue was there already but the amount rose today.

I have just restarted Apache 2, GtS and PostgreSQL, and there seem to be no new corresponding log lines.

But: I have a cronjob that restarts GtS every 06:10 UTC (using svc -t, so basically, dæmontools gives the GtS process SIGTERM, then once it’s gone, it’s immediately respawned, but supervise won’t restart it if it’s not yet gone so unless GtS itself had a child process running for longer than the main process, nothing would have run overlappingly; as far as I can tell, it only has one process though)

mirabilos commented 1 year ago

spoke to soon, it’s starting again ☹

mirabilos commented 1 year ago

Occurrence:

2023-05-07 13:56:14.542 UTC [27607] gotosocial@gotosocial ERROR:  duplicate key value violates unique constraint "new_accounts_uri_key"
2023-05-07 13:56:14.542 UTC [27607] gotosocial@gotosocial DETAIL:  Key (uri)=(https://mstdn.social/users/ayala) already exists.
2023-05-07 13:56:14.542 UTC [27607] gotosocial@gotosocial STATEMENT:  INSERT INTO "accounts" ("id", "created_at", "updated_at", "fetched_at", "username", "domain", "avatar_media_attachment_id", "avatar_remote_url", "header_media_attachment_id", "header_remote_url", "display_name", "emojis", "fields", "note", "note_raw", "memorial", "also_known_as", "moved_to_account_id", "bot", "reason", "locked", "discoverable", "privacy", "sensitive", "language", "status_content_type", "custom_css", "uri", "url", "inbox_uri", "shared_inbox_uri", "outbox_uri", "following_uri", "followers_uri", "featured_collection_uri", "actor_type", "private_key", "public_key", "public_key_uri", "sensitized_at", "silenced_at", "suspended_at", "hide_collections", "suspension_origin", "enable_rss") VALUES ('01GZV7Z9W85EC34Y9ZZW16Q5K3', '2023-05-07 13:56:13.866197+00:00', '2023-05-07 13:56:13.866197+00:00', '2023-05-07 13:56:13.866197+00:00', 'ayala', 'mstdn.social', DEFAULT, DEFAULT, DEFAULT, DEFAULT, 'ayala', NULL, 'null', '', '', FALSE, DEFAULT, DEFAULT, FALSE, '', FALSE, FALSE, DEFAULT, FALSE, DEFAULT, DEFAULT, DEFAULT, 'https://mstdn.social/users/ayala', 'https://mstdn.social/@ayala', 'https://mstdn.social/users/ayala/inbox', 'https://mstdn.social/inbox', 'https://mstdn.social/users/ayala/outbox', 'https://mstdn.social/users/ayala/following', 'https://mstdn.social/users/ayala/followers', 'https://mstdn.social/users/ayala/collections/featured', 'Person', DEFAULT, '{"N":28379124633857878313625275453107349846163353823932664716495064253679796383470123861247823218709300569431545037358997915513444043535712813643936179809667063668701062733120885970014091724619916629384220320657463559645212909790219595263027464556357482862801534499069347236184199217217075145039803566380257894060599352660600922531173613765015852561304907937104490839905441909346161432095524473949730494770098173286638143007045837155807751545612816994559512128953077071552278906070958937044968569027165804254822815817259771396072512557175932989881580947319506626387537448294649470015067535184385271750130936142092637789441,"E":65537}', 'https://mstdn.social/users/ayala#main-key', DEFAULT, DEFAULT, DEFAULT, FALSE, DEFAULT, FALSE) RETURNING "avatar_media_attachment_id", "avatar_remote_url", "header_media_attachment_id", "header_remote_url", "also_known_as", "moved_to_account_id", "privacy", "language", "status_content_type", "custom_css", "private_key", "sensitized_at", "silenced_at", "suspended_at", "suspension_origin"

corresponding GtS log around that time:

@400000006457ae071c4fbbec timestamp="07/05/2023 13:56:13.474" func=transport.(*transport).do level=INFO pubKeyID=https://toot.mirbsd.org/users/mirabilos/main-key method=GET url=https://mstdn.social/users/ayala#main-key requestID=06k7zxm704001hhydqe0 msg="performing request"
@400000006457ae07205cef5c timestamp="07/05/2023 13:56:13.542" func=transport.(*transport).do level=INFO pubKeyID=https://toot.mirbsd.org/users/mirbsd_cvs/main-key method=GET url=https://mstdn.social/users/ayala#main-key requestID=4ek7zxm704000py5vthg msg="performing request"
@400000006457ae07319682ec timestamp="07/05/2023 13:56:13.831" func=transport.(*transport).do level=INFO pubKeyID=https://toot.mirbsd.org/users/mirbsd_cvs/main-key method=GET url=https://mstdn.social/users/ayala requestID=4ek7zxm704000py5vthg msg="performing request"
@400000006457ae073218554c timestamp="07/05/2023 13:56:13.840" func=transport.(*transport).do level=INFO pubKeyID=https://toot.mirbsd.org/users/mirabilos/main-key method=GET url=https://mstdn.social/users/ayala requestID=06k7zxm704001hhydqe0 msg="performing request"
@400000006457ae0732b7d93c timestamp="07/05/2023 13:56:13.850" func=transport.(*transport).do level=INFO pubKeyID=https://toot.mirbsd.org/users/mirbsd_cvs/main-key method=GET url=https://mstdn.social/.well-known/webfinger?resource=acct%3Aayala%40mstdn.social requestID=4ek7zxm704000py5vthg msg="performing request"
@400000006457ae07331a3cbc timestamp="07/05/2023 13:56:13.857" func=transport.(*transport).do level=INFO pubKeyID=https://toot.mirbsd.org/users/mirabilos/main-key method=GET url=https://mstdn.social/.well-known/webfinger?resource=acct%3Aayala%40mstdn.social requestID=06k7zxm704001hhydqe0 msg="performing request"
@400000006457ae07333eef44 timestamp="07/05/2023 13:56:13.859" func=dereferencing.(*deref).enrichAccount level=ERROR requestID=4ek7zxm704000py5vthg msg="error webfingering[2] remote account ayala@mstdn.social: fingerRemoteAccount: error fingering @ayala@mstdn.social: account has been deleted/is gone"
@400000006457ae0733a18974 timestamp="07/05/2023 13:56:13.866" func=dereferencing.(*deref).enrichAccount level=ERROR requestID=06k7zxm704001hhydqe0 msg="error webfingering[2] remote account ayala@mstdn.social: fingerRemoteAccount: error fingering @ayala@mstdn.social: account has been deleted/is gone"
@400000006457ae0820fccd24 timestamp="07/05/2023 13:56:14.553" func=transport.(*transport).do level=INFO pubKeyID=https://toot.mirbsd.org/users/mirbsd_cvs/main-key method=GET url=https://mstdn.social/users/ayala/collections/featured requestID=4ek7zxm704000py5vthg msg="performing request"
@400000006457ae08211fe19c timestamp="07/05/2023 13:56:14.555" func=middleware.Logger.func1.1 level=INFO latency=1.114594357s clientIP=2a01:4f8:c0c:ba94::1 userAgent="http.rb/5.1.1 (Mastodon/4.1.2; +https://mstdn.social/)" method=POST statusCode=400 path=/users/mirabilos/inbox requestID=06k7zxm704001hhydqe0 msg="Bad Request: wrote 934B"
@400000006457ae0821868adc timestamp="07/05/2023 13:56:14.562" func=dereferencing.(*deref).enrichAccount level=ERROR requestID=4ek7zxm704000py5vthg msg="error fetching featured collection for account https://mstdn.social/users/ayala: GET request to https://mstdn.social/users/ayala/collections/featured failed: 403 Forbidden"
@400000006457ae0821acd3a4 timestamp="07/05/2023 13:56:14.564" func=middleware.Logger.func1.1 level=INFO latency=1.089507797s clientIP=2a01:4f8:c0c:ba94::1 userAgent="http.rb/5.1.1 (Mastodon/4.1.2; +https://mstdn.social/)" method=POST statusCode=202 path=/users/mirbsd_cvs/inbox requestID=4ek7zxm704000py5vthg msg="Accepted: wrote 23B"
@400000006457ae0821b93784 timestamp="07/05/2023 13:56:14.565" func=processing.(*Processor).ProcessFromFederator level=INFO activityType=Delete objectType=Profile toAccount=mirbsd_cvs msg="processing from federator"
@400000006457ae0824f61ebc timestamp="07/05/2023 13:56:14.620" func=account.(*Processor).Delete level=INFO username=ayala domain=mstdn.social msg="account deleted"
mirabilos commented 1 year ago

Another interesting effect: I can search (in Pinafore) for ayala@mstdn.social but not e.g. dascomur@mas.to who also showed up in the PostgreSQL log, and the latter gives a 500, with the following log:

@400000006457e70b06363f84 timestamp="07/05/2023 17:59:29.104" func=middleware.Logger.func1.1 level=ERROR latency=310.058364ms clientIP=2001:4dd7:4cb2:0:21f:3bff:fe0d:cbb1 userAgent="Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0" method=GET statusCode=500 path=/api/v2/search error="Error #01: error looking up account: enrichAccount: error webfingering account: fingerRemoteAccount: error fingering @dascomur@mas.to: webfinger discovery on mas.to returned endpoint we already tried: https://mas.to/.well-known/webfinger\n" requestID=39dnxxw704001bhr6zm0 msg="Internal Server Error: wrote 54B"

That being said, https://mas.to/dascomur gives “The page you are looking for isn't here.” (even if I see their profile in the PostgreSQL error log)… hm but https://mstdn.social/ayala does so give the same error.

tsmethurst commented 1 year ago

We made some changes to our account update/insert logic on main, so it's possible we already fixed this without realizing. Once we unleash 0.9.0 upon the world we can see if this issue persists and if so, then fix it in a bugfix release I think..

mirabilos commented 1 year ago

after upgrading to 0.9.0 I still get both (tombstones and accounts)

mirabilos commented 1 year ago

Still present in 0.10.0-rc3 git-f431974 (for both).

mirabilos commented 11 months ago

v0.11.1 even has duplicate errors in the GtS log now…

timestamp="21/08/2023 16:23:10.069" func=workers.(*Processor).EnqueueFediAPI.func1 level=ERROR requestID=38yeg64a04001sdzg12g msg="error processing fedi API message: DereferenceStatusAncestors: error dereferencing parent https://fosstodon.org/@ianthetechie/110925875497331672: enrichStatus: error putting in database: ERROR: duplicate key value violates unique constraint \"statuses_uri_key\" (SQLSTATE 23505)"

… not just in the PostgreSQL log. This particular one also shows up in the latter, with the exact query, duplicate error, and extra info:

2023-08-21 16:23:22.265 UTC [30661] gotosocial@gotosocial DETAIL:  Key (uri)=(https://pixelfed.social/p/libreivan/599104724113734314) already exists.
tsmethurst commented 11 months ago

Mm okay, will try to fix this soon. Is it causing any issues in the running of GtS itself?

mirabilos commented 11 months ago

tobi dixit:

Mm okay, will try to fix this soon.

Thanks.

It’ll probably be a bit tricky due to the ORM, but in theory, those queries could be changed to add an ON CONFLICT DO … to update the changed fields, if any, if the record already exists (or even a DO NOTHING if none). Good luck!

Is it causing any issues in the running of GtS itself?

I haven’t noticed any functional issues from this. If the failing query is not in a transaction with other queries following, there shouldn’t be any, anyway (if it were, a subsequent COMMIT would fail, and then I believe I would see that in the log as well).

I was simply looking at the logs scrolling by after doing the update, and I normally strive to eliminate warnings from logs that are considered “normal”, by either getting rid of the cause or the warning (in rare cases), so they don’t clutter the log and make actual issues harder to spot.

Nothing pressing (they will cause some minimal extra load on the database but probably less than the extra indicēs).

bye, //mirabilos

mirabilos commented 7 months ago

(this still happens, btw)