MyFavMirrors
/
headscale
mirror of https://github.com/juanfont/headscale.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Merge pull request #74 from kradalby/deadlock-logging 

Switch to a structured logger
This commit is contained in:
Juan Font 2021-08-06 00:18:40 +02:00 committed by GitHub
parent 4aad3b7933 575b15e5fa
commit d421c7b665
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
11 changed files with 336 additions and 80 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

5
README.md
View File

@ -119,6 +119,11 @@ Headscale's configuration file is named `config.json` or `config.yaml`. Headscal
`server_url` is the external URL via which Headscale is reachable. `listen_addr` is the IP address and port the Headscale program should listen on. `ip_prefix` is the IP prefix (range) in which IP addresses for nodes will be allocated (default 100.64.0.0/10, e.g., 192.168.4.0/24, 10.0.0.0/8)
```
"log_level": "debug"
```
`log_level` can be used to set the Log level for Headscale, it defaults to `debug`, and the available levels are: `trace`, `debug`, `info`, `warn` and `error`.
```
"private_key_path": "private.key",
```

9
acls.go
View File

@ -4,11 +4,12 @@ import (
"encoding/json"
"fmt"
"io"
"log"
"os"
"strconv"
"strings"
"github.com/rs/zerolog/log"
"github.com/tailscale/hujson"
"inet.af/netaddr"
"tailscale.com/tailcfg"
@ -66,7 +67,8 @@ func (h *Headscale) generateACLRules() (*[]tailcfg.FilterRule, error) {
for j, u := range a.Users {
srcs, err := h.generateACLPolicySrcIP(u)
if err != nil {
log.Printf("Error parsing ACL %d, User %d", i, j)
log.Error().
Msgf("Error parsing ACL %d, User %d", i, j)
return nil, err
}
srcIPs = append(srcIPs, *srcs...)
@ -77,7 +79,8 @@ func (h *Headscale) generateACLRules() (*[]tailcfg.FilterRule, error) {
for j, d := range a.Ports {
dests, err := h.generateACLPolicyDestPorts(d)
if err != nil {
log.Printf("Error parsing ACL %d, Port %d", i, j)
log.Error().
Msgf("Error parsing ACL %d, Port %d", i, j)
return nil, err
}
destPorts = append(destPorts, *dests...)

271
api.go
View File

@ -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("machine", req.Hostinfo.Hostname).Msg("New machine")
m = Machine{
Expiry: &req.Expiry,
MachineKey: mKey.HexString(),
@ -85,7 +92,10 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) {
NodeKey: wgkey.Key(req.NodeKey).HexString(),
}
if err := h.db.Create(&m).Error; err != nil {
log.Printf("Could not create row: %s", err)
log.Error().
Str("handler", "Registration").
Err(err).
Msg("Could not create row")
return
}
}
@ -100,13 +110,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 +131,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 +152,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 +163,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 +177,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
}
@ -183,28 +225,45 @@ func (h *Headscale) RegistrationHandler(c *gin.Context) {
//
// At this moment the updates are sent in a quite horrendous way, but they kinda work.
func (h *Headscale) PollNetMapHandler(c *gin.Context) {
log.Trace().
Str("handler", "PollNetMap").
Str("id", c.Param("id")).
Msg("PollNetMapHandler called")
body, _ := io.ReadAll(c.Request.Body)
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
}
log.Trace().
Str("handler", "PollNetMap").
Str("id", c.Param("id")).
Str("machine", m.Name).
Msg("Found machine in database")
hostinfo, _ := json.Marshal(req.Hostinfo)
m.Name = req.Hostinfo.Hostname
@ -227,17 +286,36 @@ func (h *Headscale) PollNetMapHandler(c *gin.Context) {
}
h.db.Save(&m)
pollData := make(chan []byte, 1)
update := make(chan []byte, 1)
cancelKeepAlive := make(chan []byte, 1)
pollData := make(chan []byte, 1)
defer close(pollData)
cancelKeepAlive := make(chan []byte, 1)
defer close(cancelKeepAlive)
log.Trace().
Str("handler", "PollNetMap").
Str("id", c.Param("id")).
Str("machine", m.Name).
Msg("Locking poll mutex")
h.pollMu.Lock()
h.clientsPolling[m.ID] = update
h.pollMu.Unlock()
log.Trace().
Str("handler", "PollNetMap").
Str("id", c.Param("id")).
Str("machine", m.Name).
Msg("Unlocking poll mutex")
data, err := h.getMapResponse(mKey, req, m)
if err != nil {
log.Error().
Str("handler", "PollNetMap").
Str("id", c.Param("id")).
Str("machine", m.Name).
Err(err).
Msg("Failed to get Map response")
c.String(http.StatusInternalServerError, ":(")
return
}
@ -247,37 +325,71 @@ 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("id", c.Param("id")).
Str("machine", m.Name).
Bool("readOnly", req.ReadOnly).
Bool("omitPeers", req.OmitPeers).
Bool("stream", req.Stream).
Msg("Client map request processed")
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.Info().
Str("handler", "PollNetMap").
Str("machine", m.Name).
Msg("Notifying peers")
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 +399,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 +418,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 +469,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)
@ -347,14 +487,24 @@ 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) {
log.Trace().
Str("func", "getMapResponse").
Str("machine", req.Hostinfo.Hostname).
Msg("Creating Map response")
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 +576,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 +632,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")
}

22
app.go
View File

@ -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("machine", 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)
}

5
cmd/headscale/cli/root.go
View File

@ -2,8 +2,9 @@ package cli
import (
"fmt"
"github.com/spf13/cobra"
"os"
"github.com/spf13/cobra"
)
func init() {
@ -17,7 +18,7 @@ var rootCmd = &cobra.Command{
headscale is an open source implementation of the Tailscale control server
Juan Font Alonso <juanfontalonso@gmail.com> - 2021
https://gitlab.com/juanfont/headscale`,
https://github.com/juanfont/headscale`,
}
func Execute() {

31
cmd/headscale/cli/utils.go
View File

@ -5,13 +5,13 @@ import (
"errors"
"fmt"
"io"
"log"
"os"
"path/filepath"
"strings"
"time"
"github.com/juanfont/headscale"
"github.com/rs/zerolog/log"
"github.com/spf13/viper"
"gopkg.in/yaml.v2"
"inet.af/netaddr"
@ -39,6 +39,8 @@ func LoadConfig(path string) error {
viper.SetDefault("ip_prefix", "100.64.0.0/10")
viper.SetDefault("log_level", "debug")
err := viper.ReadInConfig()
if err != nil {
return fmt.Errorf("Fatal error reading config file: %s \n", err)
@ -52,7 +54,8 @@ func LoadConfig(path string) error {
if (viper.GetString("tls_letsencrypt_hostname") != "") && (viper.GetString("tls_letsencrypt_challenge_type") == "TLS-ALPN-01") && (!strings.HasSuffix(viper.GetString("listen_addr"), ":443")) {
// this is only a warning because there could be something sitting in front of headscale that redirects the traffic (e.g. an iptables rule)
log.Println("Warning: when using tls_letsencrypt_hostname with TLS-ALPN-01 as challenge type, headscale must be reachable on port 443, i.e. listen_addr should probably end in :443")
log.Warn().
Msg("Warning: when using tls_letsencrypt_hostname with TLS-ALPN-01 as challenge type, headscale must be reachable on port 443, i.e. listen_addr should probably end in :443")
}
if (viper.GetString("tls_letsencrypt_challenge_type") != "HTTP-01") && (viper.GetString("tls_letsencrypt_challenge_type") != "TLS-ALPN-01") {
@ -82,9 +85,13 @@ func absPath(path string) string {
}
func getHeadscaleApp() (*headscale.Headscale, error) {
derpMap, err := loadDerpMap(absPath(viper.GetString("derp_map_path")))
derpPath := absPath(viper.GetString("derp_map_path"))
derpMap, err := loadDerpMap(derpPath)
if err != nil {
log.Printf("Could not load DERP servers map file: %s", err)
log.Error().
Str("path", derpPath).
Err(err).
Msg("Could not load DERP servers map file")
}
// Minimum inactivity time out is keepalive timeout (60s) plus a few seconds
@ -129,9 +136,13 @@ func getHeadscaleApp() (*headscale.Headscale, error) {
// We are doing this here, as in the future could be cool to have it also hot-reload
if viper.GetString("acl_policy_path") != "" {
err = h.LoadACLPolicy(absPath(viper.GetString("acl_policy_path")))
aclPath := absPath(viper.GetString("acl_policy_path"))
err = h.LoadACLPolicy(aclPath)
if err != nil {
log.Printf("Could not load the ACL policy: %s", err)
log.Error().
Str("path", aclPath).
Err(err).
Msg("Could not load the ACL policy")
}
}
@ -161,24 +172,24 @@ func JsonOutput(result interface{}, errResult error, outputFormat string) {
if errResult != nil {
j, err = json.MarshalIndent(ErrorOutput{errResult.Error()}, "", "\t")
if err != nil {
log.Fatalln(err)
log.Fatal().Err(err)
}
} else {
j, err = json.MarshalIndent(result, "", "\t")
if err != nil {
log.Fatalln(err)
log.Fatal().Err(err)
}
}
case "json-line":
if errResult != nil {
j, err = json.Marshal(ErrorOutput{errResult.Error()})
if err != nil {
log.Fatalln(err)
log.Fatal().Err(err)
}
} else {
j, err = json.Marshal(result)
if err != nil {
log.Fatalln(err)
log.Fatal().Err(err)
}
}
}

30
cmd/headscale/headscale.go
View File

@ -1,15 +1,41 @@
package main
import (
"log"
"os"
"time"
"github.com/juanfont/headscale/cmd/headscale/cli"
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
"github.com/spf13/viper"
)
func main() {
zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
log.Logger = log.Output(zerolog.ConsoleWriter{
Out: os.Stdout,
TimeFormat: time.RFC3339,
})
err := cli.LoadConfig("")
if err != nil {
log.Fatalf(err.Error())
log.Fatal().Err(err)
}
logLevel := viper.GetString("log_level")
switch logLevel {
case "trace":
zerolog.SetGlobalLevel(zerolog.TraceLevel)
case "debug":
zerolog.SetGlobalLevel(zerolog.DebugLevel)
case "info":
zerolog.SetGlobalLevel(zerolog.InfoLevel)
case "warn":
zerolog.SetGlobalLevel(zerolog.WarnLevel)
case "error":
zerolog.SetGlobalLevel(zerolog.ErrorLevel)
default:
zerolog.SetGlobalLevel(zerolog.DebugLevel)
}
cli.Execute()

1
go.mod
View File

@ -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

2
go.sum
View File

@ -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=

5
machine.go
View File

@ -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
}

35
namespaces.go
View File

@ -4,9 +4,9 @@ import (
"encoding/json"
"errors"
"fmt"
"log"
"time"
"github.com/rs/zerolog/log"
"gorm.io/gorm"
"tailscale.com/tailcfg"
)
@ -33,7 +33,10 @@ func (h *Headscale) CreateNamespace(name string) (*Namespace, error) {
}
n.Name = name
if err := h.db.Create(&n).Error; err != nil {
log.Printf("Could not create row: %s", err)
log.Error().
Str("func", "CreateNamespace").
Err(err).
Msg("Could not create row")
return nil, err
}
return &n, nil
@ -133,7 +136,10 @@ func (h *Headscale) RequestMapUpdates(namespaceID uint) error {
names = append(names, namespace.Name)
data, err := json.Marshal(names)
if err != nil {
log.Printf("Could not marshal namespaces_pending_updates: %s", err)
log.Error().
Str("func", "RequestMapUpdates").
Err(err).
Msg("Could not marshal namespaces_pending_updates")
return err
}
return h.setValue("namespaces_pending_updates", string(data))
@ -154,7 +160,10 @@ func (h *Headscale) checkForNamespacesPendingUpdates() {
return
}
for _, name := range names {
log.Printf("Sending updates to nodes in namespace %s", name)
log.Trace().
Str("func", "RequestMapUpdates").
Str("machine", name).
Msg("Sending updates to nodes in namespace")
machines, err := h.ListMachinesInNamespace(name)
if err != nil {
continue
@ -165,10 +174,19 @@ func (h *Headscale) checkForNamespacesPendingUpdates() {
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("func", "checkForNamespacesPendingUpdates").
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("func", "checkForNamespacesPendingUpdates").
Str("machine", m.Name).
Str("peer", m.Name).
Msgf("Peer %s does not appear to be polling", p.Name)
}
}
h.pollMu.Unlock()
@ -181,7 +199,10 @@ func (h *Headscale) checkForNamespacesPendingUpdates() {
if v == newV { // only clear when no changes, so we notified everybody
err = h.setValue("namespaces_pending_updates", "")
if err != nil {
log.Printf("Could not save to KV: %s", err)
log.Error().
Str("func", "checkForNamespacesPendingUpdates").
Err(err).
Msg("Could not save to KV")
return
}
}