element-hq / element-hq/synapse
HTTP proxy connect error overly spammy and error level too high
- Dominant language
- Python
- Stars
- 4.6k
- Forks
- 600
- Avg merge
- 5d 22h
- Merged PRs (30d)
- 51
Description
### 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
```shell
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 | --- ---
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_
Contributor guide
Research direction
Start in synapse/http/connectproxyclient.py, especially ProxyConnectError and handleStatus, which appear in the reported traceback. Reproduce with HTTP_PROXY and HTTPS_PROXY configured, then verify that remote or proxy connection failures are logged at a lower severity without the Twisted stack trace; the issue does not name a test to run.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- networking
- Issue type
- Bug
- Difficulty
- 3/5
- Estimated time
- 1-2 days
- Activity status
- Stale
- Clarity
- Clearly specified
- Newbie friendliness
- 48/100