diff --git a/README.md b/README.md index ccbbdf4..6e1fe0b 100644 --- a/README.md +++ b/README.md @@ -212,6 +212,20 @@ name that only exists while the host is up cannot be used to wake it. Give the machine a DHCP reservation and a static DNS entry, or write the IP straight into the config. +### Names on the near side + +By default doormouse logs only the client's IP. Set `client_hostname_lookup = +true` to also log the client's hostname. doormouse gets it with a reverse-DNS +(PTR) lookup, so the request log shows which machine or service sent the +traffic. + +Lookups are best-effort and cached: hits for 30 minutes, failures for 2. +Concurrent requests from the same uncached IP share one lookup. + +> [!WARNING] +> The lookup is synchronous. On a cache miss, doormouse waits up to one second +> for it before it logs the request and forwards it. That is why the setting is +> opt-in. Leave it off if your network has no PTR records or slow DNS. ## Liveness and readiness There are two `health_check` fields and they answer different questions. diff --git a/client_resolver_regression_test.go b/client_resolver_regression_test.go new file mode 100644 index 0000000..78f4873 --- /dev/null +++ b/client_resolver_regression_test.go @@ -0,0 +1,91 @@ +package main + +import ( + "fmt" + "sync" + "testing" + "time" +) + +func TestClientResolverBoundsConcurrentDistinctLookups(t *testing.T) { + resolver := newClientResolver(true) + started := make(chan struct{}, 65) + release := make(chan struct{}) + var workers sync.WaitGroup + t.Cleanup(func() { + close(release) + workers.Wait() + }) + resolver.lookupFn = func(string, time.Duration) (string, error) { + started <- struct{}{} + <-release + return "nas.lan", nil + } + for index := 0; index < 64; index++ { + workers.Add(1) + go func() { + defer workers.Done() + resolver.resolve(fmt.Sprintf("192.0.2.%d", index+1)) + }() + select { + case <-started: + case <-time.After(time.Second): + t.Fatal("lookup did not start below the limit") + } + } + + done := make(chan bool, 1) + workers.Add(1) + go func() { + defer workers.Done() + _, ok := resolver.resolve("192.0.2.100") + done <- ok + }() + select { + case <-started: + t.Fatal("started DNS work beyond the 64-lookup limit") + case ok := <-done: + if ok { + t.Fatal("overloaded lookup should fall back to the IP") + } + case <-time.After(time.Second): + t.Fatal("overloaded lookup should not wait for capacity") + } + if resolver.hasKey("192.0.2.100") { + t.Fatal("overload must not be cached as a DNS failure") + } +} + +func TestClientResolverEvictsExpiredFailureBehindFreshSuccess(t *testing.T) { + resolver := newClientResolver(true) + resolver.maxEntries = 2 + resolver.store("192.0.2.1", "nas.lan") + resolver.store("192.0.2.2", "") + resolver.ageKey("192.0.2.1", 3*time.Minute) + resolver.ageKey("192.0.2.2", 3*time.Minute) + resolver.store("192.0.2.3", "new.lan") + + if host, ok := resolver.cached("192.0.2.1"); !ok || host != "nas.lan" { + t.Fatal("fresh success evicted while an expired failure existed") + } + if resolver.hasKey("192.0.2.2") || resolver.cacheSize() != 2 { + t.Fatal("expired failure must be removed and cache stay at capacity") + } +} + +func TestClientResolverRechecksCacheBeforeStartingLookup(t *testing.T) { + resolver := newClientResolver(true) + for _, hostname := range []string{"nas.lan", ""} { + resolver.store("192.0.2.1", hostname) + calls := 0 + resolver.lookupFn = func(string, time.Duration) (string, error) { + calls++ + return "unexpected.lan", nil + } + + got, err := resolver.lookupOnce("192.0.2.1") + if err != nil || got != hostname || calls != 0 { + t.Fatalf("lookup after another caller populated cache = (%q, %v), calls = %d; want (%q, nil), no calls", got, err, calls, hostname) + } + } +} diff --git a/client_resolver_test.go b/client_resolver_test.go new file mode 100644 index 0000000..cf74902 --- /dev/null +++ b/client_resolver_test.go @@ -0,0 +1,482 @@ +package main + +import ( + "context" + "errors" + "net" + "net/http/httptest" + "strings" + "sync" + "sync/atomic" + "testing" + "time" +) + +// --- clientResolver -------------------------------------------------------- + +// TestClientResolverDisabled checks that a disabled resolver never reaches the +// lookup function and never reports a hostname. +func TestClientResolverDisabled(t *testing.T) { + r := newClientResolver(false) + r.lookupFn = func(ip string, _ time.Duration) (string, error) { + t.Fatal("lookup must not run when the resolver is disabled") + return "", nil + } + if _, ok := r.resolve("192.0.2.1"); ok { + t.Fatal("expected no hostname when the resolver is disabled") + } +} + +// TestClientResolverCachesPositiveResult checks that a successful lookup is +// remembered, that its FQDN trailing dot is dropped, and that the second +// resolve for the same IP does no further DNS work. +func TestClientResolverCachesPositiveResult(t *testing.T) { + calls := 0 + r := newClientResolver(true) + r.lookupFn = func(ip string, _ time.Duration) (string, error) { + calls++ + return "nas.lan.", nil // trailing dot must be stripped + } + + host, ok := r.resolve("192.0.2.10") + if !ok || host != "nas.lan" { + t.Fatalf("got (%q, %v), want (nas.lan, true)", host, ok) + } + if _, ok := r.resolve("192.0.2.10"); !ok { + t.Fatal("cached hostname not returned on second resolve") + } + if calls != 1 { + t.Fatalf("expected 1 lookup, got %d", calls) + } +} + +// TestClientResolverCachesNegativeResult checks that a failed lookup is cached +// so a network without PTR records is not re-queried on every request. +func TestClientResolverCachesNegativeResult(t *testing.T) { + calls := 0 + r := newClientResolver(true) + r.lookupFn = func(ip string, _ time.Duration) (string, error) { + calls++ + return "", errors.New("no PTR record") + } + + for i := 0; i < 3; i++ { + if _, ok := r.resolve("192.0.2.11"); ok { + t.Fatal("expected no hostname") + } + } + if calls != 1 { + t.Fatalf("expected 1 lookup (negative results are cached), got %d", calls) + } +} + +// TestClientResolverNegativeTTLExpiry checks that a remembered failure is +// retried once its shorter negative TTL has passed. +func TestClientResolverNegativeTTLExpiry(t *testing.T) { + calls := 0 + r := newClientResolver(true) + r.negTTL = 15 * time.Millisecond + r.lookupFn = func(ip string, _ time.Duration) (string, error) { + calls++ + return "", errors.New("no PTR record") + } + + r.resolve("192.0.2.12") + time.Sleep(30 * time.Millisecond) + r.resolve("192.0.2.12") + + if calls != 2 { + t.Fatalf("expected the lookup to repeat after the negative TTL, got %d calls", calls) + } +} + +// TestClientResolverDifferentIPsAreIndependent checks that caching one IP does +// not stand in for another: each distinct IP gets its own lookup. +func TestClientResolverDifferentIPsAreIndependent(t *testing.T) { + seen := map[string]bool{} + r := newClientResolver(true) + r.lookupFn = func(ip string, _ time.Duration) (string, error) { + seen[ip] = true + return ip + ".example", nil + } + if _, ok := r.resolve("192.0.2.20"); !ok { + t.Fatal("expected hostname for 192.0.2.20") + } + if _, ok := r.resolve("192.0.2.21"); !ok { + t.Fatal("expected hostname for 192.0.2.21") + } + if len(seen) != 2 { + t.Fatalf("expected lookups for both IPs, saw %v", seen) + } +} + +// TestClientResolverCoalescesConcurrentLookups checks the single-flight path: +// a burst of requests from one uncached IP must share a single lookup instead +// of each request starting its own. +func TestClientResolverCoalescesConcurrentLookups(t *testing.T) { + r := newClientResolver(true) + + release := make(chan struct{}) + var calls int32 + r.lookupFn = func(ip string, _ time.Duration) (string, error) { + atomic.AddInt32(&calls, 1) + <-release // hold every in-flight lookup until the whole burst arrives + return ip + ".example", nil + } + + var wg sync.WaitGroup + for i := 0; i < 8; i++ { + wg.Add(1) + go func() { + defer wg.Done() + host, ok := r.resolve("192.0.2.30") + if !ok || host != "192.0.2.30.example" { + t.Errorf("resolve() = (%q, %v), want (192.0.2.30.example, true)", host, ok) + } + }() + } + time.Sleep(50 * time.Millisecond) // let the burst pile onto the first lookup + close(release) + wg.Wait() + + if n := atomic.LoadInt32(&calls); n != 1 { + t.Fatalf("expected 1 lookup for 8 concurrent requests, got %d", n) + } + if len(r.inFlightKeys()) != 0 { + t.Fatal("in-flight lookups must be cleared once they finish") + } +} + +// TestClientResolverEvictsOldestWhenCacheFull checks the hard cap: once the +// cache is full of entries that are all still fresh, inserting another IP +// evicts the oldest entry instead of growing the cache. +func TestClientResolverEvictsOldestWhenCacheFull(t *testing.T) { + r := newClientResolver(true) + r.maxEntries = 3 + r.lookupFn = func(ip string, _ time.Duration) (string, error) { + return ip + ".example", nil + } + + for _, ip := range []string{"192.0.2.1", "192.0.2.2", "192.0.2.3"} { + if _, ok := r.resolve(ip); !ok { + t.Fatalf("expected a hostname for %s", ip) + } + } + // The cache is at the cap and nothing has expired, so this insert has to + // evict rather than grow. + if _, ok := r.resolve("192.0.2.4"); !ok { + t.Fatal("expected a hostname for 192.0.2.4") + } + + if got := r.cacheSize(); got != 3 { + t.Fatalf("cache size = %d, want the cap of 3", got) + } + if r.hasKey("192.0.2.1") { + t.Fatal("the oldest entry should have been evicted to make room") + } + for _, ip := range []string{"192.0.2.2", "192.0.2.3", "192.0.2.4"} { + if !r.hasKey(ip) { + t.Fatalf("%s should still be cached", ip) + } + } +} + +// TestClientResolverPrunesExpiredBeforeEvicting checks that making room drops +// expired entries first: a fresh entry must survive when an expired one is +// available to free. +func TestClientResolverPrunesExpiredBeforeEvicting(t *testing.T) { + r := newClientResolver(true) + r.maxEntries = 2 + r.ttl = time.Hour + + r.store("192.0.2.1", "old.example") + r.store("192.0.2.2", "fresh.example") + r.ageKey("192.0.2.1", 2*time.Hour) + + r.store("192.0.2.3", "new.example") + + if got := r.cacheSize(); got != 2 { + t.Fatalf("cache size = %d, want the cap of 2", got) + } + if r.hasKey("192.0.2.1") { + t.Fatal("the expired entry should have been pruned") + } + if !r.hasKey("192.0.2.2") { + t.Fatal("a fresh entry must not be evicted while an expired one can be pruned") + } + if !r.hasKey("192.0.2.3") { + t.Fatal("the new entry should have been stored") + } +} + +// TestClientResolverUpdateAtCapacityDoesNotEvict checks that re-storing an IP +// that is already cached only replaces its value: it must not evict a sibling +// entry or change the cache size. +func TestClientResolverUpdateAtCapacityDoesNotEvict(t *testing.T) { + r := newClientResolver(true) + r.maxEntries = 2 + + r.store("192.0.2.1", "first.example") + r.store("192.0.2.2", "second.example") + r.store("192.0.2.1", "updated.example") + + if got := r.cacheSize(); got != 2 { + t.Fatalf("cache size = %d, want 2 (an update must not evict)", got) + } + if !r.hasKey("192.0.2.2") { + t.Fatal("updating 192.0.2.1 must not evict 192.0.2.2") + } + if got := r.hostnameFor("192.0.2.1"); got != "updated.example" { + t.Fatalf("hostname = %q, want updated.example", got) + } +} + +// TestClientResolverRefreshedEntryLeavesTheFrontOfOrder checks that re-storing a +// cached IP moves it to the back of the insertion order. Left at the front, a +// freshly refreshed entry stops makeRoomLocked's expired sweep dead in its +// tracks and then becomes the first entry evicted, so the one entry that had +// just been resolved again was the one dropped. +func TestClientResolverRefreshedEntryLeavesTheFrontOfOrder(t *testing.T) { + r := newClientResolver(true) + r.maxEntries = 3 + r.ttl = time.Hour + + r.store("192.0.2.1", "first.example") + r.store("192.0.2.2", "second.example") + r.store("192.0.2.3", "third.example") + + // 192.0.2.1 is the oldest entry, and it is the one refreshed. + r.store("192.0.2.1", "renewed.example") + r.store("192.0.2.4", "new.example") + + if got := r.cacheSize(); got != 3 { + t.Fatalf("cache size = %d, want the cap of 3", got) + } + if !r.hasKey("192.0.2.1") { + t.Fatal("the entry that had just been refreshed must not be the one evicted") + } + if r.hasKey("192.0.2.2") { + t.Fatal("192.0.2.2 is now the least recently resolved entry and should have been evicted") + } + if got := r.hostnameFor("192.0.2.1"); got != "renewed.example" { + t.Fatalf("hostname = %q, want renewed.example", got) + } +} + +// TestClientResolverDefaultCapIs8192 pins the production cap so a test-only +// override cannot quietly become the shipped value. +func TestClientResolverDefaultCapIs8192(t *testing.T) { + if got := newClientResolver(true).maxEntries; got != 8192 { + t.Fatalf("default maxEntries = %d, want 8192", got) + } +} + +// --- lookupClientAddr ------------------------------------------------------ + +// blockingResolver never answers a query: its dial blocks until the lookup's +// own context is done, which is exactly what a dead DNS server looks like. +func blockingResolver() *net.Resolver { + return &net.Resolver{ + PreferGo: true, + Dial: func(ctx context.Context, _, _ string) (net.Conn, error) { + <-ctx.Done() + return nil, ctx.Err() + }, + } +} + +// TestLookupClientAddrHonoursTimeout checks that the timeout bounds the DNS +// lookup itself: the call must fail near the deadline rather than waiting on +// the resolver to give up on its own. +func TestLookupClientAddrHonoursTimeout(t *testing.T) { + const timeout = 50 * time.Millisecond + + start := time.Now() + host, err := lookupClientAddr(blockingResolver(), "192.0.2.50", timeout) + elapsed := time.Since(start) + + if err == nil { + t.Fatalf("expected a timeout error, got (%q, nil)", host) + } + if host != "" { + t.Fatalf("hostname = %q, want empty on error", host) + } + if strings.Contains(err.Error(), "no DNS servers") { + t.Skipf("host has no DNS server for the resolver to dial: %v", err) + } + if elapsed < timeout { + t.Fatalf("returned after %s, before the %s deadline", elapsed, timeout) + } + if elapsed > 20*timeout { + t.Fatalf("returned after %s, want it to stop near the %s deadline", elapsed, timeout) + } +} + +// TestLookupClientAddrPropagatesResolverError checks that a resolver failure is +// returned as an error, which is what puts the IP in the negative cache. +func TestLookupClientAddrPropagatesResolverError(t *testing.T) { + unreachable := &net.Resolver{ + PreferGo: true, + Dial: func(_ context.Context, _, _ string) (net.Conn, error) { + return nil, errors.New("no such host") + }, + } + if _, err := lookupClientAddr(unreachable, "192.0.2.51", time.Second); err == nil { + t.Fatal("expected an error when the lookup yields no name") + } +} + +// --- clientAddr ------------------------------------------------------------ + +// TestClientAddrWithHostname checks that a resolved hostname is appended to the +// remote address in the request log. +func TestClientAddrWithHostname(t *testing.T) { + tp := newTestProxy(t, nil) + tp.svc.clientResolver = newClientResolver(true) + tp.svc.clientResolver.lookupFn = func(ip string, _ time.Duration) (string, error) { + if ip == "172.23.0.3" { + return "open-webui.", nil + } + return "", errors.New("no PTR record") + } + + req := httptest.NewRequest("GET", "/api/server/ping", nil) + req.RemoteAddr = "172.23.0.3:57648" + + if got := tp.svc.clientAddr(req); got != "172.23.0.3:57648 (hostname: open-webui)" { + t.Errorf("clientAddr = %q", got) + } +} + +// TestClientAddrUnresolvableAndForwarded checks that a failed lookup leaves the +// plain remote address in place, and that X-Forwarded-For is still reported. +func TestClientAddrUnresolvableAndForwarded(t *testing.T) { + tp := newTestProxy(t, nil) + tp.svc.clientResolver = newClientResolver(true) + tp.svc.clientResolver.lookupFn = func(ip string, _ time.Duration) (string, error) { + return "", errors.New("no PTR record") + } + + req := httptest.NewRequest("GET", "/api/server/ping", nil) + req.RemoteAddr = "203.0.113.7:1234" + if got := tp.svc.clientAddr(req); got != "203.0.113.7:1234" { + t.Errorf("clientAddr = %q", got) + } + + req.Header.Set("X-Forwarded-For", "192.168.50.15") + if got := tp.svc.clientAddr(req); got != "203.0.113.7:1234 (forwarded for 192.168.50.15)" { + t.Errorf("clientAddr = %q", got) + } +} + +// TestClientAddrLookupDisabled checks the default path: with the resolver off, +// the log gets the bare remote address and no DNS work happens. +func TestClientAddrLookupDisabled(t *testing.T) { + tp := newTestProxy(t, nil) + tp.svc.clientResolver = newClientResolver(false) + tp.svc.clientResolver.lookupFn = func(ip string, _ time.Duration) (string, error) { + t.Fatal("lookup must not run when the resolver is disabled") + return "", nil + } + + req := httptest.NewRequest("GET", "/api/server/ping", nil) + req.RemoteAddr = "172.23.0.3:57648" + if got := tp.svc.clientAddr(req); got != "172.23.0.3:57648" { + t.Errorf("clientAddr = %q", got) + } +} + +// TestClientIP checks that the bare IP is split off an "ip:port" remote +// address, for IPv6 as well as IPv4, and passed through when it cannot split. +func TestClientIP(t *testing.T) { + if got := clientIP("172.23.0.3:57648"); got != "172.23.0.3" { + t.Fatalf("clientIP = %q, want 172.23.0.3", got) + } + if got := clientIP("[::1]:4242"); got != "::1" { + t.Fatalf("clientIP = %q, want ::1", got) + } + if got := clientIP("garbage"); got != "garbage" { + t.Fatalf("clientIP = %q, want garbage (passthrough)", got) + } +} + +// --- config ----------------------------------------------------------------- + +// TestLoadConfigClientHostnameLookup checks that hostname lookup is off unless +// the key is set to true: an absent key and an explicit false both disable it, +// and only an explicit true enables it. +func TestLoadConfigClientHostnameLookup(t *testing.T) { + cfg, err := LoadConfig(writeTempConfig(t, machinesRoutesConfig), RealClock{}) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if cfg.ClientHostnameLookup { + t.Error("client_hostname_lookup must default to false when absent") + } + + // The key must sit in the top-level section, before any [[machines]] table. + disabled := "client_hostname_lookup = false\n" + strings.TrimLeft(machinesRoutesConfig, "\n") + cfg, err = LoadConfig(writeTempConfig(t, disabled), RealClock{}) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if cfg.ClientHostnameLookup { + t.Error("client_hostname_lookup = false must disable the lookup") + } + + enabled := "client_hostname_lookup = true\n" + strings.TrimLeft(machinesRoutesConfig, "\n") + cfg, err = LoadConfig(writeTempConfig(t, enabled), RealClock{}) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if !cfg.ClientHostnameLookup { + t.Error("client_hostname_lookup = true must enable the lookup as an explicit opt-in") + } +} + +// --- test helpers for the resolver's internals ------------------------------ + +// cacheSize reports how many entries the resolver currently remembers. +func (r *clientResolver) cacheSize() int { + r.mu.RLock() + defer r.mu.RUnlock() + return len(r.cache) +} + +// hasKey reports whether ip currently has an entry in the cache. +func (r *clientResolver) hasKey(ip string) bool { + r.mu.RLock() + defer r.mu.RUnlock() + _, ok := r.cache[ip] + return ok +} + +// hostnameFor returns the remembered hostname for ip, "" if it has none. +func (r *clientResolver) hostnameFor(ip string) string { + r.mu.RLock() + defer r.mu.RUnlock() + return r.cache[ip].hostname +} + +// inFlightKeys lists the IPs that currently have a lookup in flight. +func (r *clientResolver) inFlightKeys() []string { + r.mu.RLock() + defer r.mu.RUnlock() + keys := make([]string, 0, len(r.inFlight)) + for k := range r.inFlight { + keys = append(keys, k) + } + return keys +} + +// ageKey backdates an entry's resolved time by age so it reads as expired. +func (r *clientResolver) ageKey(ip string, age time.Duration) { + r.mu.Lock() + defer r.mu.Unlock() + entry, ok := r.cache[ip] + if !ok { + return + } + entry.resolvedAt = entry.resolvedAt.Add(-age) + r.cache[ip] = entry +} diff --git a/config.toml b/config.toml index 90722ec..7547400 100644 --- a/config.toml +++ b/config.toml @@ -18,6 +18,12 @@ server_idle_timeout = "120s" # How long to wait for the next request when kee poll_interval = "5s" # How often to check health while waiting health_check_interval = "30s" # Background health check frequency health_cache_duration = "10s" # How long to trust a cached health result +client_hostname_lookup = false # Reverse-DNS (PTR) lookup of client IPs for the request log. + # Opt-in: when true, a client IP that is not cached yet is looked + # up synchronously, which can add up to ~1s of latency before the + # incoming-request log line is written and the request is forwarded. + # Results are cached (successes 30m, failures 2m). Set to false to + # log plain IPs only (e.g. slow DNS, no PTR records, many clients). # Optional SSL configuration. Do not add these values unless you plan to use TLS/HTTPS #ssl_certificate = "/path/to/cert.pem" diff --git a/main.go b/main.go index 0bc73a8..66a9b01 100644 --- a/main.go +++ b/main.go @@ -111,6 +111,7 @@ type Config struct { ServerReadTimeout string `toml:"server_read_timeout,omitempty"` ServerWriteTimeout string `toml:"server_write_timeout,omitempty"` ServerIdleTimeout string `toml:"server_idle_timeout,omitempty"` + ClientHostnameLookup *bool `toml:"client_hostname_lookup,omitempty"` PollInterval string `toml:"poll_interval"` HealthCheckInterval string `toml:"health_check_interval"` HealthCacheDuration string `toml:"health_cache_duration"` @@ -219,6 +220,7 @@ type ProxyConfig struct { ServerReadTimeout time.Duration ServerWriteTimeout time.Duration ServerIdleTimeout time.Duration + ClientHostnameLookup bool PollInterval time.Duration HealthCheckInterval time.Duration HealthCacheDuration time.Duration @@ -593,14 +595,17 @@ func (w *UDPWOLSender) createMagicPacket(mac net.HardwareAddr) []byte { // Main proxy service type ProxyService struct { - config *ProxyConfig - healthChecker HealthChecker - wolSender WOLSender - sshExecutor SSHExecutor - logger Logger - clock Clock + config *ProxyConfig + healthChecker HealthChecker + wolSender WOLSender + sshExecutor SSHExecutor + clientResolver *clientResolver + logger Logger + clock Clock } +// NewProxyService wires the configuration to the health checker, WOL sender and +// SSH executor and returns the running proxy service. func NewProxyService( config *ProxyConfig, healthChecker HealthChecker, @@ -610,12 +615,13 @@ func NewProxyService( clock Clock, ) *ProxyService { return &ProxyService{ - config: config, - healthChecker: healthChecker, - wolSender: wolSender, - sshExecutor: sshExecutor, - logger: logger, - clock: clock, + config: config, + healthChecker: healthChecker, + wolSender: wolSender, + sshExecutor: sshExecutor, + clientResolver: newClientResolver(config.ClientHostnameLookup), + logger: logger, + clock: clock, } } @@ -884,13 +890,272 @@ func (p *ProxyService) serveOn(server *http.Server, listener net.Listener) error // when there is one, so an X-Forwarded-For it set is reported alongside RemoteAddr // rather than in place of it. That header is written by the caller and is only as // trustworthy as the hop that wrote it — fine for reading logs, not for decisions. -func clientAddr(r *http.Request) string { +// When the network provides PTR records and client_hostname_lookup is enabled, +// the peer's reverse-DNS hostname is reported alongside the address as well. +// That lookup is synchronous: on a cache miss it runs, for up to the resolver's +// timeout, before this returns — so it delays the incoming-request log line and +// the request itself. Hence the feature is opt-in. +func (p *ProxyService) clientAddr(r *http.Request) string { + addr := r.RemoteAddr + if host, ok := p.clientResolver.resolve(clientIP(addr)); ok { + addr = fmt.Sprintf("%s (hostname: %s)", addr, host) + } if forwarded := r.Header.Get("X-Forwarded-For"); forwarded != "" { - return fmt.Sprintf("%s (forwarded for %s)", r.RemoteAddr, forwarded) + return fmt.Sprintf("%s (forwarded for %s)", addr, forwarded) + } + return addr +} + +// clientIP extracts the bare IP from an "ip:port" remote address. +func clientIP(remoteAddr string) string { + ip, _, err := net.SplitHostPort(remoteAddr) + if err != nil { + return remoteAddr + } + return ip +} + +// clientResolver performs best-effort reverse DNS lookups for client IPs so +// that incoming requests can be logged with the client's hostname when the +// network provides PTR records. Results (including failures) are cached, so +// each unique IP triggers at most one lookup per TTL window. +// +// A lookup is synchronous: on a cache miss resolve waits for it, bounded by +// r.timeout, before returning. That wait sits in front of the incoming-request +// log line and in front of forwarding the request, which is why the feature is +// opt-in via client_hostname_lookup. +type clientResolver struct { + enabled bool + ttl time.Duration // how long a successful lookup is trusted + negTTL time.Duration // how long a failed lookup is remembered + timeout time.Duration // max wait for a single lookup + resolver *net.Resolver // resolver used for the PTR lookups + lookupFn func(ip string, timeout time.Duration) (string, error) + + // maxEntries is a hard ceiling on how many distinct IPs the cache holds. + maxEntries int + + mu sync.RWMutex + cache map[string]clientHostEntry + // order holds the cache keys oldest insertion first, so freeing a slot is + // a walk from the front rather than a scan of the whole map. + order []string + // inFlight has at most one lookup per IP; concurrent callers share it. + inFlight map[string]*clientLookup +} + +// clientHostEntry is one remembered result for an IP. +type clientHostEntry struct { + hostname string // empty for failed lookups + resolvedAt time.Time +} + +// clientLookup is a single in-flight reverse lookup. Concurrent resolvers that +// ask for the same uncached IP wait on this instead of each starting their own +// DNS work. +type clientLookup struct { + wg sync.WaitGroup + host string + err error +} + +// maxClientHostCacheEntries is the default hard cap on the number of distinct +// client IPs the resolver remembers. It is a ceiling, not a target. +const maxClientHostCacheEntries = 8192 +const maxClientHostLookups = 64 + +// newClientResolver returns a resolver honouring the configured setting; with +// enabled false it never looks anything up. +func newClientResolver(enabled bool) *clientResolver { + r := &clientResolver{ + enabled: enabled, + ttl: 30 * time.Minute, + negTTL: 2 * time.Minute, + timeout: time.Second, + resolver: net.DefaultResolver, + maxEntries: maxClientHostCacheEntries, + cache: make(map[string]clientHostEntry), + inFlight: make(map[string]*clientLookup), + } + r.lookupFn = func(ip string, timeout time.Duration) (string, error) { + return lookupClientAddr(r.resolver, ip, timeout) + } + return r +} + +// resolve returns the reverse DNS hostname for ip, or ("", false) when no name +// is known (or when the resolver is disabled). On a cache miss it blocks while +// the lookup runs, bounded by r.timeout; concurrent calls for the same IP share +// that one lookup rather than each triggering their own. +func (r *clientResolver) resolve(ip string) (string, bool) { + if !r.enabled || ip == "" { + return "", false + } + if host, ok := r.cached(ip); ok { + return host, host != "" + } + + host, err := r.lookupOnce(ip) + if err != nil { + return "", false + } + return host, host != "" +} + +// lookupOnce performs the lookup for ip, sharing one in-flight lookup between +// all concurrent callers for that IP. The caller that started the lookup caches +// its result, so the others find it cached instead of repeating it. +func (r *clientResolver) lookupOnce(ip string) (string, error) { + r.mu.Lock() + if entry, ok := r.cache[ip]; ok && !r.entryExpired(entry, time.Now()) { + r.mu.Unlock() + return entry.hostname, nil + } + if call, ok := r.inFlight[ip]; ok { + r.mu.Unlock() + call.wg.Wait() + return call.host, call.err + } + if len(r.inFlight) >= maxClientHostLookups { + r.mu.Unlock() + return "", nil } - return r.RemoteAddr + call := &clientLookup{} + call.wg.Add(1) + r.inFlight[ip] = call + r.mu.Unlock() + + host, err := r.lookupFn(ip, r.timeout) + if err != nil { + host = "" // a failed lookup is cached as "no hostname" + } else { + host = strings.TrimSuffix(host, ".") // drop FQDN trailing dot + } + call.host, call.err = host, err + + // Publish the result before releasing anything: the cache entry exists + // before the in-flight marker disappears and before the waiters wake. In + // the other order a request arriving between the two steps found neither a + // cached result nor an in-flight lookup to join, and started a second DNS + // lookup for the same IP. + r.store(ip, host) + + r.mu.Lock() + delete(r.inFlight, ip) + r.mu.Unlock() + + call.wg.Done() + return host, err } +// cached returns the remembered result for ip, and false when nothing is +// cached for it or the entry has outlived the TTL that applies to it. +func (r *clientResolver) cached(ip string) (string, bool) { + r.mu.RLock() + entry, ok := r.cache[ip] + r.mu.RUnlock() + if !ok { + return "", false + } + if r.entryExpired(entry, time.Now()) { + return "", false + } + return entry.hostname, true +} + +// entryTTL is how long an entry is trusted. Failures are remembered for less +// time than successes, so a network without PTR records is re-probed sooner +// while still not being probed on every request. +func (r *clientResolver) entryTTL(entry clientHostEntry) time.Duration { + if entry.hostname == "" { + return r.negTTL + } + return r.ttl +} + +// entryExpired reports whether entry is older than the TTL that applies to it. +func (r *clientResolver) entryExpired(entry clientHostEntry, now time.Time) bool { + return now.Sub(entry.resolvedAt) > r.entryTTL(entry) +} + +// store remembers the result for ip. A new key may not push the cache past +// r.maxEntries, so room is made for it first; updating an IP that is already +// cached only replaces its value and never evicts another entry. +func (r *clientResolver) store(ip, host string) { + r.mu.Lock() + defer r.mu.Unlock() + + now := time.Now() + if _, exists := r.cache[ip]; exists { + r.cache[ip] = clientHostEntry{hostname: host, resolvedAt: now} + r.touchOrderLocked(ip) + return + } + + r.makeRoomLocked(now) + r.cache[ip] = clientHostEntry{hostname: host, resolvedAt: now} + r.order = append(r.order, ip) +} + +// touchOrderLocked moves an already-cached key to the back of the insertion +// order, making it the most recently resolved entry. Caller holds r.mu. +func (r *clientResolver) touchOrderLocked(ip string) { + for i, k := range r.order { + if k == ip { + r.order = append(r.order[:i], r.order[i+1:]...) + break + } + } + r.order = append(r.order, ip) +} + +func (r *clientResolver) makeRoomLocked(now time.Time) { + if len(r.cache) < r.maxEntries { + return + } + retained := r.order[:0] + for _, key := range r.order { + entry, ok := r.cache[key] + if !ok || r.entryExpired(entry, now) { + delete(r.cache, key) + continue + } + retained = append(retained, key) + } + clear(r.order[len(retained):]) + r.order = retained + for len(r.cache) >= r.maxEntries && len(r.order) > 0 { + oldest := r.order[0] + r.order = r.order[1:] + delete(r.cache, oldest) + } +} + +// lookupClientAddr performs a reverse DNS (PTR) lookup through resolver, with +// the deadline enforced by a context so a slow or unreachable DNS server gets +// its lookup cancelled at the timeout instead of left running. The first +// non-empty name in the answer wins; an empty answer is reported as an error. +func lookupClientAddr(resolver *net.Resolver, ip string, timeout time.Duration) (string, error) { + ctx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + + names, err := resolver.LookupAddr(ctx, ip) + if err != nil { + return "", err + } + for _, name := range names { + if name != "" { + return name, nil + } + } + return "", fmt.Errorf("no PTR record for %s", ip) +} + +// handleRequest serves one request on one route: it resolves the route, logs +// where the request came from, and either proxies straight through or wakes the +// machine first. Note that logging the client hostname can itself block on a +// reverse-DNS lookup when client_hostname_lookup is enabled and the IP is not +// cached yet. func (p *ProxyService) handleRequest(w http.ResponseWriter, r *http.Request) { route := p.routeForRequest(r) @@ -904,7 +1169,7 @@ func (p *ProxyService) handleRequest(w http.ResponseWriter, r *http.Request) { machineName := machineState.Name p.logger.Info("Incoming request for hostname: %s -> machine: %s, path: %s, client: %s", - r.Host, machineName, r.URL.Path, clientAddr(r)) + r.Host, machineName, r.URL.Path, p.clientAddr(r)) // Check if we have fresh health data cached, reason := p.healthCacheStatus(machineState) @@ -1320,7 +1585,9 @@ func (p *ProxyService) proxyRequest(w http.ResponseWriter, r *http.Request, rout proxy.ServeHTTP(w, r) } -// Config loader +// LoadConfig reads and validates the TOML configuration file at filename, +// filling in defaults for every optional setting, and returns the resolved +// ProxyConfig. func LoadConfig(filename string, clock Clock) (*ProxyConfig, error) { var config Config meta, err := toml.DecodeFile(filename, &config) @@ -1411,6 +1678,14 @@ func LoadConfig(filename string, clock Clock) (*ProxyConfig, error) { return nil, fmt.Errorf("invalid health_cache_duration: %w", err) } + // client_hostname_lookup is optional; unset means disabled. Enabling it is + // an explicit opt-in because a cache miss delays the request log line and + // the request itself by up to the lookup timeout. + clientHostnameLookup := false + if config.ClientHostnameLookup != nil { + clientHostnameLookup = *config.ClientHostnameLookup + } + if len(config.Targets) > 0 && (len(config.Machines) > 0 || len(config.Routes) > 0) { return nil, fmt.Errorf("config mixes the legacy [[targets]] format with [[machines]]/[[routes]]; use one or the other") } @@ -1436,6 +1711,7 @@ func LoadConfig(filename string, clock Clock) (*ProxyConfig, error) { ServerReadTimeout: serverReadTimeout, ServerWriteTimeout: serverWriteTimeout, ServerIdleTimeout: serverIdleTimeout, + ClientHostnameLookup: clientHostnameLookup, PollInterval: pollInterval, HealthCheckInterval: healthCheckInterval, HealthCacheDuration: healthCacheDuration,