element-hq / element-hq/synapse

HTTP proxy connect error overly spammy and error level too high

Open
#16,860 6 comments 1 reaction 0 assignees View on GitHub
A-Logging O-Uncommon S-Tolerable T-Defect
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.