diff --git a/client/internal/dns/handler_chain.go b/client/internal/dns/handler_chain.go index 06a2056b1..f468be833 100644 --- a/client/internal/dns/handler_chain.go +++ b/client/internal/dns/handler_chain.go @@ -92,6 +92,8 @@ func (c *HandlerChain) AddHandler(pattern string, handler dns.Handler, priority c.mu.Lock() defer c.mu.Unlock() + log.Warnf("[DNS-ROUTE] HandlerChain.AddHandler: pattern=%s priority=%d handler=%T", pattern, priority, handler) + pattern = strings.ToLower(dns.Fqdn(pattern)) origPattern := pattern isWildcard := strings.HasPrefix(pattern, "*.") @@ -108,6 +110,8 @@ func (c *HandlerChain) AddHandler(pattern string, handler dns.Handler, priority matchSubdomains = matcher.MatchSubdomains() } + log.Warnf("[DNS-ROUTE] HandlerChain.AddHandler: processed pattern=%s origPattern=%s wildcard=%v matchSubdomains=%v priority=%d", + pattern, origPattern, isWildcard, matchSubdomains, priority) log.Debugf("adding handler pattern: domain=%s original: domain=%s wildcard=%v match_subdomain=%v priority=%d", pattern, origPattern, isWildcard, matchSubdomains, priority) @@ -123,6 +127,7 @@ func (c *HandlerChain) AddHandler(pattern string, handler dns.Handler, priority pos := c.findHandlerPosition(entry) c.handlers = append(c.handlers[:pos], append([]HandlerEntry{entry}, c.handlers[pos:]...)...) + log.Warnf("[DNS-ROUTE] HandlerChain.AddHandler: total handlers now=%d", len(c.handlers)) c.logHandlers() } @@ -212,6 +217,11 @@ func (c *HandlerChain) ServeDNS(w dns.ResponseWriter, r *dns.Msg) { if !c.isHandlerMatch(qname, entry) { continue } + // Only log for DNS route handlers to reduce noise + if entry.Priority == PriorityDNSRoute { + log.Warnf("[DNS-ROUTE] HandlerChain.ServeDNS: matched DNS route handler pattern=%s for domain=%s", + entry.OrigPattern, qname) + } handlerName := entry.OrigPattern if s, ok := entry.Handler.(interface{ String() string }); ok { diff --git a/client/internal/dns/server.go b/client/internal/dns/server.go index 4d4fcc06e..c149644ab 100644 --- a/client/internal/dns/server.go +++ b/client/internal/dns/server.go @@ -220,6 +220,8 @@ func newDefaultServer( // RegisterHandler registers a handler for the given domains with the given priority. // Any previously registered handler for the same domain and priority will be replaced. func (s *DefaultServer) RegisterHandler(domains domain.List, handler dns.Handler, priority int) { + log.Warnf("[DNS-ROUTE] DefaultServer.RegisterHandler: domains=%v priority=%d", domains.SafeString(), priority) + s.mux.Lock() defer s.mux.Unlock() @@ -230,10 +232,12 @@ func (s *DefaultServer) RegisterHandler(domains domain.List, handler dns.Handler // convert to zone with simple ref counter s.extraDomains[toZone(domain)]++ } + log.Warnf("[DNS-ROUTE] DefaultServer.RegisterHandler: extraDomains now has %d entries", len(s.extraDomains)) s.applyHostConfig() } func (s *DefaultServer) registerHandler(domains []string, handler dns.Handler, priority int) { + log.Warnf("[DNS-ROUTE] registerHandler: domains=%v priority=%d handler=%T", domains, priority, handler) log.Debugf("registering handler %s with priority %d for %v", handler, priority, domains) for _, domain := range domains { @@ -242,6 +246,7 @@ func (s *DefaultServer) registerHandler(domains []string, handler dns.Handler, p continue } + log.Warnf("[DNS-ROUTE] registerHandler: adding to handlerChain domain=%s priority=%d", domain, priority) s.handlerChain.AddHandler(domain, handler, priority) } } @@ -563,6 +568,7 @@ func (s *DefaultServer) enableDNS() error { func (s *DefaultServer) applyHostConfig() { // prevent reapplying config if we're shutting down if s.ctx.Err() != nil { + log.Warnf("[DNS-ROUTE] applyHostConfig: skipped, context is done") return } @@ -585,6 +591,8 @@ func (s *DefaultServer) applyHostConfig() { } } + log.Warnf("[DNS-ROUTE] applyHostConfig: routeAll=%v domains=%d extraDomains=%v", + config.RouteAll, len(config.Domains), maps.Keys(s.extraDomains)) log.Debugf("extra match domains: %v", maps.Keys(s.extraDomains)) hash, err := hashstructure.Hash(config, hashstructure.FormatV2, &hashstructure.HashOptions{ @@ -594,18 +602,21 @@ func (s *DefaultServer) applyHostConfig() { UseStringer: true, }) if err != nil { - log.Warnf("unable to hash the host dns configuration, will apply config anyway: %s", err) + log.Warnf("[DNS-ROUTE] applyHostConfig: hash error, applying anyway: %s", err) // Fall through to apply config anyway (fail-safe approach) } else if s.currentConfigHash == hash { - log.Debugf("not applying host config as there are no changes") + log.Warnf("[DNS-ROUTE] applyHostConfig: skipped, no changes (hash=%d)", hash) return } + log.Warnf("[DNS-ROUTE] applyHostConfig: applying new config (oldHash=%d newHash=%d)", s.currentConfigHash, hash) log.Debugf("applying host config as there are changes") if err := s.hostManager.applyDNSConfig(config, s.stateManager); err != nil { + log.Warnf("[DNS-ROUTE] applyHostConfig: failed to apply: %v", err) log.Errorf("failed to apply DNS host manager update: %v", err) return } + log.Warnf("[DNS-ROUTE] applyHostConfig: successfully applied") // Only update hash if it was computed successfully and config was applied if err == nil { diff --git a/client/internal/routemanager/client/client.go b/client/internal/routemanager/client/client.go index 0b8e161d2..8a3f7b273 100644 --- a/client/internal/routemanager/client/client.go +++ b/client/internal/routemanager/client/client.go @@ -85,6 +85,8 @@ type Watcher struct { func NewWatcher(config WatcherConfig) *Watcher { ctx, cancel := context.WithCancel(config.Context) + log.Warnf("[DNS-ROUTE] NewWatcher: creating watcher for handler=%s route=%s", config.Handler.String(), config.Route.Network) + client := &Watcher{ ctx: ctx, cancel: cancel, @@ -283,10 +285,15 @@ func (w *Watcher) startNewPeerStatusWatchers() { // addAllowedIPs adds the allowed IPs for the current chosen route to the handler. func (w *Watcher) addAllowedIPs(route *route.Route) error { + log.Warnf("[DNS-ROUTE] Watcher.addAllowedIPs: handler=%s peer=%s network=%s", w.handler.String(), route.Peer, route.Network) + if err := w.handler.AddAllowedIPs(route.Peer); err != nil { + log.Warnf("[DNS-ROUTE] Watcher.addAllowedIPs: failed handler=%s peer=%s: %v", w.handler.String(), route.Peer, err) return fmt.Errorf("add allowed IPs for peer %s: %w", route.Peer, err) } + log.Warnf("[DNS-ROUTE] Watcher.addAllowedIPs: success handler=%s peer=%s", w.handler.String(), route.Peer) + if err := w.statusRecorder.AddPeerStateRoute(route.Peer, w.handler.String(), route.GetResourceID()); err != nil { log.Warnf("Failed to update peer state: %v", err) } @@ -328,14 +335,21 @@ func (w *Watcher) shouldSkipRecalculation(newChosenID route.ID, newStatus router } func (w *Watcher) recalculateRoutes(rsn reason, routerPeerStatuses map[route.ID]routerPeerStatus) error { + log.Warnf("[DNS-ROUTE] Watcher.recalculateRoutes: handler=%s reason=%d peerStatuses=%d currentChosen=%v", + w.handler.String(), rsn, len(routerPeerStatuses), w.currentChosen != nil) + newChosenID, newStatus := w.getBestRouteFromStatuses(routerPeerStatuses) + log.Warnf("[DNS-ROUTE] Watcher.recalculateRoutes: handler=%s newChosenID=%s newStatus=%+v", + w.handler.String(), newChosenID, newStatus) // If no route is chosen, remove the route from the peer if newChosenID == "" { if w.currentChosen == nil { + log.Warnf("[DNS-ROUTE] Watcher.recalculateRoutes: handler=%s no route chosen and no current, nothing to do", w.handler.String()) return nil } + log.Warnf("[DNS-ROUTE] Watcher.recalculateRoutes: handler=%s removing obsolete route", w.handler.String()) if err := w.removeAllowedIPs(w.currentChosen, rsn); err != nil { return fmt.Errorf("remove obsolete: %w", err) } @@ -348,17 +362,21 @@ func (w *Watcher) recalculateRoutes(rsn reason, routerPeerStatuses map[route.ID] // If we can skip recalculation for the same route without changes, do nothing if w.shouldSkipRecalculation(newChosenID, newStatus) { + log.Warnf("[DNS-ROUTE] Watcher.recalculateRoutes: handler=%s skipping recalculation, same route", w.handler.String()) return nil } // If the chosen route was assigned to a different peer, remove the allowed IPs first if isNew := w.currentChosen == nil; !isNew { + log.Warnf("[DNS-ROUTE] Watcher.recalculateRoutes: handler=%s removing old route for HA switch", w.handler.String()) if err := w.removeAllowedIPs(w.currentChosen, reasonHA); err != nil { return fmt.Errorf("remove old: %w", err) } } newChosenRoute := w.routes[newChosenID] + log.Warnf("[DNS-ROUTE] Watcher.recalculateRoutes: handler=%s adding new route peer=%s network=%s", + w.handler.String(), newChosenRoute.Peer, newChosenRoute.Network) if err := w.addAllowedIPs(newChosenRoute); err != nil { return fmt.Errorf("add new: %w", err) } @@ -517,6 +535,8 @@ func (w *Watcher) Start() { } func (w *Watcher) handleRouteUpdate(update RoutesUpdate) { + log.Warnf("[DNS-ROUTE] Watcher.handleRouteUpdate: handler=%s serial=%d routes=%d", + w.handler.String(), update.UpdateSerial, len(update.Routes)) log.Debugf("Received a new client network route update for [%v]", w.handler) // hash update somehow @@ -525,12 +545,15 @@ func (w *Watcher) handleRouteUpdate(update RoutesUpdate) { w.updateSerial = update.UpdateSerial if isTrueRouteUpdate { + log.Warnf("[DNS-ROUTE] Watcher.handleRouteUpdate: handler=%s routes changed, recalculating", w.handler.String()) log.Debugf("client network update %v for [%v] contains different routes, recalculating routes", update.UpdateSerial, w.handler) routePeerStatuses := w.getRouterPeerStatuses() + log.Warnf("[DNS-ROUTE] Watcher.handleRouteUpdate: handler=%s peerStatuses=%d", w.handler.String(), len(routePeerStatuses)) if err := w.recalculateRoutes(reasonRouteUpdate, routePeerStatuses); err != nil { log.Errorf("failed to recalculate routes for network [%v]: %v", w.handler, err) } } else { + log.Warnf("[DNS-ROUTE] Watcher.handleRouteUpdate: handler=%s no changes, skipping", w.handler.String()) log.Debugf("route update %v for [%v] is not different, skipping route recalculation", update.UpdateSerial, w.handler) } @@ -553,7 +576,20 @@ func (w *Watcher) Stop() { } func HandlerFromRoute(params common.HandlerParams) RouteHandler { - switch handlerType(params.Route, params.UseNewDNSRoute) { + ht := handlerType(params.Route, params.UseNewDNSRoute) + var handlerName string + switch ht { + case handlerTypeDnsInterceptor: + handlerName = "DnsInterceptor" + case handlerTypeDynamic: + handlerName = "Dynamic" + default: + handlerName = "Static" + } + log.Warnf("[DNS-ROUTE] HandlerFromRoute: route=%s isDynamic=%v useNewDNSRoute=%v -> handler=%s", + params.Route.Network, params.Route.IsDynamic(), params.UseNewDNSRoute, handlerName) + + switch ht { case handlerTypeDnsInterceptor: return dnsinterceptor.New(params) case handlerTypeDynamic: diff --git a/client/internal/routemanager/dnsinterceptor/handler.go b/client/internal/routemanager/dnsinterceptor/handler.go index 12c9ff4af..9b4c094cc 100644 --- a/client/internal/routemanager/dnsinterceptor/handler.go +++ b/client/internal/routemanager/dnsinterceptor/handler.go @@ -75,6 +75,7 @@ func (d *DnsInterceptor) String() string { } func (d *DnsInterceptor) AddRoute(context.Context) error { + log.Warnf("[DNS-ROUTE] Registering DNS interceptor for domains: %v", d.route.Domains.SafeString()) d.dnsServer.RegisterHandler(d.route.Domains, d, nbdns.PriorityDNSRoute) return nil } @@ -151,12 +152,16 @@ func (d *DnsInterceptor) addAllowedIPForPrefix(realPrefix netip.Prefix, peerKey func (d *DnsInterceptor) addRouteAndAllowedIP(realPrefix netip.Prefix, domain domain.Domain) error { // Routes use fake IPs (so traffic to fake IPs gets routed to interface) routePrefix := d.transformRealToFakePrefix(realPrefix) + log.Warnf("[DNS-ROUTE] Adding route for domain=%s realIP=%s routePrefix=%s", domain.SafeString(), realPrefix, routePrefix) if _, err := d.routeRefCounter.Increment(routePrefix, struct{}{}); err != nil { + log.Warnf("[DNS-ROUTE] Failed to add route for domain=%s prefix=%s: %v", domain.SafeString(), routePrefix, err) return fmt.Errorf("add route for IP %s: %v", routePrefix, err) } + log.Warnf("[DNS-ROUTE] Successfully added route for domain=%s prefix=%s", domain.SafeString(), routePrefix) // Add to AllowedIPs if we have a current peer (uses real IPs) if d.currentPeerKey == "" { + log.Warnf("[DNS-ROUTE] No current peer key, skipping AllowedIPs for domain=%s", domain.SafeString()) return nil } @@ -221,11 +226,17 @@ func (d *DnsInterceptor) ServeDNS(w dns.ResponseWriter, r *dns.Msg) { }) if len(r.Question) == 0 { + log.Warnf("[DNS-ROUTE] ServeDNS: empty question list") return } + qName := r.Question[0].Name + qType := r.Question[0].Qtype + log.Warnf("[DNS-ROUTE] ServeDNS: received query for domain=%s type=%d", qName, qType) + // pass if non A/AAAA query - if r.Question[0].Qtype != dns.TypeA && r.Question[0].Qtype != dns.TypeAAAA { + if qType != dns.TypeA && qType != dns.TypeAAAA { + log.Warnf("[DNS-ROUTE] ServeDNS: skipping non A/AAAA query for domain=%s type=%d", qName, qType) d.continueToNextHandler(w, r, logger, "non A/AAAA query") return } @@ -235,9 +246,11 @@ func (d *DnsInterceptor) ServeDNS(w dns.ResponseWriter, r *dns.Msg) { d.mu.RUnlock() if peerKey == "" { + log.Warnf("[DNS-ROUTE] ServeDNS: no current peer key for domain=%s", qName) d.writeDNSError(w, r, logger, "no current peer key") return } + log.Warnf("[DNS-ROUTE] ServeDNS: using peer=%s for domain=%s", peerKey, qName) upstreamIP, err := d.getUpstreamIP(peerKey) if err != nil { @@ -307,6 +320,8 @@ func (d *DnsInterceptor) writeMsg(w dns.ResponseWriter, r *dns.Msg, logger *log. r.MsgHdr.Zero = false if len(r.Answer) > 0 && len(r.Question) > 0 { + log.Warnf("[DNS-ROUTE] writeMsg: processing %d answers for domain=%s", len(r.Answer), r.Question[0].Name) + origPattern := "" if writer, ok := w.(*nbdns.ResponseWriterChain); ok { origPattern = writer.GetOrigPattern() @@ -346,12 +361,17 @@ func (d *DnsInterceptor) writeMsg(w dns.ResponseWriter, r *dns.Msg, logger *log. newPrefixes = append(newPrefixes, prefix) } + log.Warnf("[DNS-ROUTE] writeMsg: extracted %d prefixes for domain=%s: %v", len(newPrefixes), resolvedDomain.SafeString(), newPrefixes) if len(newPrefixes) > 0 { + log.Warnf("[DNS-ROUTE] writeMsg: calling updateDomainPrefixes for domain=%s", resolvedDomain.SafeString()) if err := d.updateDomainPrefixes(resolvedDomain, originalDomain, newPrefixes, logger); err != nil { + log.Warnf("[DNS-ROUTE] writeMsg: updateDomainPrefixes failed for domain=%s: %v", resolvedDomain.SafeString(), err) logger.Errorf("failed to update domain prefixes: %v", err) } d.replaceIPsInDNSResponse(r, newPrefixes, logger) + } else { + log.Warnf("[DNS-ROUTE] writeMsg: no prefixes to add for domain=%s", resolvedDomain.SafeString()) } } @@ -382,8 +402,13 @@ func (d *DnsInterceptor) updateDomainPrefixes(resolvedDomain, originalDomain dom d.mu.Lock() defer d.mu.Unlock() + log.Warnf("[DNS-ROUTE] updateDomainPrefixes: domain=%s (original=%s) newPrefixes=%v currentPeer=%s", + resolvedDomain.SafeString(), originalDomain.SafeString(), newPrefixes, d.currentPeerKey) + oldPrefixes := d.interceptedDomains[resolvedDomain] toAdd, toRemove := determinePrefixChanges(oldPrefixes, newPrefixes) + log.Warnf("[DNS-ROUTE] updateDomainPrefixes: domain=%s oldPrefixes=%v toAdd=%v toRemove=%v keepRoute=%v", + resolvedDomain.SafeString(), oldPrefixes, toAdd, toRemove, d.route.KeepRoute) var merr *multierror.Error var dnatMappings map[netip.Addr]netip.Addr diff --git a/client/internal/routemanager/manager.go b/client/internal/routemanager/manager.go index 2baa0e668..693e9f3b9 100644 --- a/client/internal/routemanager/manager.go +++ b/client/internal/routemanager/manager.go @@ -173,12 +173,23 @@ func (m *DefaultManager) setupAndroidRoutes(config ManagerConfig) { } func (m *DefaultManager) setupRefCounters(useNoop bool) { + i := m.wgInterface.ToInterface() + log.Warnf("[DNS-ROUTE] setupRefCounters: wgInterface=%s useNoop=%v", i.Name, useNoop) + m.routeRefCounter = refcounter.New( func(prefix netip.Prefix, _ struct{}) (struct{}, error) { - return struct{}{}, m.sysOps.AddVPNRoute(prefix, m.wgInterface.ToInterface()) + log.Warnf("[DNS-ROUTE] routeRefCounter.AddFunc called: prefix=%s interface=%s", prefix, i.Name) + err := m.sysOps.AddVPNRoute(prefix, i) + if err != nil { + log.Warnf("[DNS-ROUTE] routeRefCounter.AddFunc failed: prefix=%s err=%v", prefix, err) + } else { + log.Warnf("[DNS-ROUTE] routeRefCounter.AddFunc success: prefix=%s", prefix) + } + return struct{}{}, err }, func(prefix netip.Prefix, _ struct{}) error { - return m.sysOps.RemoveVPNRoute(prefix, m.wgInterface.ToInterface()) + log.Warnf("[DNS-ROUTE] routeRefCounter.RemoveFunc called: prefix=%s", prefix) + return m.sysOps.RemoveVPNRoute(prefix, i) }, ) @@ -376,6 +387,18 @@ func (m *DefaultManager) UpdateRoutes( clientRoutes route.HAMap, useNewDNSRoute bool, ) error { + log.Warnf("[DNS-ROUTE] UpdateRoutes: serial=%d serverRoutes=%d clientRoutes=%d useNewDNSRoute=%v", + updateSerial, len(serverRoutes), len(clientRoutes), useNewDNSRoute) + + // Log each client route for debugging + for id, routes := range clientRoutes { + if len(routes) > 0 { + r := routes[0] + log.Warnf("[DNS-ROUTE] UpdateRoutes: clientRoute id=%s network=%s isDynamic=%v domains=%v peer=%s", + id, r.Network, r.IsDynamic(), r.Domains.SafeString(), r.Peer) + } + } + select { case <-m.ctx.Done(): log.Infof("not updating routes as context is closed")