derp,wgengine/magicsock: more call-me-maybe tracing

Signed-off-by: Jordan Whited <jordan@tailscale.com>

derp/derp_client.go

@@ -5,6 +5,7 @@ package derp
 
 import (
 	"bufio"
+	"bytes"
 	"encoding/binary"
 	"encoding/json"
 	"errors"
@@ -16,6 +17,7 @@ import (
 
 	"go4.org/mem"
 	"golang.org/x/time/rate"
+	"tailscale.com/disco"
 	"tailscale.com/syncs"
 	"tailscale.com/tstime"
 	"tailscale.com/types/key"
@@ -210,6 +212,10 @@ func (c *Client) send(dstKey key.NodePublic, pkt []byte) (ret error) {
 		}
 	}()
 
+	if len(pkt) > 46 && bytes.Equal(pkt[:6], []byte(disco.Magic)) {
+		c.logf("JORDAN: derp.Client.send() disco packet with nonce[:8]: %x", pkt[38:46])
+	}
+
 	if len(pkt) > MaxPacketSize {
 		return fmt.Errorf("packet too big: %d", len(pkt))
 	}
@@ -569,6 +575,9 @@ func (c *Client) recvTimeout(timeout time.Duration) (m ReceivedMessage, err erro
 			}
 			rp.Source = key.NodePublicFromRaw32(mem.B(b[:keyLen]))
 			rp.Data = b[keyLen:n]
+			if len(rp.Data) > 46 && bytes.Equal(rp.Data[:6], []byte(disco.Magic)) {
+				c.logf("JORDAN: derp client recvTimeout() RX disco with nonce[:8]: %x", rp.Data[38:46])
+			}
 			return rp, nil
 
 		case framePing:

disco/disco.go

@@ -171,6 +171,7 @@ func parsePing(ver uint8, p []byte) (m *Ping, err error) {
 // The recipient may choose to not open a path back, if it's already
 // happy with its path. But usually it will.
 type CallMeMaybe struct {
+	MarshalTime time.Time
 	// MyNumber is what the peer believes its endpoints are.
 	//
 	// Prior to Tailscale 1.4, the endpoints were exchanged purely
@@ -194,9 +195,9 @@ const epLength = 16 + 2 // 16 byte IP address + 2 byte port
 
 func (m *CallMeMaybe) AppendMarshal(b []byte) []byte {
 	ret, p := appendMsgHeader(b, TypeCallMeMaybe, 1, 8+(epLength*len(m.MyNumber)))
-	t := time.Now().Unix()
-	fmt.Printf("JORDAN: putting timestamp %s in call-me-maybe\n", time.Unix(t, 0))
-	binary.BigEndian.PutUint64(p, uint64(t))
+	now := time.Now()
+	binary.BigEndian.PutUint64(p, uint64(now.UnixNano()))
+	m.MarshalTime = now
 	p = p[8:]
 	for _, ipp := range m.MyNumber {
 		a := ipp.Addr().As16()
@@ -211,10 +212,11 @@ func parseCallMeMaybe(ver uint8, p []byte) (m *CallMeMaybe, err error) {
 	m = new(CallMeMaybe)
 	if ver == 1 {
 		u := binary.BigEndian.Uint64(p)
-		t := time.Unix(int64(u), 0)
-		fmt.Printf("JORDAN: call-me-maybe has timestamp: %s\n", t)
+		t := time.Unix(0, int64(u))
+		m.MarshalTime = t
 		p = p[8:]
-	} else if len(p)%epLength != 0 || ver != 0 || len(p) == 0 {
+	}
+	if len(p)%epLength != 0 || (ver != 0 && ver != 1) || len(p) == 0 {
 		return m, nil
 	}
 	m.MyNumber = make([]netip.AddrPort, 0, len(p)/epLength)

wgengine/magicsock/derp.go

@@ -5,6 +5,7 @@ package magicsock
 
 import (
 	"bufio"
+	"bytes"
 	"context"
 	"fmt"
 	"hash/fnv"
@@ -20,6 +21,7 @@ import (
 	"github.com/tailscale/wireguard-go/conn"
 	"tailscale.com/derp"
 	"tailscale.com/derp/derphttp"
+	"tailscale.com/disco"
 	"tailscale.com/health"
 	"tailscale.com/logtail/backoff"
 	"tailscale.com/net/dnscache"
@@ -530,6 +532,9 @@ func (c *Conn) runDerpReader(ctx context.Context, derpFakeAddr netip.AddrPort, d
 			pkt = m
 			res.n = len(m.Data)
 			res.src = m.Source
+			if len(m.Data) > 46 && bytes.Equal(m.Data[:6], []byte(disco.Magic)) {
+				c.logf("JORDAN: conn.runDerpReader() RX disco with nonce[:8]: %x", m.Data[38:46])
+			}
 			if logDerpVerbose() {
 				c.logf("magicsock: got derp-%v packet: %q", regionID, m.Data)
 			}
@@ -567,6 +572,7 @@ func (c *Conn) runDerpReader(ctx context.Context, derpFakeAddr netip.AddrPort, d
 					regionID, key.NodePublic(m.Peer).ShortString(), m.Reason)
 			}
 			c.removeDerpPeerRoute(key.NodePublic(m.Peer), regionID, dc)
+			// this will fall down to c.derpRecvCh <- res, writing the previous packet again
 		default:
 			// Ignore.
 			continue
@@ -608,6 +614,9 @@ func (c *Conn) runDerpWriter(ctx context.Context, dc *derphttp.Client, ch <-chan
 		case <-ctx.Done():
 			return
 		case wr := <-ch:
+			if len(wr.b) > 46 && bytes.Equal(wr.b[:6], []byte(disco.Magic)) {
+				c.logf("JORDAN: runDerpWriter() disco packet with nonce[:8]: %x", wr.b[38:46])
+			}
 			err := dc.Send(wr.pubKey, wr.b)
 			if err != nil {
 				c.logf("magicsock: derp.Send(%v): %v", wr.addr, err)
@@ -627,6 +636,7 @@ func (c *connBind) receiveDERP(buffs [][]byte, sizes []int, eps []conn.Endpoint)
 		if c.isClosed() {
 			break
 		}
+
 		n, ep := c.processDERPReadResult(dm, buffs[0])
 		if n == 0 {
 			// No data read occurred. Wait for another packet.
@@ -681,6 +691,13 @@ func (c *Conn) SetDERPMap(dm *tailcfg.DERPMap) {
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
+	if debugUseDERPHTTP() {
+		for _, v := range dm.Regions {
+			for _, n := range v.Nodes {
+				n.DERPPort = 3340
+			}
+		}
+	}
 	var derpAddr = debugUseDERPAddr()
 	if derpAddr != "" {
 		derpPort := 443

wgengine/magicsock/magicsock.go

@@ -1277,6 +1277,10 @@ func (c *Conn) sendDiscoMessage(dst netip.AddrPort, dstKey key.NodePublic, dstDi
 	pkt = append(pkt, box...)
 	sent, err = c.sendAddr(dst, dstKey, pkt)
 	if sent {
+		cmm, ok := m.(*disco.CallMeMaybe)
+		if ok {
+			c.logf("JORDAN: TX call-me-maybe nonce[:8]: %x marshalTime: %s", box[:8], cmm.MarshalTime)
+		}
 		if logLevel == discoLog || (logLevel == discoVerboseLog && debugDisco()) {
 			node := "?"
 			if !dstKey.IsZero() {
@@ -1436,6 +1440,7 @@ func (c *Conn) handleDiscoMessage(msg []byte, src netip.AddrPort, derpNodeSrc ke
 			return true
 		})
 	case *disco.CallMeMaybe:
+		c.logf("JORDAN: RX call-me-maybe nonce[:8]: %x marshalTime: %s via: %s", sealedBox[:8], dm.MarshalTime, via)
 		metricRecvDiscoCallMeMaybe.Add(1)
 		if !isDERP || derpNodeSrc.IsZero() {
 			// CallMeMaybe messages should only come via DERP.