Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Servers may sometimes incorrectly issue 429s #1732

Closed
ara4n opened this issue Dec 30, 2016 · 5 comments
Closed

Servers may sometimes incorrectly issue 429s #1732

ara4n opened this issue Dec 30, 2016 · 5 comments

Comments

@ara4n
Copy link
Member

ara4n commented Dec 30, 2016

@erikjohnston was seeing servers incorrectly issuing 429s just before Christmas:

I think i just saw this too, with darmstadt spuriously 429'ing arasphere on receiving a backfill request for no obvious reason:

2016-12-30 04:55:25,666 - synapse.http.outbound - 124 - INFO -  - {PUT-O-2859} [darmstadt.ccc.de] Sending request: PUT matrix://darmstadt.ccc.de/_matrix/federation/v1/send/1483062694063/
2016-12-30 04:55:26,656 - synapse.http.outbound - 209 - INFO -  - {PUT-O-2859} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 04:55:26,657 - synapse.federation.transaction_queue - 468 - INFO -  - TX [darmstadt.ccc.de] {1483062694063} got 429 response
2016-12-30 04:55:26,657 - synapse.federation.transaction_queue - 505 - WARNING -  - TX [darmstadt.ccc.de] Problem in _attempt_transaction: 429: Unknown Status
2016-12-30 04:55:26,657 - synapse.federation.transaction_queue - 511 - INFO -  - Failed to send event $148307371832hqjZG:productionservers.net to darmstadt.ccc.de
2016-12-30 05:00:42,940 - synapse.http.outbound - 124 - INFO - PUT-10860 - {POST-O-2988} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:01:42,940 - synapse.http.matrixfederationclient - 183 - WARNING - PUT-10860 - {POST-O-2988} Sending request failed to darmstadt.ccc.de: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org: CancelledError - CancelledError: 
2016-12-30 05:01:44,814 - synapse.http.outbound - 209 - INFO - PUT-10860 - {POST-O-2988} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:01:48,665 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3008} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:01:48,764 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3008} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:01:48,767 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3009} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:01:48,836 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3009} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:01:48,839 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3010} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:01:48,929 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3010} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:01:48,931 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3011} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:01:49,224 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3011} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:01:49,227 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3012} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:01:49,303 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3012} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:01:49,305 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3013} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:01:49,382 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3013} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:01:49,385 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3014} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:02:49,386 - synapse.http.matrixfederationclient - 183 - WARNING - PUT-10914 - {POST-O-3014} Sending request failed to darmstadt.ccc.de: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org: CancelledError - CancelledError: 
2016-12-30 05:02:50,187 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3014} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:02:50,190 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3015} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:02:50,482 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3015} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:02:51,052 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3016} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:02:51,190 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3016} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:02:51,401 - synapse.http.outbound - 124 - INFO - PUT-10914 - {POST-O-3017} [darmstadt.ccc.de] Sending request: POST matrix://darmstadt.ccc.de/_matrix/federation/v1/get_missing_events/!cURbafjkfsMDVwdRDQ:matrix.org
2016-12-30 05:02:51,645 - synapse.http.outbound - 209 - INFO - PUT-10914 - {POST-O-3017} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:22:16,243 - synapse.access.https.8448 - 91 - INFO - PUT-11879 - 130.83.177.132 - 8448 - {darmstadt.ccc.de} Processed request: 432ms (0ms, 0ms) (429ms/3) 11B 200 "PUT /_matrix/federation/v1/send/1482195872229/ HTTP/1.1" "Synapse/0.18.5 (b=develop,09f1591)"
2016-12-30 05:51:42,119 - synapse.http.outbound - 124 - INFO -  - {GET-O-3357} [darmstadt.ccc.de] Sending request: GET matrix://darmstadt.ccc.de/_matrix/federation/v1/event/$14168368325cmTRA:arasphere.net/
2016-12-30 05:51:42,295 - synapse.http.outbound - 209 - INFO -  - {GET-O-3357} [darmstadt.ccc.de] Result: 429 Unknown Status
2016-12-30 05:51:42,296 - synapse.federation.federation_client - 270 - INFO -  - Failed to get PDU $14168368325cmTRA:arasphere.net from darmstadt.ccc.de because 429: Unknown Status

This then looks also to be related to arasphere subsequently blackholing requests from darmstadt entirely.

@ara4n
Copy link
Member Author

ara4n commented Dec 30, 2016

Meanwhile, disroot.org->matrix.org is seeing the same misbehaviour right now:

2016-12-30 14:27:39,465 - synapse.federation.transport.server - 138 - INFO - PUT-6389931 - Request from disroot.org
2016-12-30 14:27:39,465 - synapse.http.server - 123 - INFO - PUT-6389931 - <XForwardedForRequest at 0x91c2a098 method=PUT uri=/_matrix/federation/v1/send/1483107686718/ clientproto=HTTP/1.1 site=8080> SynapseError: 429 - Too Many Requests
2016-12-30 14:27:39,466 - synapse.access.http.8080 - 91 - INFO - PUT-6389931 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 2ms (0ms, 0ms) (0ms/0) 80B 429 "PUT /_matrix/federation/v1/send/1483107686718/ HTTP/1.1" "Synapse/0.18.6-rc1"

@ara4n
Copy link
Member Author

ara4n commented Dec 30, 2016

Right. It looks like the 429s might be coming from the

# The maximum number of concurrent federation requests allowed
# from a single server
federation_rc_reject_limit: 50

...config option on the homeserver. When #1733 kicks in, if we get more than 50 concurrent requests stacked up, the server will start 429ing new ones. Given the requests can take hours/days to execute as per #1733, it gives the appearance of 429ing new ones from that server.

@ara4n
Copy link
Member Author

ara4n commented Dec 30, 2016

For disroot.org, it looks like this:

2016-12-30 02:49:21,739 - synapse.federation.transport.server - 138 - INFO - PUT-3150741 - Request from disroot.org
2016-12-30 02:49:21,742 - synapse.access.http.8080 - 91 - INFO - PUT-3150741 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 4ms (0ms, 0ms) (0ms/2) 11B 200 "PUT /_matrix/federation/v1/send/1483039212850/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 02:49:23,116 - synapse.federation.transport.server - 138 - INFO - PUT-3150869 - Request from disroot.org
2016-12-30 02:49:23,118 - synapse.access.http.8080 - 91 - INFO - PUT-3150869 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 3ms (0ms, 0ms) (0ms/2) 11B 200 "PUT /_matrix/federation/v1/send/1483039212934/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 02:54:30,497 - synapse.federation.transport.server - 138 - INFO - PUT-3174290 - Request from disroot.org
2016-12-30 02:54:30,508 - synapse.access.http.8080 - 91 - INFO - PUT-3174290 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 12ms (0ms, 0ms) (2ms/3) 11B 200 "PUT /_matrix/federation/v1/send/1483039212954/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 02:56:04,409 - synapse.federation.transport.server - 138 - INFO - PUT-3181447 - Request from disroot.org
2016-12-30 02:56:04,443 - synapse.access.http.8080 - 91 - INFO - PUT-3181447 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 35ms (0ms, 0ms) (20ms/3) 11B 200 "PUT /_matrix/federation/v1/send/1483039212956/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 03:03:17,596 - synapse.federation.transport.server - 138 - INFO - PUT-3210817 - Request from disroot.org
2016-12-30 03:03:17,599 - synapse.access.http.8080 - 91 - INFO - PUT-3210817 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 4ms (0ms, 0ms) (0ms/2) 49B 200 "PUT /_matrix/federation/v1/send/1483039212976/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 03:10:05,445 - synapse.federation.transport.server - 138 - INFO - PUT-3241402 - Request from disroot.org
2016-12-30 03:11:07,323 - synapse.federation.transport.server - 138 - INFO - PUT-3245635 - Request from disroot.org
2016-12-30 03:12:25,327 - synapse.federation.transport.server - 138 - INFO - PUT-3250887 - Request from disroot.org
2016-12-30 03:14:35,309 - synapse.federation.transport.server - 138 - INFO - PUT-3259791 - Request from disroot.org
2016-12-30 03:16:58,756 - synapse.federation.transport.server - 138 - INFO - PUT-3268750 - Request from disroot.org
2016-12-30 03:19:03,568 - synapse.federation.transport.server - 138 - INFO - PUT-3277416 - Request from disroot.org
2016-12-30 03:21:22,362 - synapse.federation.transport.server - 138 - INFO - PUT-3287568 - Request from disroot.org
2016-12-30 03:23:26,122 - synapse.federation.transport.server - 138 - INFO - PUT-3295976 - Request from disroot.org
2016-12-30 03:25:35,499 - synapse.federation.transport.server - 138 - INFO - PUT-3305687 - Request from disroot.org
2016-12-30 03:27:29,209 - synapse.federation.transport.server - 138 - INFO - PUT-3313044 - Request from disroot.org
2016-12-30 03:29:20,775 - synapse.federation.transport.server - 138 - INFO - PUT-3320742 - Request from disroot.org
2016-12-30 03:41:07,860 - synapse.federation.transport.server - 138 - INFO - PUT-3372471 - Request from disroot.org
2016-12-30 03:42:10,447 - synapse.federation.transport.server - 138 - INFO - PUT-3377058 - Request from disroot.org
2016-12-30 03:43:24,048 - synapse.federation.transport.server - 138 - INFO - PUT-3382743 - Request from disroot.org
2016-12-30 03:45:34,454 - synapse.federation.transport.server - 138 - INFO - PUT-3391664 - Request from disroot.org
2016-12-30 03:47:42,648 - synapse.federation.transport.server - 138 - INFO - PUT-3401472 - Request from disroot.org
2016-12-30 03:49:51,242 - synapse.federation.transport.server - 138 - INFO - PUT-3411124 - Request from disroot.org
2016-12-30 03:52:04,420 - synapse.federation.transport.server - 138 - INFO - PUT-3420748 - Request from disroot.org
2016-12-30 03:53:56,141 - synapse.federation.transport.server - 138 - INFO - PUT-3428525 - Request from disroot.org
2016-12-30 03:56:04,713 - synapse.federation.transport.server - 138 - INFO - PUT-3437552 - Request from disroot.org
2016-12-30 03:58:05,410 - synapse.federation.transport.server - 138 - INFO - PUT-3445739 - Request from disroot.org
2016-12-30 04:00:24,892 - synapse.federation.transport.server - 138 - INFO - PUT-3454960 - Request from disroot.org
2016-12-30 04:53:20,476 - synapse.federation.transport.server - 138 - INFO - PUT-3696149 - Request from disroot.org
2016-12-30 04:54:25,662 - synapse.federation.transport.server - 138 - INFO - PUT-3701446 - Request from disroot.org
2016-12-30 04:55:41,612 - synapse.federation.transport.server - 138 - INFO - PUT-3708327 - Request from disroot.org
2016-12-30 04:57:47,805 - synapse.federation.transport.server - 138 - INFO - PUT-3720699 - Request from disroot.org
2016-12-30 04:59:50,613 - synapse.federation.transport.server - 138 - INFO - PUT-3732643 - Request from disroot.org
2016-12-30 05:02:00,601 - synapse.federation.transport.server - 138 - INFO - PUT-3745522 - Request from disroot.org
2016-12-30 05:04:21,411 - synapse.federation.transport.server - 138 - INFO - PUT-3758583 - Request from disroot.org
2016-12-30 05:06:32,774 - synapse.federation.transport.server - 138 - INFO - PUT-3771427 - Request from disroot.org
2016-12-30 05:08:22,756 - synapse.federation.transport.server - 138 - INFO - PUT-3781240 - Request from disroot.org
2016-12-30 05:10:19,169 - synapse.federation.transport.server - 138 - INFO - PUT-3791370 - Request from disroot.org
2016-12-30 05:12:36,919 - synapse.federation.transport.server - 138 - INFO - PUT-3803651 - Request from disroot.org
2016-12-30 08:17:36,659 - synapse.federation.transport.server - 138 - INFO - PUT-4699188 - Request from disroot.org
2016-12-30 08:18:42,059 - synapse.federation.transport.server - 138 - INFO - PUT-4704012 - Request from disroot.org
2016-12-30 08:20:03,411 - synapse.federation.transport.server - 138 - INFO - PUT-4710092 - Request from disroot.org
2016-12-30 08:22:27,034 - synapse.federation.transport.server - 138 - INFO - PUT-4720696 - Request from disroot.org
2016-12-30 08:24:24,145 - synapse.federation.transport.server - 138 - INFO - PUT-4730839 - Request from disroot.org
2016-12-30 08:26:47,468 - synapse.federation.transport.server - 138 - INFO - PUT-4740693 - Request from disroot.org
2016-12-30 08:29:00,925 - synapse.federation.transport.server - 138 - INFO - PUT-4750102 - Request from disroot.org
2016-12-30 08:31:21,338 - synapse.federation.transport.server - 138 - INFO - PUT-4760041 - Request from disroot.org
2016-12-30 08:33:29,666 - synapse.federation.transport.server - 138 - INFO - PUT-4769517 - Request from disroot.org
2016-12-30 08:35:44,390 - synapse.federation.transport.server - 138 - INFO - PUT-4779223 - Request from disroot.org
2016-12-30 08:38:05,526 - synapse.federation.transport.server - 138 - INFO - PUT-4788798 - Request from disroot.org
2016-12-30 08:46:18,587 - synapse.federation.transport.server - 138 - INFO - PUT-4823173 - Request from disroot.org
2016-12-30 08:47:22,358 - synapse.federation.transport.server - 138 - INFO - PUT-4828143 - Request from disroot.org
2016-12-30 08:48:43,516 - synapse.federation.transport.server - 138 - INFO - PUT-4833717 - Request from disroot.org
2016-12-30 08:50:48,768 - synapse.federation.transport.server - 138 - INFO - PUT-4842599 - Request from disroot.org
2016-12-30 08:52:50,997 - synapse.federation.transport.server - 138 - INFO - PUT-4851366 - Request from disroot.org
2016-12-30 08:55:11,112 - synapse.federation.transport.server - 138 - INFO - PUT-4861127 - Request from disroot.org
2016-12-30 08:57:08,757 - synapse.federation.transport.server - 138 - INFO - PUT-4869007 - Request from disroot.org
2016-12-30 08:59:07,421 - synapse.federation.transport.server - 138 - INFO - PUT-4876932 - Request from disroot.org
2016-12-30 09:01:21,715 - synapse.federation.transport.server - 138 - INFO - PUT-4886697 - Request from disroot.org
2016-12-30 09:03:14,222 - synapse.federation.transport.server - 138 - INFO - PUT-4894928 - Request from disroot.org
2016-12-30 09:05:30,382 - synapse.federation.transport.server - 138 - INFO - PUT-4904708 - Request from disroot.org
2016-12-30 09:11:34,572 - synapse.federation.transport.server - 138 - INFO - GET-4929651 - Request from disroot.org
2016-12-30 09:11:34,573 - synapse.access.http.8080 - 91 - INFO - GET-4929651 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 2ms (0ms, 0ms) (0ms/0) 80B 429 "GET /_matrix/federation/v1/event_auth/!zYbmJBUierHCOIgeEi:matrix.org/$1483069834242866IqUif:matrix.org HTTP/1.1" "Synapse/0.18.5"
2016-12-30 09:11:34,915 - synapse.federation.transport.server - 138 - INFO - PUT-4929672 - Request from disroot.org
2016-12-30 09:11:34,916 - synapse.access.http.8080 - 91 - INFO - PUT-4929672 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 2ms (0ms, 0ms) (0ms/0) 80B 429 "PUT /_matrix/federation/v1/send/1483081149010/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 09:11:34,963 - synapse.federation.transport.server - 138 - INFO - GET-4929680 - Request from disroot.org
2016-12-30 09:11:34,963 - synapse.access.http.8080 - 91 - INFO - GET-4929680 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 1ms (0ms, 0ms) (0ms/0) 80B 429 "GET /_matrix/federation/v1/event_auth/!zYbmJBUierHCOIgeEi:matrix.org/$1483070684246704ZKxFF:matrix.org HTTP/1.1" "Synapse/0.18.5"
2016-12-30 09:11:35,265 - synapse.federation.transport.server - 138 - INFO - PUT-4929713 - Request from disroot.org
2016-12-30 09:11:35,265 - synapse.access.http.8080 - 91 - INFO - PUT-4929713 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 1ms (0ms, 0ms) (0ms/0) 80B 429 "PUT /_matrix/federation/v1/send/1483081149011/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 09:11:35,379 - synapse.federation.transport.server - 138 - INFO - PUT-4929724 - Request from disroot.org
2016-12-30 09:11:35,379 - synapse.access.http.8080 - 91 - INFO - PUT-4929724 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 2ms (0ms, 0ms) (0ms/0) 80B 429 "PUT /_matrix/federation/v1/send/1483081149012/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 09:11:35,535 - synapse.federation.transport.server - 138 - INFO - PUT-4929744 - Request from disroot.org
2016-12-30 09:11:35,535 - synapse.access.http.8080 - 91 - INFO - PUT-4929744 - 178.21.23.139 - 8080 - {disroot.org} Processed request: 2ms (0ms, 0ms) (0ms/0) 80B 429 "PUT /_matrix/federation/v1/send/1483081149013/ HTTP/1.1" "Synapse/0.18.5"
2016-12-30 09:11:35,678 - synapse.federation.transport.server - 138 - INFO - PUT-4929755 - Request from disroot.org

@ara4n
Copy link
Member Author

ara4n commented Dec 30, 2016

However, the reason these requests never return seems to be different to #1733. They certainly don't seem to be directly triggering get_missing_events requests which then block. They either get blocked whilst trying to talk to disroot (which has been marked as unavailable due to having #1733 problems of its own)... or due to being blocked on some other stuck federation activity on curbaf. Digging further.

NegativeMjark pushed a commit that referenced this issue Dec 30, 2016
get_missing_events used to fallback to fetching the missing events
individually requesting from every server in the room, one by one.e

This could be unacceptably slow, possibly causing #1732
@ara4n
Copy link
Member Author

ara4n commented Dec 30, 2016

Mjark reckons that they were blocked on the room lineariser for other unrelated get_missing_events activity. Meanwhile we only let 3 transactions execute concurrently from the same host before we start queuing, so to quote Mjark:

So my theory is that we had:

  1. requests that blocked for 14hours because they were fetching events
  2. requests that were blocked behind the first kind by the room linearizer
  3. requests that were blocked behind the first and second kind by the federation ratelimiter.

Therefore the 429ing here was actually correct behaviour, and i'm going to close this in favour of the main woes in #1733.

@ara4n ara4n closed this as completed Dec 30, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant