diff --git a/net/portmapper/pcp.go b/net/portmapper/pcp.go index c1d62b02b..0066ba225 100644 --- a/net/portmapper/pcp.go +++ b/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 { diff --git a/net/portmapper/portmapper.go b/net/portmapper/portmapper.go index f346028d2..f6e73dda3 100644 --- a/net/portmapper/portmapper.go +++ b/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() diff --git a/net/portmapper/portmapper_test.go b/net/portmapper/portmapper_test.go index 575ddd6f1..e41223dba 100644 --- a/net/portmapper/portmapper_test.go +++ b/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) diff --git a/net/portmapper/upnp.go b/net/portmapper/upnp.go index b0a243138..67d9cbbab 100644 --- a/net/portmapper/upnp.go +++ b/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) }