From 947ab906b38cafe23efb09389d8af25a73c4a3e1 Mon Sep 17 00:00:00 2001 From: Jordan Whited Date: Wed, 13 Dec 2023 10:47:31 -0800 Subject: [PATCH] derp,wgengine/magicsock: more call-me-maybe tracing Signed-off-by: Jordan Whited --- derp/derp_client.go | 9 +++++++++ disco/disco.go | 14 ++++++++------ wgengine/magicsock/derp.go | 17 +++++++++++++++++ wgengine/magicsock/magicsock.go | 5 +++++ 4 files changed, 39 insertions(+), 6 deletions(-) diff --git a/derp/derp_client.go b/derp/derp_client.go index 7ad98cfe8..98bc31fa8 100644 --- a/derp/derp_client.go +++ b/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: diff --git a/disco/disco.go b/disco/disco.go index a104d2e0d..84bb2852c 100644 --- a/disco/disco.go +++ b/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) diff --git a/wgengine/magicsock/derp.go b/wgengine/magicsock/derp.go index 2a9f1cae3..49bd14f56 100644 --- a/wgengine/magicsock/derp.go +++ b/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 diff --git a/wgengine/magicsock/magicsock.go b/wgengine/magicsock/magicsock.go index 9fc80c2d4..953cc8899 100644 --- a/wgengine/magicsock/magicsock.go +++ b/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.