HTTP proxy connect error overly spammy and error level too high

schildbach commented 8 months ago

Description

I started proxying outbound requests via HTTP proxy (Squid), and now every remote server problem (HTTP error from peer, even transient HTTP errors, DNS error) is being logged with error level CRITICAL and includes a lengthy stack trace that doesn't help because the problem is caused by a federating peer.

See example log output below.

I would argue that remote servers errors should be logged at a much lower level, maybe INFO. And it should not contain any stack trace, as that's useless.

My proxy specific config (for docker-compose):

    environment:
      - HTTP_PROXY=http://10.10.10.111:3128
      - HTTPS_PROXY=http://10.10.10.111:3128

Steps to reproduce

configure Synapse to use HTTP proxy for outbound requests (env variables HTTPS_PROXY and HTTP_PROXY)
restart Synapse
wait a bit until federation starts
watch the log being spammed with stack traces

Homeserver

matrix.schildbach.de

Synapse Version

1.99.0

Installation Method

Docker (matrixdotorg/synapse)

Database

postgres, single

Workers

Single process

Platform

Docker version 20.10.24+dfsg1, build 297e128

Configuration

No response

Relevant log output

synapse_1                      | 2024-01-28 14:57:24,707 - twisted - 280 - CRITICAL - sentinel - Unhandled Error
synapse_1                      | Traceback (most recent call last):
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/python/log.py", line 96, in callWithLogger
synapse_1                      |     return callWithContext({"system": lp}, func, *args, **kw)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/python/log.py", line 80, in callWithContext
synapse_1                      |     return context.call({ILogContext: newCtx}, func, *args, **kw)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
synapse_1                      |     return self.currentContext().callWithContext(ctx, func, *args, **kw)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
synapse_1                      |     return func(*args, **kw)
synapse_1                      | --- <exception caught here> ---
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/internet/posixbase.py", line 482, in _doReadOrWrite
synapse_1                      |     why = selectable.doRead()
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/internet/tcp.py", line 248, in doRead
synapse_1                      |     return self._dataReceived(data)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/internet/tcp.py", line 253, in _dataReceived
synapse_1                      |     rval = self.protocol.dataReceived(data)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/internet/endpoints.py", line 151, in dataReceived
synapse_1                      |     return self._wrappedProtocol.dataReceived(data)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/synapse/http/connectproxyclient.py", line 254, in dataReceived
synapse_1                      |     return self.http_setup_client.dataReceived(data)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/protocols/basic.py", line 549, in dataReceived
synapse_1                      |     why = self.lineReceived(line)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/twisted/web/http.py", line 664, in lineReceived
synapse_1                      |     self.handleStatus(version, status, message)
synapse_1                      |   File "/usr/local/lib/python3.11/site-packages/synapse/http/connectproxyclient.py", line 294, in handleStatus
synapse_1                      |     raise ProxyConnectError(f"Unexpected status on CONNECT: {status!s}")
synapse_1                      | synapse.http.connectproxyclient.ProxyConnectError: An error occurred while connecting: Unexpected status on CONNECT: b'503'.

Anything else that would be useful to know?

No response

reivilibre commented 8 months ago

Does this actually happen for HTTP errors (status codes), or just timeouts/connection refused/DNS errors at the proxy etc?

I would expect the latter (and for 503 that makes sense). Agreed we should treat this just like a TCP-level error.

schildbach commented 8 months ago

I think both.

schildbach commented 8 months ago

For reference, timeouts are much less spammy when no outbound proxy is used:

2024-01-31 12:58:05,213 - synapse.util.retryutils - 283 - INFO - federation_transaction_transmission_loop-21405 - Connection to matrix.dagfinsen.no was unsuccessful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: TimeoutError: User timeout caused connection failure.)); backoff now 604800000
2024-01-31 12:58:05,214 - synapse.federation.sender.per_destination_queue - 417 - WARNING - federation_transaction_transmission_loop-21405 - TX [matrix.dagfinsen.no] Failed to send transaction: Failed to send request: TimeoutError: User timeout caused connection failure.

Or this is a cancelled connection:

2024-01-31 13:02:45,623 - synapse.util.retryutils - 283 - INFO - federation_transaction_transmission_loop-545 - Connection to mtx.0ef.de was unsuccessful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.defer.CancelledError: >])); backoff now 600000
2024-01-31 13:02:45,623 - synapse.federation.sender.per_destination_queue - 417 - WARNING - federation_transaction_transmission_loop-545 - TX [mtx.0ef.de] Failed to send transaction: Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.defer.CancelledError: >]

Failed certificate verification:

2024-01-31 13:04:04,724 - synapse.util.retryutils - 283 - INFO - federation_transaction_transmission_loop-26242 - Connection to imyxh.net was un
successful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: RequestTransmissionFailed: [<twisted.python.failure.Failure OpenSSL.SSL.Error: [('system library', '', ''),
 ('system library', '', ''), ('SSL routines', '', 'certificate verify failed')]>])); backoff now 1187939
2024-01-31 13:04:04,724 - synapse.federation.sender.per_destination_queue - 417 - WARNING - federation_transaction_transmission_loop-26242 - TX 
[imyxh.net] Failed to send transaction: Failed to send request: RequestTransmissionFailed: [<twisted.python.failure.Failure OpenSSL.SSL.Error: [('system library', '', ''), ('system library',
 '', ''), ('SSL routines', '', 'certificate verify failed')]>]

element-hq / synapse