additional debug logging, use mapper pointer

Signed-off-by: Kristoffer Dalby <kristoffer@tailscale.com>

go.mod

@@ -61,7 +61,7 @@ require (
 	github.com/containerd/console v1.0.3 // indirect
 	github.com/containerd/continuity v0.3.0 // indirect
 	github.com/docker/cli v23.0.5+incompatible // indirect
-	github.com/docker/docker v23.0.5+incompatible // indirect
+	github.com/docker/docker v24.0.4+incompatible // indirect
 	github.com/docker/go-connections v0.4.0 // indirect
 	github.com/docker/go-units v0.5.0 // indirect
 	github.com/dustin/go-humanize v1.0.1 // indirect

go.sum

@@ -111,6 +111,8 @@ github.com/docker/cli v23.0.5+incompatible h1:ufWmAOuD3Vmr7JP2G5K3cyuNC4YZWiAsuD
 github.com/docker/cli v23.0.5+incompatible/go.mod h1:JLrzqnKDaYBop7H2jaqPtU4hHvMKP+vjCwu2uszcLI8=
 github.com/docker/docker v23.0.5+incompatible h1:DaxtlTJjFSnLOXVNUBU1+6kXGz2lpDoEAH6QoxaSg8k=
 github.com/docker/docker v23.0.5+incompatible/go.mod h1:eEKB0N0r5NX/I1kEveEz05bcu8tLC/8azJZsviup8Sk=
+github.com/docker/docker v24.0.4+incompatible h1:s/LVDftw9hjblvqIeTiGYXBCD95nOEEl7qRsRrIOuQI=
+github.com/docker/docker v24.0.4+incompatible/go.mod h1:eEKB0N0r5NX/I1kEveEz05bcu8tLC/8azJZsviup8Sk=
 github.com/docker/go-connections v0.4.0 h1:El9xVISelRB7BuFusrZozjnkIM5YnzCViNKohAFqRJQ=
 github.com/docker/go-connections v0.4.0/go.mod h1:Gbd7IOopHjR8Iph03tsViu4nIes5XhDvyHbTtUxmeec=
 github.com/docker/go-units v0.4.0/go.mod h1:fgPhTUdO+D/Jk86RDLlptpiXQzgHJF7gydDDbaIK4Dk=
@@ -149,6 +151,7 @@ github.com/go-jose/go-jose/v3 v3.0.0 h1:s6rrhirfEP/CGIoc6p+PZAeogN2SxKav6Wp7+dyM
 github.com/go-jose/go-jose/v3 v3.0.0/go.mod h1:RNkWWRld676jZEYoV3+XK8L2ZnNSvIsxFMht0mSX+u8=
 github.com/go-kit/log v0.1.0/go.mod h1:zbhenjAZHb184qTLMA9ZjW7ThYL0H2mk7Q6pNt4vbaY=
 github.com/go-logfmt/logfmt v0.5.0/go.mod h1:wCYkCAKZfumFQihp8CzCvQ3paCTfi41vtzG1KdI/P7A=
+github.com/go-logfmt/logfmt v0.5.1/go.mod h1:WYhtIu8zTZfxdn5+rREduYbwxfcBr/Vr6KEVveWlfTs=
 github.com/go-playground/assert/v2 v2.0.1/go.mod h1:VDjEfimB/XKnb+ZQfWdccd7VUvScMdVu0Titje2rxJ4=
 github.com/go-playground/locales v0.13.0 h1:HyWk6mgj5qFqCT5fjGBuRArbVDfE4hi8+e8ceBS/t7Q=
 github.com/go-playground/locales v0.13.0/go.mod h1:taPMhCMXrRLJO55olJkUXHZBHCxTMfnGwq/HNwmWNS8=
@@ -292,12 +295,15 @@ github.com/jinzhu/now v1.1.5 h1:/o9tlHleP7gOFmsnYNz3RGnqzefHA47wQpKrrdTIwXQ=
 github.com/jinzhu/now v1.1.5/go.mod h1:d3SSVoowX0Lcu0IBviAWJpolVfI5UJVZZ7cO71lE/z8=
 github.com/josharian/native v1.1.1-0.20230202152459-5c7d0dd6ab86 h1:elKwZS1OcdQ0WwEDBeqxKwb7WB62QX8bvZ/FJnVXIfk=
 github.com/josharian/native v1.1.1-0.20230202152459-5c7d0dd6ab86/go.mod h1:aFAMtuldEgx/4q7iSGazk22+IcgvtiC+HIimFO9XlS8=
+github.com/jpillora/backoff v1.0.0/go.mod h1:J/6gKK9jxlEcS3zixgDgUAsiuZ7yrSoa/FX5e0EB2j4=
 github.com/jsimonetti/rtnetlink v1.3.2 h1:dcn0uWkfxycEEyNy0IGfx3GrhQ38LH7odjxAghimsVI=
 github.com/jsimonetti/rtnetlink v1.3.2/go.mod h1:BBu4jZCpTjP6Gk0/wfrO8qcqymnN3g0hoFqObRmUo6U=
 github.com/json-iterator/go v1.1.9/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/json-iterator/go v1.1.12 h1:PV8peI4a0ysnczrg+LtxykD8LfKY9ML6u2jnxaEnrnM=
+github.com/json-iterator/go v1.1.12/go.mod h1:e30LSqwooZae/UwlEbR2852Gd8hjQvJoHmT4TnhNGBo=
 github.com/jstemmer/go-junit-report v0.0.0-20190106144839-af01ea7f8024/go.mod h1:6v2b51hI/fHJwM22ozAgKL4VKDeJcHhJFhtBdhmNjmU=
 github.com/jstemmer/go-junit-report v0.9.1/go.mod h1:Brl9GWCQeLvo8nXZwPNNblvFj/XSXhF0NWZEnDohbsk=
+github.com/julienschmidt/httprouter v1.3.0/go.mod h1:JR6WtHb+2LUe8TCKY3cZOxFyyO8IZAc4RVcycCCAKdM=
 github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 h1:Z9n2FFNUXsshfwJMBgNA0RU6/i7WVaAegv3PtuIHPMs=
 github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51/go.mod h1:CzGEWj7cYgsdH8dAjBGEr58BoE7ScuLd+fwFZ44+/x8=
 github.com/kisielk/errcheck v1.5.0/go.mod h1:pFxgyoBC7bSaBwPgfKdkLd5X25qrDl4LWUI2bnpBCr8=
@@ -360,9 +366,12 @@ github.com/moby/term v0.0.0-20221205130635-1aeaba878587 h1:HfkjXDfhgVaN5rmueG8cL
 github.com/moby/term v0.0.0-20221205130635-1aeaba878587/go.mod h1:8FzsFHVUBGZdbDsJw/ot+X+d5HLUbvklYLJ9uGfcI3Y=
 github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q=
 github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd h1:TRLaZ9cD/w8PVh93nsPXa1VrQ6jlwL5oN8l14QlcNfg=
+github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q=
 github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742/go.mod h1:bx2lNnkwVCuqBIxFjflWJWanXIb3RllmbCylyMrvgv0=
 github.com/modern-go/reflect2 v1.0.2 h1:xBagoLtFs94CBntxluKeaWgTMpvLxC4ur3nMaC9Gz0M=
+github.com/modern-go/reflect2 v1.0.2/go.mod h1:yWuevngMOJpCy52FWWMvUC8ws7m/LJsjYzDa0/r8luk=
 github.com/mrunalp/fileutils v0.5.0/go.mod h1:M1WthSahJixYnrXQl/DFQuteStB1weuxD2QJNHXfbSQ=
+github.com/mwitkow/go-conntrack v0.0.0-20190716064945-2f068394615f/go.mod h1:qRWi+5nqEBWmkhHvq77mSJWrCKwh8bxhgT7d/eI7P4U=
 github.com/oauth2-proxy/mockoidc v0.0.0-20220308204021-b9169deeb282 h1:TQMyrpijtkFyXpNI3rY5hsZQZw+paiH+BfAlsb81HBY=
 github.com/oauth2-proxy/mockoidc v0.0.0-20220308204021-b9169deeb282/go.mod h1:rW25Kyd08Wdn3UVn0YBsDTSvReu0jqpmJKzxITPSjks=
 github.com/opencontainers/go-digest v1.0.0 h1:apOUWs51W5PlhuyGyz9FCeeBIOUDA/6nW8Oi/yOhh5U=

hscontrol/mapper/mapper.go

@@ -49,9 +49,14 @@ type Mapper struct {
 	dnsCfg           *tailcfg.DNSConfig
 	logtail          bool
 	randomClientPort bool
+
+	uid     string
+	created time.Time
+	seq     uint64
 }
 
 func NewMapper(
+	machine *types.Machine,
 	db *db.HSDatabase,
 	privateKey *key.MachinePrivate,
 	isNoise bool,
@@ -61,6 +66,14 @@ func NewMapper(
 	logtail bool,
 	randomClientPort bool,
 ) *Mapper {
+	log.Debug().
+		Caller().
+		Bool("noise", isNoise).
+		Str("machine", machine.Hostname).
+		Msg("creating new mapper")
+
+	uid, _ := util.GenerateRandomStringDNSSafe(8)
+
 	return &Mapper{
 		db: db,
 
@@ -72,9 +85,17 @@ func NewMapper(
 		dnsCfg:           dnsCfg,
 		logtail:          logtail,
 		randomClientPort: randomClientPort,
+
+		uid:     uid,
+		created: time.Now(),
+		seq:     0,
 	}
 }
 
+func (m *Mapper) String() string {
+	return fmt.Sprintf("Mapper: { seq: %d, uid: %s, created: %s }", m.seq, m.uid, m.created)
+}
+
 // TODO: Optimise
 // As this work continues, the idea is that there will be one Mapper instance
 // per node, attached to the open stream between the control and client.
@@ -270,7 +291,7 @@ func addNextDNSMetadata(resolvers []*dnstype.Resolver, machine types.Machine) {
 }
 
 // FullMapResponse returns a MapResponse for the given machine.
-func (m Mapper) FullMapResponse(
+func (m *Mapper) FullMapResponse(
 	mapRequest tailcfg.MapRequest,
 	machine *types.Machine,
 	pol *policy.ACLPolicy,
@@ -306,7 +327,7 @@ func (m Mapper) FullMapResponse(
 	return m.marshalMapResponse(mapResponse, machine, mapRequest.Compress)
 }
 
-func (m Mapper) KeepAliveResponse(
+func (m *Mapper) KeepAliveResponse(
 	mapRequest tailcfg.MapRequest,
 	machine *types.Machine,
 ) ([]byte, error) {
@@ -316,7 +337,7 @@ func (m Mapper) KeepAliveResponse(
 	return m.marshalMapResponse(&resp, machine, mapRequest.Compress)
 }
 
-func (m Mapper) DERPMapResponse(
+func (m *Mapper) DERPMapResponse(
 	mapRequest tailcfg.MapRequest,
 	machine *types.Machine,
 	derpMap tailcfg.DERPMap,
@@ -327,7 +348,7 @@ func (m Mapper) DERPMapResponse(
 	return m.marshalMapResponse(&resp, machine, mapRequest.Compress)
 }
 
-func (m Mapper) PeerChangedResponse(
+func (m *Mapper) PeerChangedResponse(
 	mapRequest tailcfg.MapRequest,
 	machine *types.Machine,
 	machineKeys []uint64,
@@ -380,12 +401,12 @@ func (m Mapper) PeerChangedResponse(
 
 	resp := m.baseMapResponse(machine)
 	resp.PeersChanged = tailPeers
-	resp.PeerSeenChange = lastSeen
+	// resp.PeerSeenChange = lastSeen
 
 	return m.marshalMapResponse(&resp, machine, mapRequest.Compress)
 }
 
-func (m Mapper) PeerRemovedResponse(
+func (m *Mapper) PeerRemovedResponse(
 	mapRequest tailcfg.MapRequest,
 	machine *types.Machine,
 	removed []tailcfg.NodeID,
@@ -396,11 +417,13 @@ func (m Mapper) PeerRemovedResponse(
 	return m.marshalMapResponse(&resp, machine, mapRequest.Compress)
 }
 
-func (m Mapper) marshalMapResponse(
+func (m *Mapper) marshalMapResponse(
 	resp *tailcfg.MapResponse,
 	machine *types.Machine,
 	compression string,
 ) ([]byte, error) {
+	atomic.AddUint64(&m.seq, 1)
+
 	var machineKey key.MachinePublic
 	err := machineKey.UnmarshalText([]byte(util.MachinePublicKeyEnsurePrefix(machine.MachineKey)))
 	if err != nil {
@@ -445,11 +468,11 @@ func (m Mapper) marshalMapResponse(
 
 		mapResponsePath := path.Join(
 			mPath,
-			fmt.Sprintf("%d-%s-%d.json", now, m.uid, atomic.LoadUint64(&m.seq)),
+			fmt.Sprintf("%d-%s-%d.json", atomic.LoadUint64(&m.seq), m.uid, now),
 		)
 
 		log.Trace().Msgf("Writing MapResponse to %s", mapResponsePath)
-		err = os.WriteFile(mapResponsePath, body, perms)
+		err = os.WriteFile(mapResponsePath, jsonBody, perms)
 		if err != nil {
 			panic(err)
 		}

hscontrol/notifier/notifier.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/juanfont/headscale/hscontrol/types"
 	"github.com/juanfont/headscale/hscontrol/util"
+	"github.com/rs/zerolog/log"
 )
 
 type Notifier struct {
@@ -25,6 +26,11 @@ func (n *Notifier) AddNode(machineKey string, c chan<- types.StateUpdate) {
 	}
 
 	n.nodes[machineKey] = c
+
+	log.Trace().
+		Str("machine_key", machineKey).
+		Int("open_chans", len(n.nodes)).
+		Msg("Added new channel")
 }
 
 func (n *Notifier) RemoveNode(machineKey string) {
@@ -36,6 +42,11 @@ func (n *Notifier) RemoveNode(machineKey string) {
 	}
 
 	delete(n.nodes, machineKey)
+
+	log.Trace().
+		Str("machine_key", machineKey).
+		Int("open_chans", len(n.nodes)).
+		Msg("Removed channel")
 }
 
 func (n *Notifier) NotifyAll(update types.StateUpdate) {

hscontrol/poll.go

@@ -65,6 +65,7 @@ func (h *Headscale) handlePoll(
 	logInfo, logErr := logPollFunc(mapRequest, machine, isNoise)
 
 	mapp := mapper.NewMapper(
+		machine,
 		h.db,
 		h.privateKey2019,
 		isNoise,
@@ -176,7 +177,6 @@ func (h *Headscale) handlePoll(
 			Bool("noise", isNoise).
 			Str("machine", machine.Hostname).
 			Msg("Ignoring request, don't know how to handle it")
-		http.Error(writer, "", http.StatusBadRequest)
 
 		return
 	}
@@ -239,6 +239,7 @@ func (h *Headscale) pollNetMapStream(
 	defer cancel()
 
 	for {
+		logInfo("Waiting for update on stream channel")
 		select {
 		case <-keepAliveTicker.C:
 			data, err := mapp.KeepAliveResponse(mapRequest, machine)
@@ -256,6 +257,8 @@ func (h *Headscale) pollNetMapStream(
 			if flusher, ok := writer.(http.Flusher); ok {
 				flusher.Flush()
 			} else {
+				log.Error().Msg("Failed to create http flusher")
+
 				return
 			}
 
@@ -267,6 +270,8 @@ func (h *Headscale) pollNetMapStream(
 			}
 
 		case update := <-updateChan:
+			logInfo("Received update")
+
 			var data []byte
 			var err error
 
@@ -304,6 +309,8 @@ func (h *Headscale) pollNetMapStream(
 			if flusher, ok := writer.(http.Flusher); ok {
 				flusher.Flush()
 			} else {
+				log.Error().Msg("Failed to create http flusher")
+
 				return
 			}
 
@@ -318,6 +325,7 @@ func (h *Headscale) pollNetMapStream(
 				return
 			}
 
+			logInfo("Update sent")
 		case <-ctx.Done():
 			logInfo("The client has closed the connection")
 
@@ -335,6 +343,8 @@ func (h *Headscale) pollNetMapStream(
 			return
 		}
 	}
+
+	logInfo("Finishing map stream session")
 }
 
 func closeChanWithLog[C chan []byte | chan struct{} | chan types.StateUpdate](channel C, machine, name string) {

hscontrol/poll_legacy.go

@@ -91,7 +91,7 @@ func (h *Headscale) PollNetMapHandler(
 		Str("handler", "PollNetMap").
 		Str("id", machineKeyStr).
 		Str("machine", machine.Hostname).
-		Msg("A machine is entering polling via the legacy protocol")
+		Msg("A machine is sending a MapRequest via legacy protocol")
 
 	h.handlePoll(writer, req.Context(), machine, mapRequest, false)
 }

hscontrol/poll_noise.go

@@ -72,7 +72,7 @@ func (ns *noiseServer) NoisePollNetMapHandler(
 	log.Debug().
 		Str("handler", "NoisePollNetMap").
 		Str("machine", machine.Hostname).
-		Msg("A machine is entering polling via the Noise protocol")
+		Msg("A machine sending a MapRequest with Noise protocol")
 
 	ns.headscale.handlePoll(writer, req.Context(), machine, mapRequest, true)
 }

integration/hsic/hsic.go

@@ -364,7 +364,7 @@ func (t *HeadscaleInContainer) SaveProfile(savePath string) error {
 	}
 
 	err = os.WriteFile(
-		path.Join(savePath, t.hostname+"maps.tar"),
+		path.Join(savePath, t.hostname+".pprof.tar"),
 		tarFile,
 		os.ModePerm,
 	)
@@ -382,7 +382,7 @@ func (t *HeadscaleInContainer) SaveMapResponses(savePath string) error {
 	}
 
 	err = os.WriteFile(
-		path.Join(savePath, t.hostname+".pprof.tar"),
+		path.Join(savePath, t.hostname+".maps.tar"),
 		tarFile,
 		os.ModePerm,
 	)

integration/tsic/tsic.go

@@ -181,7 +181,7 @@ func New(
 		withEntrypoint: []string{
 			"/bin/sh",
 			"-c",
-			"/bin/sleep 3 ; update-ca-certificates ; tailscaled --tun=tsdev",
+			"/bin/sleep 3 ; update-ca-certificates ; tailscaled --tun=tsdev --verbose=10",
 		},
 	}