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

client connection leaks if it causes a federation connection which times out #2179

Closed
richvdh opened this issue May 2, 2017 · 1 comment
Closed

client connection leaks if it causes a federation connection which times out #2179

richvdh opened this issue May 2, 2017 · 1 comment

Comments

@richvdh
Copy link
Member

richvdh commented May 2, 2017

Basically, we never send the response back to the client.
@richvdh
Copy link
Member Author

richvdh commented May 2, 2017 

2017-04-07 11:14:09,074 - synapse.access.https.8447 - 59 - INFO - GET-12- 81.2.100.169 - 8447 - Received request: GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/displayname?access_token=<redacted>
2017-04-07 11:14:09,075 - synapse.storage.txn - 229 - DEBUG - GET-12- [TXN START] {get_profile_displayname-1e}
2017-04-07 11:14:09,076 - synapse.storage.txn - 285 - DEBUG - GET-12- [TXN END] {get_profile_displayname-1e} 1.090088
2017-04-07 11:14:09,079 - synapse.access.https.8447 - 91 - INFO - GET-12- 81.2.100.169 - 8447 - {None} Processed request: 5ms (0ms, 0ms) (1ms/1) 22B 200 "GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/displayname?access_token=<redacted> HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36"
2017-04-07 11:16:15,095 - synapse.access.https.8447 - 59 - INFO - GET-12- 81.2.100.169 - 8447 - Received request: GET /_matrix/client/api/v1/voip/turnServer?access_token=<redacted>
2017-04-07 11:16:15,098 - synapse.access.https.8447 - 91 - INFO - GET-12- 81.2.100.169 - 8447 - {@richvdh:matrixtest.sw1v.org} Processed request: 2ms (0ms, 0ms) (0ms/0) 22B 200 "GET /_matrix/client/api/v1/voip/turnServer?access_token=<redacted> HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36"
2017-04-07 11:18:11,101 - synapse.access.https.8447 - 59 - INFO - GET-12- 81.2.100.169 - 8447 - Received request: GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/avatar_url?access_token=<redacted>
2017-04-07 11:18:11,102 - synapse.storage.txn - 228 - DEBUG - GET-12- [TXN START] {get_profile_avatar_url-1e}
2017-04-07 11:18:11,103 - synapse.storage.txn - 284 - DEBUG - GET-12- [TXN END] {get_profile_avatar_url-1e} 0.982910
2017-04-07 11:18:11,105 - synapse.access.https.8447 - 91 - INFO - GET-12- 81.2.100.169 - 8447 - {None} Processed request: 3ms (0ms, 0ms) (0ms/1) 22B 200 "GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/avatar_url?access_token=<redacted> HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36"
2017-04-07 11:23:59,935 - synapse.access.https.8447 - 59 - INFO - GET-12- 81.2.100.169 - 8447 - Received request: GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/avatar_url?access_token=<redacted>
2017-04-07 11:23:59,935 - synapse.storage.txn - 228 - DEBUG - GET-12- [TXN START] {get_profile_avatar_url-1e}
2017-04-07 11:23:59,936 - synapse.storage.txn - 284 - DEBUG - GET-12- [TXN END] {get_profile_avatar_url-1e} 0.309326
2017-04-07 11:23:59,937 - synapse.access.https.8447 - 91 - INFO - GET-12- 81.2.100.169 - 8447 - {None} Processed request: 2ms (3ms, 0ms) (0ms/1) 22B 200 "GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/avatar_url?access_token=<redacted> HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36"
2017-04-07 11:31:56,746 - synapse.access.https.8447 - 59 - INFO - GET-12- 81.2.100.169 - 8447 - Received request: GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/avatar_url?access_token=<redacted>
2017-04-07 11:31:56,749 - synapse.storage.txn - 228 - DEBUG - GET-12- [TXN START] {get_profile_avatar_url-1e}
2017-04-07 11:31:56,750 - synapse.storage.txn - 284 - DEBUG - GET-12- [TXN END] {get_profile_avatar_url-1e} 0.406250
2017-04-07 11:31:56,751 - synapse.access.https.8447 - 91 - INFO - GET-12- 81.2.100.169 - 8447 - {None} Processed request: 5ms (0ms, 0ms) (0ms/1) 22B 200 "GET /_matrix/client/api/v1/profile/%40richvdh%3Amatrixtest.sw1v.org/avatar_url?access_token=<redacted> HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36"
2017-05-02 11:39:41,049 - synapse.access.https.8447 - 59 - INFO - GET-12- 81.2.100.169 - 8447 - Received request: GET /_matrix/client/api/v1/events?access_token=<redacted>&from=s125_323_0_2_1_1_36_2&timeout=30000
2017-05-02 11:39:41,051 - synapse.handlers.events - 52 - DEBUG - GET-12- Invoked 'get_stream' with args: auth_user_id=@richvdh:matrixtest.sw1v.org, affect_presence=True, self=<synapse.handlers.events.EventStreamHandler object..., as_client_event=True, room_id=None, timeout=30000, is_guest=False, pagin_config=PaginationConfig(from_tok=Token(room_key='s125', p..., only_keys=None
2017-05-02 11:40:12,377 - synapse.storage.txn - 231 - DEBUG - GET-12- [TXN START] {update_presence-3e}
2017-05-02 11:40:12,379 - synapse.access.https.8447 - 91 - INFO - GET-12- 81.2.100.169 - 8447 - {@richvdh:matrixtest.sw1v.org} Processed request: 31330ms (3ms, 0ms) (0ms/0) 69B 200 "GET /_matrix/client/api/v1/events?access_token=<redacted>&from=s125_323_0_2_1_1_36_2&timeout=30000 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36"
2017-05-02 11:40:12,381 - synapse.storage.txn - 287 - DEBUG - GET-12- [TXN END] {update_presence-3e} 4.015137
2017-05-02 11:40:12,382 - synapse.util.logcontext - 260 - DEBUG - GET-12- Restoring dead context: GET-12@7f56385f6d70
2017-05-02 11:40:12,383 - synapse.util.logcontext - 260 - DEBUG - GET-12- Restoring dead context: GET-12@7f56385f6d70
2017-05-02 11:40:12,383 - synapse.util.logcontext - 260 - DEBUG - GET-12- Restoring dead context: GET-12@7f56385f6d70
2017-05-02 11:40:12,384 - synapse.util.logcontext - 260 - DEBUG - GET-12- Restoring dead context: GET-12@7f56385f6d70
2017-05-02 11:56:19,774 - synapse.access.https.8447 - 59 - INFO - GET-12- 81.2.100.169 - 8447 - Received request: GET /_matrix/client/r0/directory/room/%23matrix-dev%3Amatrix.org?access_token=<redacted>
2017-05-02 11:56:19,775 - synapse.federation.federation_client - 89 - DEBUG - GET-12- Invoked 'make_query' with args: retry_on_dns_fail=False, args={'room_alias': u'#matrix-dev:matrix.org'}, query_type=directory, self=<ReplicationLayer(matrixtest.sw1v.org)>, destination=matrix.org, ignore_backoff=True
2017-05-02 11:56:19,775 - synapse.federation.transport.client - 176 - DEBUG - GET-12- Invoked 'make_query' with args: retry_on_dns_fail=False, args={'room_alias': u'#matrix-dev:matrix.org'}, query_type=directory, self=<synapse.federation.transport.client.TransportLaye..., destination=matrix.org, ignore_backoff=True
2017-05-02 11:56:19,775 - synapse.http.matrixfederationclient - 421 - DEBUG - GET-12- get_json args: {'room_alias': u'#matrix-dev:matrix.org'}
2017-05-02 11:56:19,775 - synapse.http.matrixfederationclient - 430 - DEBUG - GET-12- Query bytes: {'room_alias': u'#matrix-dev:matrix.org'} Retry DNS: False
2017-05-02 11:56:19,776 - synapse.storage.txn - 231 - DEBUG - GET-12- [TXN START] {get_destination_retry_timings-a}
2017-05-02 11:56:19,776 - synapse.storage.txn - 287 - DEBUG - GET-12- [TXN END] {get_destination_retry_timings-a} 0.452148
2017-05-02 11:56:19,777 - synapse.http.outbound - 152 - INFO - GET-12- {GET-O-1} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/federation/v1/query/directory?room_alias=%23matrix-dev%3Amatrix.org
2017-05-02 11:56:29,781 - synapse.http.matrixfederationclient - 211 - WARNING - GET-12- {GET-O-1} Sending request failed to matrix.org: GET matrix://matrix.org/_matrix/federation/v1/query/directory?room_alias=%23matrix-dev%3Amatrix.org: DeferredTimedOutError - DeferredTimedOutError: 504: Timed out
2017-05-02 11:56:29,781 - synapse.http.outbound - 237 - INFO - GET-12- {GET-O-1} [matrix.org] Result: DeferredTimedOutError - DeferredTimedOutError: 504: Timed out
2017-05-02 11:56:29,782 - synapse.util.retryutils - 182 - DEBUG - GET-12- Connection to matrix.org was unsuccessful (<class 'synapse.util.DeferredTimedOutError'>(504: Timed out)); backoff now 600000
2017-05-02 11:56:29,782 - synapse.storage.txn - 231 - DEBUG - GET-12- [TXN START] {set_destination_retry_timings-b}
2017-05-02 11:56:29,783 - root - 181 - WARNING - GET-12- Error retrieving alias
2017-05-02 11:56:29,783 - synapse.http.server - 123 - INFO - GET-12- <SynapseRequest at 0x7fe091e3ccf8 method=GET uri=/_matrix/client/r0/directory/room/%23matrix-dev%3Amatrix.org?access_token=<redacted> clientproto=HTTP/1.1 site=8447> SynapseError: 504 - Timed out
2017-05-02 11:56:29,784 - twisted - 131 - CRITICAL - - Unhandled error in Deferred:
2017-05-02 11:56:29,785 - twisted - 131 - CRITICAL - - 
Traceback (most recent call last):
  File "/opt/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1299, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/http/server.py", line 129, in wrapped_request_handler
  File "synapse/api/errors.py", line 227, in cs_exception
  File "synapse/api/errors.py", line 90, in error_dict
AttributeError: 'DeferredTimedOutError' object has no attribute 'errcode'
2017-05-02 11:56:29,789 - twisted - 131 - INFO - - Stopping factory <twisted.web.client._HTTP11ClientFactory instance at 0x7fe092793d88>
2017-05-02 11:56:29,796 - synapse.storage.txn - 287 - DEBUG - GET-12- [TXN END] {set_destination_retry_timings-b} 13.510010
2017-05-02 11:56:29,796 - synapse.util.logcontext - 260 - DEBUG - GET-12- Restoring dead context: GET-12@7fe0928b6ec0

@richvdh richvdh mentioned this issue May 2, 2017
Closed
richvdh added a commit that referenced this issue May 2, 2017
@richvdh
Instantiate DeferredTimedOutError correctly
2e99627 
Call `super` correctly, so that we correctly initialise the `errcode` field.

Fixes #2179.
@richvdh richvdh mentioned this issue May 2, 2017
Merged
@richvdh richvdh closed this as completed May 2, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@richvdh