fix(proxy): name the reason when the Control D forwarder answers 502

docs/guide/proxies-and-vpn.md

@@ -462,11 +462,18 @@ it next needs them.
 
 ### Troubleshooting Control D
 
+When the forwarder cannot connect to a host, it answers `502 Bad Gateway` and gives the reason in brackets.
+Python-Requests shows it as `Tunnel connection failed: 502 Bad Gateway (<reason>)`. The forwarder also logs
+each reason once as a warning, `Could not reach <host>:<port>: <reason>`, because some HTTP clients do not
+show the reason.
+
 | Symptom | Cause and fix |
 |---|---|
 | `Proxy check failed`, because the exit IP is your own IP. | The profile does not redirect. Make sure that the plan includes traffic redirection (*Full Control*, not *Some Control*). After a region change, wait for the TTL of the previous answer to end. |
-| A `502 Bad Gateway` for one host. With `-d`, the log shows `Control D returned no A record for …`. | Control D gave no IPv4 address for that host. |
-| A `502 Bad Gateway` for one host only. With `-d`, the log shows `Refused …, an address that Control D cannot redirect`. | The request names the host by IP address. The forwarder refuses it. See the note on IPv4 above. |
+| `502 Bad Gateway (Control D returned no A record for …)` | Control D gave no IPv4 address for that host. |
+| `502 Bad Gateway (an IP address skips Control D's DNS …)` | The request names the host by IP address. The forwarder refuses it. See the note on IPv4 above. |
+| `502 Bad Gateway (Control D sent … to …, which did not answer: …)` | Control D gave an address for the host, but the connection to that address failed. This is usually a temporary fault on Control D's network. Try again, or use `--no-proxy-download` to download without the proxy. |
+| `502 Bad Gateway (Control D DNS timed out)`, `(Control D DNS could not be reached …)` or `(Control D DNS answered HTTP …)` | unshackle got no answer from Control D's DNS at `dns.controld.com`. Check the network connection of this machine. |
 | An HTTP `401` or `403` from `api.controld.com`. | The token is a *Read* token, or its *Allowed IPs* do not include this machine. Use a *Write* token. |
 | `Control D needs both a profile and a resolver` or `Control D needs max_profiles of 1 or more` at startup. | The `controld` config is not valid. Give `profile` and `resolver` together, and a `max_profiles` of 1 or more. Every run fails until you correct it, also a run that does not use Control D. |
 | `Could not read Control D's locations`. | unshackle could not get the location list. It tries again at the next Control D query. |

tests/core/test_controld_proxy.py

@@ -6,6 +6,7 @@ from __future__ import annotations
 
 import base64
 import http.server
+import logging
 import re
 import socket
 import socketserver
@@ -13,6 +14,7 @@ import threading
 import time
 from types import SimpleNamespace
 from typing import Iterator
+from unittest.mock import Mock
 
 import click
 import pytest
@@ -30,6 +32,7 @@ from unshackle.core.proxies.controld import (
     parse_a_records,
 )
 from unshackle.core.proxies.resolve import REGION, resolve_proxy
+from unshackle.core.utilities import get_free_port
 
 pytestmark = pytest.mark.unit
 
@@ -74,9 +77,12 @@ def origin(body: bytes) -> http.server.HTTPServer:
 
 
 @pytest.fixture
-def forwarder() -> Iterator[LocalProxy]:
-    """A forwarder whose resolver sends every hostname to 127.0.0.1, as Control D sends it to its proxy."""
-    proxy = LocalProxy(SimpleNamespace(resolve=lambda host: "127.0.0.1"))
+def forwarder(request: pytest.FixtureRequest) -> Iterator[LocalProxy]:
+    """A forwarder whose resolver sends every hostname to 127.0.0.1, as Control D sends it to its proxy.
+
+    A test can pass its own resolver as the indirect parameter.
+    """
+    proxy = LocalProxy(getattr(request, "param", None) or SimpleNamespace(resolve=lambda host: "127.0.0.1"))
     threading.Thread(target=proxy.serve_forever, daemon=True).start()
     yield proxy
     proxy.shutdown()
@@ -134,8 +140,8 @@ def test_connect_tunnels_bytes_both_ways(forwarder: LocalProxy) -> None:
 @pytest.mark.parametrize(
     ("target", "status"),
     [
-        ("1.2.3.4:443", b"502"),  # an IP literal would bypass Control D
-        ("[::1]:443", b"502"),
+        ("1.2.3.4:443", b"502 Bad Gateway (an IP address skips Control D's DNS"),
+        ("[::1]:443", b"502 Bad Gateway (an IP address skips Control D's DNS"),
         ("a.test:x", b"400"),
     ],
 )
@@ -145,18 +151,63 @@ def test_connect_refuses_what_it_cannot_redirect(forwarder: LocalProxy, target:
         assert client.recv(128).startswith(b"HTTP/1.1 " + status)
 
 
-def test_an_unreachable_host_answers_502() -> None:
-    def refuse(host: str) -> str:
-        raise ConnectionError("no A record")
+def failing_resolver(error: Exception) -> Resolver:
+    resolver = Resolver("https://dns.controld.com/SECRETID")
+    resolver.session = SimpleNamespace(get=Mock(side_effect=error))
+    return resolver
 
-    proxy = LocalProxy(SimpleNamespace(resolve=refuse))
-    threading.Thread(target=proxy.serve_forever, daemon=True).start()
-    try:
-        response = requests.get("http://unresolvable.test/", proxies={"http": proxy.uri}, timeout=10)
-        assert response.status_code == 502
-    finally:
-        proxy.shutdown()
-        proxy.server_close()
+
+@pytest.mark.parametrize(
+    ("error", "reason"),
+    [
+        (
+            requests.ConnectionError("HTTPSConnectionPool(host='dns.controld.com'): /SECRETID"),
+            "Control D DNS could not be reached (ConnectionError)",
+        ),
+        (requests.Timeout("read timed out: dns.controld.com/SECRETID"), "Control D DNS timed out"),
+        (
+            requests.HTTPError("503 for url: /SECRETID", response=SimpleNamespace(status_code=503)),
+            "Control D DNS answered HTTP 503",
+        ),
+    ],
+)
+def test_a_failed_lookup_hides_the_resolver(error: Exception, reason: str) -> None:
+    with pytest.raises(ConnectionError) as e:
+        failing_resolver(error).resolve("a.test")
+    assert str(e.value) == reason and e.value.__suppress_context__  # a traceback must not print the URL
+
+
+@pytest.mark.parametrize(
+    ("forwarder", "reason"),
+    [
+        (
+            SimpleNamespace(resolve=Mock(side_effect=ConnectionError("Control D returned no A record for a.test"))),
+            "no A record for a.test",
+        ),
+        (
+            failing_resolver(requests.ConnectionError("dns.controld.com: /SECRETID")),
+            "Control D DNS could not be reached",
+        ),
+        # a CR/LF left in the reason would end the status line early and cut the reason off
+        (
+            SimpleNamespace(resolve=Mock(side_effect=ConnectionError("no A record\r\nX-Injected: 1"))),
+            "no A record X-Injected: 1",
+        ),
+        (None, "Control D sent a.test to 127.0.0.1, which did not answer"),
+    ],
+    indirect=["forwarder"],
+)
+def test_a_failed_tunnel_names_the_reason(forwarder: LocalProxy, reason: str, caplog: pytest.LogCaptureFixture) -> None:
+    caplog.set_level(logging.WARNING, logger="ControlD")
+    with pytest.raises(requests.exceptions.ProxyError) as e:
+        requests.get(f"https://a.test:{get_free_port()}/", proxies={"https": forwarder.uri}, timeout=10)
+    assert "502 Bad Gateway (" in str(e.value) and reason in str(e.value)
+    assert "SECRETID" not in str(e.value)
+    response = requests.get(f"http://a.test:{get_free_port()}/", proxies={"http": forwarder.uri}, timeout=10)
+    assert response.status_code == 502
+    # clients that drop the reason phrase still get it once in the log
+    warnings = [r.getMessage() for r in caplog.records if r.levelno == logging.WARNING]
+    assert len(warnings) == 1 and reason in warnings[0]
 
 
 def stub_session(response: bytes, seen: list) -> object:

unshackle/core/proxies/controld.py

@@ -102,6 +102,7 @@ class Resolver:
         self.lock = threading.Lock()
 
     def resolve(self, host: str) -> str:
+        """Get the IPv4 address Control D gives `host`. A failure raises `ConnectionError` without the resolver ID."""
         host = host.lower()
         with self.lock:
             cached = self.cache.get(host)
@@ -109,13 +110,20 @@ class Resolver:
             return cached[0]
 
         query = base64.urlsafe_b64encode(build_query(host)).rstrip(b"=").decode()
-        response = self.session.get(
-            self.url,
-            params={"dns": query},
-            headers={"accept": "application/dns-message"},
-            timeout=DOH_TIMEOUT,
-        )
-        response.raise_for_status()
+        try:
+            response = self.session.get(
+                self.url,
+                params={"dns": query},
+                headers={"accept": "application/dns-message"},
+                timeout=DOH_TIMEOUT,
+            )
+            response.raise_for_status()
+        except requests.HTTPError as e:
+            raise ConnectionError(f"Control D DNS answered HTTP {e.response.status_code}") from None
+        except requests.Timeout:
+            raise ConnectionError("Control D DNS timed out") from None
+        except requests.RequestException as e:
+            raise ConnectionError(f"Control D DNS could not be reached ({type(e).__name__})") from None
 
         records = parse_a_records(response.content)
         if not records:
@@ -158,6 +166,17 @@ class Handler(socketserver.StreamRequestHandler):
         except OSError:
             pass
 
+    def refuse(self, host: str, port: int, reason: str) -> None:
+        """Answer 502 with the reason in the status line, which a client shows as `Tunnel connection failed: ...`.
+
+        Some HTTP clients drop the reason phrase, so this also logs each new reason once as a warning.
+        """
+        reason = " ".join(reason.split())
+        if (host, reason) not in self.server.refused:
+            self.server.refused.add((host, reason))
+            log.warning(f"Could not reach {host}:{port}: {reason}")
+        self.reply(f"502 Bad Gateway ({reason})".encode("latin-1", "replace"))
+
     def forward_response_head(self, upstream: socket.socket) -> None:
         """Send the response head on with `Connection: close`, so the client never reuses this connection."""
         data = b""
@@ -212,16 +231,16 @@ class Handler(socketserver.StreamRequestHandler):
         except ValueError:
             pass
         else:
-            # an IP literal bypasses Control D's DNS and would leak this machine's own IP
-            log.debug(f"Refused {host}:{port}, an address that Control D cannot redirect")
-            return self.reply(b"502 Bad Gateway")
+            return self.refuse(host, port, "an IP address skips Control D's DNS and would expose this machine's IP")
 
         try:
             ip = self.server.resolver.resolve(host)
-            upstream = socket.create_connection((ip, port), timeout=HEAD_TIMEOUT)
         except Exception as e:
-            log.debug(f"Could not reach {host}:{port}: {e}")
-            return self.reply(b"502 Bad Gateway")
+            return self.refuse(host, port, str(e) or type(e).__name__)
+        try:
+            upstream = socket.create_connection((ip, port), timeout=HEAD_TIMEOUT)
+        except OSError as e:
+            return self.refuse(host, port, f"Control D sent {host} to {ip}, which did not answer: {e.strerror or e}")
 
         self.connection.settimeout(IDLE_TIMEOUT)
         upstream.settimeout(IDLE_TIMEOUT)
@@ -253,6 +272,7 @@ class LocalProxy(socketserver.ThreadingTCPServer):
         """An HTTP forward proxy on loopback that resolves every host through `resolver`."""
         super().__init__(("127.0.0.1", 0), Handler)
         self.resolver = resolver
+        self.refused: set[tuple[str, str]] = set()
 
     @property
     def uri(self) -> str:
@@ -460,6 +480,7 @@ class ControlD(Proxy):
             if server:
                 with server.resolver.lock:
                     server.resolver.cache.clear()
+                server.refused.clear()
             REGIONS.pop(profile, None)
             REGIONS[profile] = query
             LOCATIONS[profile] = location