net/portmapper: add logs about obtained mapping(s)

This logs additional information about what mapping(s) are obtained
during the creation process, including whether we return an existing
cached mapping.

Updates #10597

Signed-off-by: Andrew Dunham <andrew@du.nham.ca>
Change-Id: I9ff25071f064c91691db9ab0b9365ccc5f948d6e

net/portmapper/pcp.go

@@ -58,9 +58,16 @@ type pcpMapping struct {
 	// Doesn't seem to be used elsewhere, but can use it for validation at some point.
 }
 
+func (p *pcpMapping) MappingType() string      { return "pcp" }
 func (p *pcpMapping) GoodUntil() time.Time     { return p.goodUntil }
 func (p *pcpMapping) RenewAfter() time.Time    { return p.renewAfter }
 func (p *pcpMapping) External() netip.AddrPort { return p.external }
+func (p *pcpMapping) MappingDebug() string {
+	return fmt.Sprintf("pcpMapping{gw:%v, external:%v, internal:%v, renewAfter:%d, goodUntil:%d}",
+		p.gw, p.external, p.internal,
+		p.renewAfter.Unix(), p.goodUntil.Unix())
+}
+
 func (p *pcpMapping) Release(ctx context.Context) {
 	uc, err := p.c.listenPacket(ctx, "udp4", ":0")
 	if err != nil {

net/portmapper/portmapper.go

@@ -127,6 +127,11 @@ type mapping interface {
 	RenewAfter() time.Time
 	// External indicates what port the mapping can be reached from on the outside.
 	External() netip.AddrPort
+	// MappingType returns a descriptive string for this type of mapping.
+	MappingType() string
+	// MappingDebug returns a debug string for this mapping, for use when
+	// printing verbose logs.
+	MappingDebug() string
 }
 
 // HaveMapping reports whether we have a current valid mapping.
@@ -154,10 +159,18 @@ func (m *pmpMapping) externalValid() bool {
 	return m.external.Addr().IsValid() && m.external.Port() != 0
 }
 
+func (p *pmpMapping) MappingType() string      { return "pmp" }
 func (p *pmpMapping) GoodUntil() time.Time     { return p.goodUntil }
 func (p *pmpMapping) RenewAfter() time.Time    { return p.renewAfter }
 func (p *pmpMapping) External() netip.AddrPort { return p.external }
 
+func (p *pmpMapping) MappingDebug() string {
+	return fmt.Sprintf("pmpMapping{gw:%v, external:%v, internal:%v, renewAfter:%d, goodUntil:%d, epoch:%v}",
+		p.gw, p.external, p.internal,
+		p.renewAfter.Unix(), p.goodUntil.Unix(),
+		p.epoch)
+}
+
 // Release does a best effort fire-and-forget release of the PMP mapping m.
 func (m *pmpMapping) Release(ctx context.Context) {
 	uc, err := m.c.listenPacket(ctx, "udp4", ":0")
@@ -454,6 +467,44 @@ func (c *Client) createOrGetMapping(ctx context.Context) (external netip.AddrPor
 		return netip.AddrPort{}, NoMappingError{ErrGatewayIPv6}
 	}
 
+	now := time.Now()
+
+	// Log what kind of portmap we obtained
+	reusedExisting := false
+	defer func() {
+		if err != nil {
+			return
+		}
+
+		c.mu.Lock()
+		defer c.mu.Unlock()
+
+		portmapType := "none"
+		if c.mapping != nil {
+			portmapType = c.mapping.MappingType()
+		}
+		if reusedExisting {
+			portmapType = "existing-" + portmapType
+		}
+
+		if c.mapping == nil {
+			c.logf("[unexpected] no error but no stored mapping: now=%d external=%v type=%s",
+				now.Unix(), external, portmapType)
+			return
+		}
+
+		// Print the internal details of each mapping if we're being verbose.
+		if c.debug.VerboseLogs {
+			c.logf("successfully obtained mapping: now=%d external=%v type=%s mapping=%s",
+				now.Unix(), external, portmapType, c.mapping.MappingDebug())
+			return
+		}
+
+		c.logf("[v1] successfully obtained mapping: now=%d external=%v type=%s goodUntil=%d renewAfter=%d",
+			now.Unix(), external, portmapType,
+			c.mapping.GoodUntil().Unix(), c.mapping.RenewAfter().Unix())
+	}()
+
 	c.mu.Lock()
 	localPort := c.localPort
 	internalAddr := netip.AddrPortFrom(myIP, localPort)
@@ -463,10 +514,10 @@ func (c *Client) createOrGetMapping(ctx context.Context) (external netip.AddrPor
 	var prevPort uint16
 
 	// Do we have an existing mapping that's valid?
-	now := time.Now()
 	if m := c.mapping; m != nil {
 		if now.Before(m.RenewAfter()) {
 			defer c.mu.Unlock()
+			reusedExisting = true
 			return m.External(), nil
 		}
 		// The mapping might still be valid, so just try to renew it.
@@ -478,6 +529,7 @@ func (c *Client) createOrGetMapping(ctx context.Context) (external netip.AddrPor
 		if external, ok := c.getUPnPPortMapping(ctx, gw, internalAddr, prevPort); ok {
 			return external, nil
 		}
+		c.vlogf("fallback to UPnP due to PCP and PMP being disabled failed")
 		return netip.AddrPort{}, NoMappingError{ErrNoPortMappingServices}
 	}
 
@@ -507,6 +559,7 @@ func (c *Client) createOrGetMapping(ctx context.Context) (external netip.AddrPor
 		if external, ok := c.getUPnPPortMapping(ctx, gw, internalAddr, prevPort); ok {
 			return external, nil
 		}
+		c.vlogf("fallback to UPnP due to no PCP and PMP failed")
 		return netip.AddrPort{}, NoMappingError{ErrNoPortMappingServices}
 	}
 	c.mu.Unlock()

net/portmapper/portmapper_test.go

@@ -51,6 +51,7 @@ func TestClientProbeThenMap(t *testing.T) {
 	}
 	c := NewClient(t.Logf, nil, nil, new(controlknobs.Knobs), nil)
 	defer c.Close()
+	c.debug.VerboseLogs = true
 	c.SetLocalPort(1234)
 	res, err := c.Probe(context.Background())
 	t.Logf("Probe: %+v, %v", res, err)

net/portmapper/upnp.go

@@ -68,9 +68,16 @@ type upnpMapping struct {
 //	https://github.com/tailscale/tailscale/issues/7377
 const upnpProtocolUDP = "UDP"
 
+func (u *upnpMapping) MappingType() string      { return "upnp" }
 func (u *upnpMapping) GoodUntil() time.Time     { return u.goodUntil }
 func (u *upnpMapping) RenewAfter() time.Time    { return u.renewAfter }
 func (u *upnpMapping) External() netip.AddrPort { return u.external }
+func (u *upnpMapping) MappingDebug() string {
+	return fmt.Sprintf("upnpMapping{gw:%v, external:%v, internal:%v, renewAfter:%d, goodUntil:%d, loc:%q}",
+		u.gw, u.external, u.internal,
+		u.renewAfter.Unix(), u.goodUntil.Unix(),
+		u.loc)
+}
 func (u *upnpMapping) Release(ctx context.Context) {
 	u.client.DeletePortMapping(ctx, "", u.external.Port(), upnpProtocolUDP)
 }