From e0ba325b3b15ee785f673c143c615ef4141c9698 Mon Sep 17 00:00:00 2001 From: Kristoffer Dalby Date: Mon, 24 Jul 2023 08:58:51 +0200 Subject: [PATCH] additional debug logging, use mapper pointer Signed-off-by: Kristoffer Dalby --- go.mod | 2 +- go.sum | 9 ++++++++ hscontrol/mapper/mapper.go | 41 ++++++++++++++++++++++++++-------- hscontrol/notifier/notifier.go | 11 +++++++++ hscontrol/poll.go | 12 +++++++++- hscontrol/poll_legacy.go | 2 +- hscontrol/poll_noise.go | 2 +- integration/hsic/hsic.go | 4 ++-- integration/tsic/tsic.go | 2 +- 9 files changed, 69 insertions(+), 16 deletions(-) diff --git a/go.mod b/go.mod index 21070015..2a37c505 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index e5aaa15c..125eca60 100644 --- a/go.sum +++ b/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= diff --git a/hscontrol/mapper/mapper.go b/hscontrol/mapper/mapper.go index 0b004a08..8ae71c90 100644 --- a/hscontrol/mapper/mapper.go +++ b/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) } diff --git a/hscontrol/notifier/notifier.go b/hscontrol/notifier/notifier.go index 53fcd6a5..bcd92c2f 100644 --- a/hscontrol/notifier/notifier.go +++ b/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) { diff --git a/hscontrol/poll.go b/hscontrol/poll.go index 77161fce..075e6825 100644 --- a/hscontrol/poll.go +++ b/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) { diff --git a/hscontrol/poll_legacy.go b/hscontrol/poll_legacy.go index e175df92..90cb1320 100644 --- a/hscontrol/poll_legacy.go +++ b/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) } diff --git a/hscontrol/poll_noise.go b/hscontrol/poll_noise.go index e512213a..a21ef5ff 100644 --- a/hscontrol/poll_noise.go +++ b/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) } diff --git a/integration/hsic/hsic.go b/integration/hsic/hsic.go index 01f34443..7d1bbceb 100644 --- a/integration/hsic/hsic.go +++ b/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, ) diff --git a/integration/tsic/tsic.go b/integration/tsic/tsic.go index 04ad2f3a..158f3a3c 100644 --- a/integration/tsic/tsic.go +++ b/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", }, }