From ee704f8ef35b6ebf54eaad0f7bfd65991ab29739 Mon Sep 17 00:00:00 2001 From: Kristoffer Dalby Date: Thu, 5 Aug 2021 18:11:26 +0100 Subject: [PATCH] Initial port to zerologger --- api.go | 225 +++++++++++++++++++++++++++++++++++++++++++---------- app.go | 22 +++--- go.mod | 1 + go.sum | 2 + machine.go | 5 +- 5 files changed, 202 insertions(+), 53 deletions(-) diff --git a/api.go b/api.go index 97ec4d41..af8a6dcd 100644 --- a/api.go +++ b/api.go @@ -6,10 +6,11 @@ import ( "errors" "fmt" "io" - "log" "net/http" "time" + "github.com/rs/zerolog/log" + "github.com/gin-gonic/gin" "github.com/klauspost/compress/zstd" "gorm.io/datatypes" @@ -63,21 +64,27 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) { mKeyStr := c.Param("id") mKey, err := wgkey.ParseHex(mKeyStr) if err != nil { - log.Printf("Cannot parse machine key: %s", err) + log.Error(). + Str("Handler", "Registration"). + Err(err). + Msg("Cannot parse machine key") c.String(http.StatusInternalServerError, "Sad!") return } req := tailcfg.RegisterRequest{} err = decode(body, &req, &mKey, h.privateKey) if err != nil { - log.Printf("Cannot decode message: %s", err) + log.Error(). + Str("Handler", "Registration"). + Err(err). + Msg("Cannot decode message") c.String(http.StatusInternalServerError, "Very sad!") return } var m Machine if result := h.db.Preload("Namespace").First(&m, "machine_key = ?", mKey.HexString()); errors.Is(result.Error, gorm.ErrRecordNotFound) { - log.Println("New Machine!") + log.Info().Str("Name", req.Hostinfo.Hostname).Msg("New machine") m = Machine{ Expiry: &req.Expiry, MachineKey: mKey.HexString(), @@ -100,13 +107,20 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) { // We have the updated key! if m.NodeKey == wgkey.Key(req.NodeKey).HexString() { if m.Registered { - log.Printf("[%s] Client is registered and we have the current NodeKey. All clear to /map", m.Name) + log.Debug(). + Str("Handler", "Registration"). + Str("Machine", m.Name). + Msg("Client is registered and we have the current NodeKey. All clear to /mSending keepaliveap") + resp.AuthURL = "" resp.MachineAuthorized = true resp.User = *m.Namespace.toUser() respBody, err := encode(resp, &mKey, h.privateKey) if err != nil { - log.Printf("Cannot encode message: %s", err) + log.Error(). + Str("Handler", "Registration"). + Err(err). + Msg("Cannot encode message") c.String(http.StatusInternalServerError, "") return } @@ -114,12 +128,18 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) { return } - log.Printf("[%s] Not registered and not NodeKey rotation. Sending a authurl to register", m.Name) + log.Debug(). + Str("Handler", "Registration"). + Str("Machine", m.Name). + Msg("Not registered and not NodeKey rotation. Sending a authurl to register") resp.AuthURL = fmt.Sprintf("%s/register?key=%s", h.cfg.ServerURL, mKey.HexString()) respBody, err := encode(resp, &mKey, h.privateKey) if err != nil { - log.Printf("Cannot encode message: %s", err) + log.Error(). + Str("Handler", "Registration"). + Err(err). + Msg("Cannot encode message") c.String(http.StatusInternalServerError, "") return } @@ -129,7 +149,10 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) { // The NodeKey we have matches OldNodeKey, which means this is a refresh after an key expiration if m.NodeKey == wgkey.Key(req.OldNodeKey).HexString() { - log.Printf("[%s] We have the OldNodeKey in the database. This is a key refresh", m.Name) + log.Debug(). + Str("Handler", "Registration"). + Str("Machine", m.Name). + Msg("We have the OldNodeKey in the database. This is a key refresh") m.NodeKey = wgkey.Key(req.NodeKey).HexString() h.db.Save(&m) @@ -137,7 +160,10 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) { resp.User = *m.Namespace.toUser() respBody, err := encode(resp, &mKey, h.privateKey) if err != nil { - log.Printf("Cannot encode message: %s", err) + log.Error(). + Str("Handler", "Registration"). + Err(err). + Msg("Cannot encode message") c.String(http.StatusInternalServerError, "Extremely sad!") return } @@ -148,25 +174,38 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) { // We arrive here after a client is restarted without finalizing the authentication flow or // when headscale is stopped in the middle of the auth process. if m.Registered { - log.Printf("[%s] The node is sending us a new NodeKey, but machine is registered. All clear for /map", m.Name) + log.Debug(). + Str("Handler", "Registration"). + Str("Machine", m.Name). + Msg("The node is sending us a new NodeKey, but machine is registered. All clear for /map") resp.AuthURL = "" resp.MachineAuthorized = true resp.User = *m.Namespace.toUser() respBody, err := encode(resp, &mKey, h.privateKey) if err != nil { - log.Printf("Cannot encode message: %s", err) + log.Error(). + Str("Handler", "Registration"). + Err(err). + Msg("Cannot encode message") c.String(http.StatusInternalServerError, "") return } c.Data(200, "application/json; charset=utf-8", respBody) return } - log.Printf("[%s] The node is sending us a new NodeKey, sending auth url", m.Name) + + log.Debug(). + Str("Handler", "Registration"). + Str("Machine", m.Name). + Msg("The node is sending us a new NodeKey, sending auth url") resp.AuthURL = fmt.Sprintf("%s/register?key=%s", h.cfg.ServerURL, mKey.HexString()) respBody, err := encode(resp, &mKey, h.privateKey) if err != nil { - log.Printf("Cannot encode message: %s", err) + log.Error(). + Str("Handler", "Registration"). + Err(err). + Msg("Cannot encode message") c.String(http.StatusInternalServerError, "") return } @@ -187,21 +226,29 @@ func (h *Headscale) PollNetMapHandler(c *gin.Context) { mKeyStr := c.Param("id") mKey, err := wgkey.ParseHex(mKeyStr) if err != nil { - log.Printf("Cannot parse client key: %s", err) + log.Error(). + Str("Handler", "PollNetMap"). + Err(err). + Msg("Cannot parse client key") c.String(http.StatusBadRequest, "") return } req := tailcfg.MapRequest{} err = decode(body, &req, &mKey, h.privateKey) if err != nil { - log.Printf("Cannot decode message: %s", err) + log.Error(). + Str("Handler", "PollNetMap"). + Err(err). + Msg("Cannot decode message") c.String(http.StatusBadRequest, "") return } var m Machine if result := h.db.Preload("Namespace").First(&m, "machine_key = ?", mKey.HexString()); errors.Is(result.Error, gorm.ErrRecordNotFound) { - log.Printf("Ignoring request, cannot find machine with key %s", mKey.HexString()) + log.Warn(). + Str("Handler", "PollNetMap"). + Msgf("Ignoring request, cannot find machine with key %s", mKey.HexString()) c.String(http.StatusUnauthorized, "") return } @@ -247,37 +294,66 @@ func (h *Headscale) PollNetMapHandler(c *gin.Context) { // empty endpoints to peers) // Details on the protocol can be found in https://github.com/tailscale/tailscale/blob/main/tailcfg/tailcfg.go#L696 - log.Printf("[%s] ReadOnly=%t OmitPeers=%t Stream=%t", m.Name, req.ReadOnly, req.OmitPeers, req.Stream) + log.Debug(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Bool("ReadOnly", req.ReadOnly). + Bool("OmitPeers", req.OmitPeers). + Bool("Stream", req.Stream) if req.ReadOnly { - log.Printf("[%s] Client is starting up. Asking for DERP map", m.Name) + log.Info(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Msg("Client is starting up. Asking for DERP map") c.Data(200, "application/json; charset=utf-8", *data) return } if req.OmitPeers && !req.Stream { - log.Printf("[%s] Client sent endpoint update and is ok with a response without peer list", m.Name) + log.Info(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Msg("Client sent endpoint update and is ok with a response without peer list") c.Data(200, "application/json; charset=utf-8", *data) return } else if req.OmitPeers && req.Stream { - log.Printf("[%s] Warning, ignoring request, don't know how to handle it", m.Name) + log.Warn(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Msg("Ignoring request, don't know how to handle it") c.String(http.StatusBadRequest, "") return } - log.Printf("[%s] Client is ready to access the tailnet", m.Name) - log.Printf("[%s] Sending initial map", m.Name) + log.Info(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Msg("Client is ready to access the tailnet") + log.Info(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Msg("Sending initial map") pollData <- *data - log.Printf("[%s] Notifying peers", m.Name) + log.Printf("[PollMap] (%s) Notifying peers", m.Name) peers, _ := h.getPeers(m) h.pollMu.Lock() for _, p := range *peers { pUp, ok := h.clientsPolling[uint64(p.ID)] if ok { - log.Printf("[%s] Notifying peer %s (%s)", m.Name, p.Name, p.Addresses[0]) + log.Info(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Str("Peer", m.Name). + Str("Address", p.Addresses[0].String()). + Msgf("Notifying peer %s (%s)", p.Name, p.Addresses[0]) pUp <- []byte{} } else { - log.Printf("[%s] Peer %s does not appear to be polling", m.Name, p.Name) + log.Info(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Str("Peer", m.Name). + Msgf("Peer %s does not appear to be polling", p.Name) } } h.pollMu.Unlock() @@ -287,10 +363,18 @@ func (h *Headscale) PollNetMapHandler(c *gin.Context) { c.Stream(func(w io.Writer) bool { select { case data := <-pollData: - log.Printf("[%s] Sending data (%d bytes)", m.Name, len(data)) + log.Trace(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Int("Bytes", len(data)). + Msg("Sending data") _, err := w.Write(data) if err != nil { - log.Printf("[%s] Cannot write data: %s", m.Name, err) + log.Error(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Err(err). + Msg("Cannot write data") } now := time.Now().UTC() m.LastSeen = &now @@ -298,19 +382,33 @@ func (h *Headscale) PollNetMapHandler(c *gin.Context) { return true case <-update: - log.Printf("[%s] Received a request for update", m.Name) + log.Debug(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Msg("Received a request for update") data, err := h.getMapResponse(mKey, req, m) if err != nil { - log.Printf("[%s] Could not get the map update: %s", m.Name, err) + log.Error(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Err(err). + Msg("Could not get the map update") } _, err = w.Write(*data) if err != nil { - log.Printf("[%s] Could not write the map response: %s", m.Name, err) + log.Error(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Err(err). + Msg("Could not write the map response") } return true case <-c.Request.Context().Done(): - log.Printf("[%s] The client has closed the connection", m.Name) + log.Info(). + Str("Handler", "PollNetMap"). + Str("Machine", m.Name). + Msg("The client has closed the connection") now := time.Now().UTC() m.LastSeen = &now h.db.Save(&m) @@ -335,10 +433,16 @@ func (h *Headscale) keepAlive(cancel chan []byte, pollData chan []byte, mKey wgk h.pollMu.Lock() data, err := h.getMapKeepAliveResponse(mKey, req, m) if err != nil { - log.Printf("Error generating the keep alive msg: %s", err) + log.Error(). + Str("Func", "keepAlive"). + Err(err). + Msg("Error generating the keep alive msg") return } - log.Printf("[%s] Sending keepalive", m.Name) + log.Debug(). + Str("Func", "keepAlive"). + Str("Machine", m.Name). + Msg("Sending keepalive") pollData <- *data h.pollMu.Unlock() time.Sleep(60 * time.Second) @@ -349,12 +453,18 @@ func (h *Headscale) keepAlive(cancel chan []byte, pollData chan []byte, mKey wgk func (h *Headscale) getMapResponse(mKey wgkey.Key, req tailcfg.MapRequest, m Machine) (*[]byte, error) { node, err := m.toNode() if err != nil { - log.Printf("Cannot convert to node: %s", err) + log.Error(). + Str("Func", "getMapResponse"). + Err(err). + Msg("Cannot convert to node") return nil, err } peers, err := h.getPeers(m) if err != nil { - log.Printf("Cannot fetch peers: %s", err) + log.Error(). + Str("Func", "getMapResponse"). + Err(err). + Msg("Cannot fetch peers") return nil, err } @@ -426,26 +536,49 @@ func (h *Headscale) getMapKeepAliveResponse(mKey wgkey.Key, req tailcfg.MapReque } func (h *Headscale) handleAuthKey(c *gin.Context, db *gorm.DB, idKey wgkey.Key, req tailcfg.RegisterRequest, m Machine) { + log.Debug(). + Str("Func", "handleAuthKey"). + Str("Machine", req.Hostinfo.Hostname). + Msgf("Processing auth key for %s", req.Hostinfo.Hostname) resp := tailcfg.RegisterResponse{} pak, err := h.checkKeyValidity(req.Auth.AuthKey) if err != nil { resp.MachineAuthorized = false respBody, err := encode(resp, &idKey, h.privateKey) if err != nil { - log.Printf("Cannot encode message: %s", err) + log.Error(). + Str("Func", "handleAuthKey"). + Str("Machine", m.Name). + Err(err). + Msg("Cannot encode message") c.String(http.StatusInternalServerError, "") return } c.Data(200, "application/json; charset=utf-8", respBody) - log.Printf("[%s] Failed authentication via AuthKey", m.Name) + log.Error(). + Str("Func", "handleAuthKey"). + Str("Machine", m.Name). + Msg("Failed authentication via AuthKey") return } + + log.Debug(). + Str("Func", "handleAuthKey"). + Str("Machine", m.Name). + Msg("Authentication key was valid, proceeding to acquire an IP address") ip, err := h.getAvailableIP() if err != nil { - log.Println(err) + log.Error(). + Str("Func", "handleAuthKey"). + Str("Machine", m.Name). + Msg("Failed to find an available IP") return } - log.Printf("Assigning %s to %s", ip, m.Name) + log.Info(). + Str("Func", "handleAuthKey"). + Str("Machine", m.Name). + Str("IP", ip.String()). + Msgf("Assining %s to %s", ip, m.Name) m.AuthKeyID = uint(pak.ID) m.IPAddress = ip.String() @@ -459,10 +592,18 @@ func (h *Headscale) handleAuthKey(c *gin.Context, db *gorm.DB, idKey wgkey.Key, resp.User = *pak.Namespace.toUser() respBody, err := encode(resp, &idKey, h.privateKey) if err != nil { - log.Printf("Cannot encode message: %s", err) + log.Error(). + Str("Func", "handleAuthKey"). + Str("Machine", m.Name). + Err(err). + Msg("Cannot encode message") c.String(http.StatusInternalServerError, "Extremely sad!") return } c.Data(200, "application/json; charset=utf-8", respBody) - log.Printf("[%s] Successfully authenticated via AuthKey", m.Name) + log.Info(). + Str("Func", "handleAuthKey"). + Str("Machine", m.Name). + Str("IP", ip.String()). + Msg("Successfully authenticated via AuthKey") } diff --git a/app.go b/app.go index 70ea2cd1..012ab9ea 100644 --- a/app.go +++ b/app.go @@ -3,13 +3,14 @@ package headscale import ( "errors" "fmt" - "log" "net/http" "os" "strings" "sync" "time" + "github.com/rs/zerolog/log" + "github.com/gin-gonic/gin" "golang.org/x/crypto/acme/autocert" "gorm.io/gorm" @@ -120,21 +121,21 @@ func (h *Headscale) ExpireEphemeralNodes(milliSeconds int64) { func (h *Headscale) expireEphemeralNodesWorker() { namespaces, err := h.ListNamespaces() if err != nil { - log.Printf("Error listing namespaces: %s", err) + log.Error().Err(err).Msg("Error listing namespaces") return } for _, ns := range *namespaces { machines, err := h.ListMachinesInNamespace(ns.Name) if err != nil { - log.Printf("Error listing machines in namespace %s: %s", ns.Name, err) + log.Error().Err(err).Str("Namespace", ns.Name).Msg("Error listing machines in namespace") return } for _, m := range *machines { if m.AuthKey != nil && m.LastSeen != nil && m.AuthKey.Ephemeral && time.Now().After(m.LastSeen.Add(h.cfg.EphemeralNodeInactivityTimeout)) { - log.Printf("[%s] Ephemeral client removed from database\n", m.Name) + log.Info().Str("Machine", m.Name).Msg("Ephemeral client removed from database") err = h.db.Unscoped().Delete(m).Error if err != nil { - log.Printf("[%s] 🤮 Cannot delete ephemeral machine from the database: %s", m.Name, err) + log.Error().Err(err).Str("Name", m.Name).Msg("🤮 Cannot delete ephemeral machine from the database") } } } @@ -168,7 +169,7 @@ func (h *Headscale) Serve() error { if h.cfg.TLSLetsEncryptHostname != "" { if !strings.HasPrefix(h.cfg.ServerURL, "https://") { - log.Println("WARNING: listening with TLS but ServerURL does not start with https://") + log.Warn().Msg("Listening with TLS but ServerURL does not start with https://") } m := autocert.Manager{ @@ -191,7 +192,10 @@ func (h *Headscale) Serve() error { // port 80 for the certificate validation in addition to the headscale // service, which can be configured to run on any other port. go func() { - log.Fatal(http.ListenAndServe(h.cfg.TLSLetsEncryptListen, m.HTTPHandler(http.HandlerFunc(h.redirect)))) + + log.Fatal(). + Err(http.ListenAndServe(h.cfg.TLSLetsEncryptListen, m.HTTPHandler(http.HandlerFunc(h.redirect)))). + Msg("failed to set up a HTTP server") }() err = s.ListenAndServeTLS("", "") } else { @@ -199,12 +203,12 @@ func (h *Headscale) Serve() error { } } else if h.cfg.TLSCertPath == "" { if !strings.HasPrefix(h.cfg.ServerURL, "http://") { - log.Println("WARNING: listening without TLS but ServerURL does not start with http://") + log.Warn().Msg("Listening without TLS but ServerURL does not start with http://") } err = r.Run(h.cfg.Addr) } else { if !strings.HasPrefix(h.cfg.ServerURL, "https://") { - log.Println("WARNING: listening with TLS but ServerURL does not start with https://") + log.Warn().Msg("Listening with TLS but ServerURL does not start with https://") } err = r.RunTLS(h.cfg.Addr, h.cfg.TLSCertPath, h.cfg.TLSKeyPath) } diff --git a/go.mod b/go.mod index 0d8c86b5..818683ef 100644 --- a/go.mod +++ b/go.mod @@ -9,6 +9,7 @@ require ( github.com/klauspost/compress v1.13.1 github.com/lib/pq v1.10.2 // indirect github.com/mattn/go-sqlite3 v1.14.7 // indirect + github.com/rs/zerolog v1.23.0 // indirect github.com/spf13/cobra v1.1.3 github.com/spf13/viper v1.8.1 github.com/tailscale/hujson v0.0.0-20200924210142-dde312d0d6a2 diff --git a/go.sum b/go.sum index 4751eaac..4b189d72 100644 --- a/go.sum +++ b/go.sum @@ -683,6 +683,8 @@ github.com/rogpeppe/go-internal v1.6.2/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTE github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ= github.com/rs/zerolog v1.13.0/go.mod h1:YbFCdg8HfsridGWAh22vktObvhZbQsZXe4/zB0OKkWU= github.com/rs/zerolog v1.15.0/go.mod h1:xYTKnLHcpfU2225ny5qZjxnj9NvkumZYjJHlAThCjNc= +github.com/rs/zerolog v1.23.0 h1:UskrK+saS9P9Y789yNNulYKdARjPZuS35B8gJF2x60g= +github.com/rs/zerolog v1.23.0/go.mod h1:6c7hFfxPOy7TacJc4Fcdi24/J0NKYGzjG8FWRI916Qo= github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM= github.com/ryancurrah/gomodguard v1.1.0/go.mod h1:4O8tr7hBODaGE6VIhfJDHcwzh5GUccKSJBU0UMXJFVM= github.com/ryanrolds/sqlclosecheck v0.3.0/go.mod h1:1gREqxyTGR3lVtpngyFo3hZAgk0KCtEdgEkHwDbigdA= diff --git a/machine.go b/machine.go index 1895e464..f2745c06 100644 --- a/machine.go +++ b/machine.go @@ -3,11 +3,12 @@ package headscale import ( "encoding/json" "fmt" - "log" "sort" "strconv" "time" + "github.com/rs/zerolog/log" + "gorm.io/datatypes" "inet.af/netaddr" "tailscale.com/tailcfg" @@ -157,7 +158,7 @@ func (h *Headscale) getPeers(m Machine) (*[]*tailcfg.Node, error) { machines := []Machine{} if err := h.db.Where("namespace_id = ? AND machine_key <> ? AND registered", m.NamespaceID, m.MachineKey).Find(&machines).Error; err != nil { - log.Printf("Error accessing db: %s", err) + log.Error().Err(err).Msg("Error accessing db") return nil, err }