Intermittent 504s from nginx because Pleroma takes too long to respond
I've been getting intermittent 504s from the home timeline endpoint ever since upgrading Pleroma to 8444e7ee a couple weeks ago, before which I never got them. The Pleroma logs don't show anything unusal:
Apr 16 07:11:25 bbs.kawa-kun.com mix[562]: 07:11:25.693 request_id=FgZSLwppjNFHN6gAAKdx [error] Could not decode user at fetch https://xn--69aa8bzb.xn--y9a3aq/actor, {:error, :timeout}
Apr 16 07:11:25 bbs.kawa-kun.com mix[562]: 07:11:25.835 request_id=FgZSMDOeH3z1pcYAALWR [error] Could not decode user at fetch https://sinblr.com/actor, {:error, {:reject, nil}}
Apr 16 07:11:26 bbs.kawa-kun.com mix[562]: 07:11:26.770 request_id=FgZSMGtOA30qkbkAALah [error] Could not decode user at fetch https://sinblr.com/actor, {:error, {:reject, nil}}
Apr 16 07:11:26 bbs.kawa-kun.com mix[562]: 07:11:26.925 request_id=FgZSMGvEbLSQm_cAAI8C [error] Could not decode user at fetch https://sinblr.com/actor, {:error, {:reject, nil}}
Apr 16 07:11:27 bbs.kawa-kun.com mix[562]: 07:11:27.526 request_id=FgZSL96-j8DhSngAALKR [error] Follower/Following counter update for https://mastodon.nl/actor failed.
Apr 16 07:11:27 bbs.kawa-kun.com mix[562]: {:error, "id must be a string"}
Apr 16 07:11:27 bbs.kawa-kun.com mix[562]: 07:11:27.793 request_id=FgZSMH0VQxkzrYIAALcR [error] Could not decode user at fetch https://xn--69aa8bzb.xn--y9a3aq/actor, {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS clien
t: In state certify at ssl_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:27 bbs.kawa-kun.com mix[562]: 07:11:27.810 request_id=FgZSMKk0DxiV190AALeh [error] Could not decode user at fetch https://sinblr.com/actor, {:error, {:reject, nil}}
Apr 16 07:11:27 bbs.kawa-kun.com mix[562]: 07:11:27.812 [warn] Opening connection to https://xn--69aa8bzb.xn--y9a3aq/actor failed with error {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS client: In state certify at ss
l_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:27 bbs.kawa-kun.com mix[562]: 07:11:27.915 request_id=FgZSL477-UmHsUEAAK3B [error] Could not decode user at fetch https://wall.demouliere.eu/internal/fetch, {:error, :timeout}
Apr 16 07:11:27 bbs.kawa-kun.com mix[562]: 07:11:27.915 [warn] Opening connection to https://wall.demouliere.eu/internal/fetch failed with error {:error, :timeout}
Apr 16 07:11:29 bbs.kawa-kun.com mix[562]: 07:11:29.469 request_id=FgZSMML2gOfUWTYAAJBi [error] Follower/Following counter update for https://wall.demouliere.eu/internal/fetch failed.
Apr 16 07:11:29 bbs.kawa-kun.com mix[562]: {:error, %Jason.DecodeError{data: "<!DOCTYPE html><html lang=en><head><meta charset=utf-8><meta name=viewport content=\"width=device-width,initial-scale=1,user-scalable=no\"><title>Pleroma</title>
<!--server-generated-meta--><link rel=icon type=image/png href=/favicon.png><link href=/static/css/vendors~app.b2603a50868c68a1c192.css rel=stylesheet><link href=/static/css/app.1055039ce3f2fe4dd110.css rel=stylesheet><link href=/static/fo
ntello.1586352043988.css rel=stylesheet></head><body class=hidden><noscript>To use Pleroma, please enable JavaScript.</noscript><div id=app></div><script type=text/javascript src=/static/js/vendors~app.de343579e844e698d456.js></script><scr
ipt type=text/javascript src=/static/js/app.89eafa17d89159680407.js></script></body></html>", position: 0, token: nil}}
Apr 16 07:11:34 bbs.kawa-kun.com mix[562]: 07:11:34.454 request_id=FgZSMgnR4oYQ57sAALmh [error] Could not decode user at fetch https://xn--69aa8bzb.xn--y9a3aq/actor, {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS clien
t: In state certify at ssl_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:36 bbs.kawa-kun.com mix[562]: 07:11:36.839 [warn] Opening connection to https://xn--69aa8bzb.xn--y9a3aq/actor failed with error {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS client: In state certify at ss
l_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:37 bbs.kawa-kun.com mix[562]: 07:11:37.250 [warn] Opening connection to https://xn--69aa8bzb.xn--y9a3aq/actor failed with error {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS client: In state certify at ss
l_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:37 bbs.kawa-kun.com mix[562]: 07:11:37.265 request_id=FgZSMqqyMJ-lVbAAALnx [error] Could not decode user at fetch https://xn--69aa8bzb.xn--y9a3aq/actor, {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS clien
t: In state certify at ssl_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:37 bbs.kawa-kun.com mix[562]: 07:11:37.271 [warn] Opening connection to https://xn--69aa8bzb.xn--y9a3aq/actor failed with error {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS client: In state certify at ss
l_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:37 bbs.kawa-kun.com mix[562]: 07:11:37.297 request_id=FgZSMqD4EGB0LYgAALnh [error] Could not decode user at fetch https://xn--69aa8bzb.xn--y9a3aq/actor, {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS clien
t: In state certify at ssl_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:39 bbs.kawa-kun.com mix[562]: 07:11:39.224 [warn] Opening connection to https://xn--69aa8bzb.xn--y9a3aq/actor failed with error {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS client: In state certify at ss
l_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:11:39 bbs.kawa-kun.com mix[562]: 07:11:39.241 request_id=FgZSMyaad4LHoi0AAJJS [error] Could not decode user at fetch https://xn--69aa8bzb.xn--y9a3aq/actor, {:error, {:down, {:shutdown, {:tls_alert, {:handshake_failure, 'TLS clien
t: In state certify at ssl_handshake.erl:1768 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,invalid_key_usage}'}}}}}
Apr 16 07:15:56 bbs.kawa-kun.com mix[562]: 07:15:56.525 [error] Couldn't fetch "https://mstdn.beer/users/sakasato/statuses/104008678164348102", error: nil
Apr 16 07:19:17 bbs.kawa-kun.com mix[562]: 07:19:17.640 [info] CONNECTED TO Pleroma.Web.UserSocket in 1ms
Apr 16 07:19:17 bbs.kawa-kun.com mix[562]: Transport: :websocket
Apr 16 07:19:17 bbs.kawa-kun.com mix[562]: Serializer: Phoenix.Socket.V2.JSONSerializer
Apr 16 07:19:17 bbs.kawa-kun.com mix[562]: Connect Info: %{}
Apr 16 07:19:17 bbs.kawa-kun.com mix[562]: Parameters: %{"token" => "<REDACTED>", "vsn" => "2.0.0"}
Nor do the Postgres logs contain any recent queries of over 5 seconds in duration. Thees are the most recent before the 504.
2020-04-16 03:25:15.350 PDT [9890] pleroma@pleroma STATEMENT: INSERT INTO "objects" ("data","inserted_at","updated_at") VALUES ($1,$2,$3) RETURNING "id"
2020-04-16 03:25:15.378 PDT [9899] pleroma@pleroma ERROR: duplicate key value violates unique constraint "objects_unique_apid_index"
2020-04-16 03:25:15.378 PDT [9899] pleroma@pleroma DETAIL: Key ((data ->> 'id'::text))=(https://mastodon.ml/users/drq/statuses/104004072069768767) already exists.
2020-04-16 03:25:15.378 PDT [9899] pleroma@pleroma STATEMENT: INSERT INTO "objects" ("data","inserted_at","updated_at") VALUES ($1,$2,$3) RETURNING "id"
2020-04-16 06:10:32.455 PDT [653] pleroma@pleroma ERROR: duplicate key value violates unique constraint "objects_unique_apid_index"
2020-04-16 06:10:32.455 PDT [653] pleroma@pleroma DETAIL: Key ((data ->> 'id'::text))=(https://gameliberty.club/users/matrix/statuses/104008425890362943) already exists.
2020-04-16 06:10:32.455 PDT [653] pleroma@pleroma STATEMENT: INSERT INTO "objects" ("data","inserted_at","updated_at") VALUES ($1,$2,$3) RETURNING "id"
Edited by Neil E. Hodges