Mirrors/juanfont.headscale
1
0
Fork 0
mirror of https://github.com/juanfont/headscale.git synced 2026-02-07 20:04:00 +01:00
Code Issues Projects Releases Wiki Activity

hscontrol/state,db: use zf constants for logging

Browse Source 
Replace raw string field names with zf constants in state.go and
db/node.go for consistent, type-safe logging.

state.go changes:
- User creation, hostinfo validation, node registration
- Tag processing during reauth (processReauthTags)
- Auth path and PreAuthKey handling
- Route auto-approval and MapRequest processing

db/node.go changes:
- RegisterNodeForTest logging
- Invalid hostname replacement logging
This commit is contained in:
Kristoffer Dalby 2026-02-05 11:55:20 +00:00
parent e0a436cefc
commit dd16567c52
2 changed files with 120 additions and 107 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

47
hscontrol/db/node.go
View File

@ -16,6 +16,7 @@ import (
"github.com/juanfont/headscale/hscontrol/types"
"github.com/juanfont/headscale/hscontrol/util"
"github.com/juanfont/headscale/hscontrol/util/zlog/zf"
"github.com/rs/zerolog/log"
"gorm.io/gorm"
"tailscale.com/net/tsaddr"
@ -207,6 +208,7 @@ func SetTags(
slices.Sort(tags)
tags = slices.Compact(tags)
b, err := json.Marshal(tags)
if err != nil {
return err
@ -228,7 +230,8 @@ func SetApprovedRoutes(
) error {
if len(routes) == 0 {
// if no routes are provided, we remove all
if err := tx.Model(&types.Node{}).Where("id = ?", nodeID).Update("approved_routes", "[]").Error; err != nil {
err := tx.Model(&types.Node{}).Where("id = ?", nodeID).Update("approved_routes", "[]").Error
if err != nil {
return fmt.Errorf("removing approved routes: %w", err)
}
@ -277,13 +280,16 @@ func SetLastSeen(tx *gorm.DB, nodeID types.NodeID, lastSeen time.Time) error {
func RenameNode(tx *gorm.DB,
nodeID types.NodeID, newName string,
) error {
if err := util.ValidateHostname(newName); err != nil {
err := util.ValidateHostname(newName)
if err != nil {
return fmt.Errorf("renaming node: %w", err)
}
// Check if the new name is unique
var count int64
if err := tx.Model(&types.Node{}).Where("given_name = ? AND id != ?", newName, nodeID).Count(&count).Error; err != nil {
err = tx.Model(&types.Node{}).Where("given_name = ? AND id != ?", newName, nodeID).Count(&count).Error
if err != nil {
return fmt.Errorf("failed to check name uniqueness: %w", err)
}
@ -352,16 +358,16 @@ func RegisterNodeForTest(tx *gorm.DB, node types.Node, ipv4 *netip.Addr, ipv6 *n
}
logEvent := log.Debug().
Str("node", node.Hostname).
Str("machine_key", node.MachineKey.ShortString()).
Str("node_key", node.NodeKey.ShortString())
Str(zf.NodeHostname, node.Hostname).
Str(zf.MachineKey, node.MachineKey.ShortString()).
Str(zf.NodeKey, node.NodeKey.ShortString())
if node.User != nil {
logEvent = logEvent.Str("user", node.User.Username())
logEvent = logEvent.Str(zf.UserName, node.User.Username())
} else if node.UserID != nil {
logEvent = logEvent.Uint("user_id", *node.UserID)
logEvent = logEvent.Uint(zf.UserID, *node.UserID)
} else {
logEvent = logEvent.Str("user", "none")
logEvent = logEvent.Str(zf.UserName, "none")
}
logEvent.Msg("Registering test node")
@ -379,6 +385,7 @@ func RegisterNodeForTest(tx *gorm.DB, node types.Node, ipv4 *netip.Addr, ipv6 *n
if ipv4 == nil {
ipv4 = oldNode.IPv4
}
if ipv6 == nil {
ipv6 = oldNode.IPv6
}
@ -394,10 +401,10 @@ func RegisterNodeForTest(tx *gorm.DB, node types.Node, ipv4 *netip.Addr, ipv6 *n
log.Trace().
Caller().
Str("node", node.Hostname).
Str("machine_key", node.MachineKey.ShortString()).
Str("node_key", node.NodeKey.ShortString()).
Str("user", node.User.Username()).
Str(zf.NodeHostname, node.Hostname).
Str(zf.MachineKey, node.MachineKey.ShortString()).
Str(zf.NodeKey, node.NodeKey.ShortString()).
Str(zf.UserName, node.User.Username()).
Msg("Test node authorized again")
return &node, nil
@ -407,10 +414,11 @@ func RegisterNodeForTest(tx *gorm.DB, node types.Node, ipv4 *netip.Addr, ipv6 *n
node.IPv6 = ipv6
var err error
node.Hostname, err = util.NormaliseHostname(node.Hostname)
if err != nil {
newHostname := util.InvalidString()
log.Info().Err(err).Str("invalid-hostname", node.Hostname).Str("new-hostname", newHostname).Msgf("Invalid hostname, replacing")
log.Info().Err(err).Str(zf.InvalidHostname, node.Hostname).Str(zf.NewHostname, newHostname).Msgf("Invalid hostname, replacing")
node.Hostname = newHostname
}
@ -429,7 +437,7 @@ func RegisterNodeForTest(tx *gorm.DB, node types.Node, ipv4 *netip.Addr, ipv6 *n
log.Trace().
Caller().
Str("node", node.Hostname).
Str(zf.NodeHostname, node.Hostname).
Msg("Test node registered with the database")
return &node, nil
@ -491,8 +499,10 @@ func generateGivenName(suppliedName string, randomSuffix bool) (string, error) {
func isUniqueName(tx *gorm.DB, name string) (bool, error) {
nodes := types.Nodes{}
if err := tx.
Where("given_name = ?", name).Find(&nodes).Error; err != nil {
err := tx.
Where("given_name = ?", name).Find(&nodes).Error
if err != nil {
return false, err
}
@ -694,9 +704,12 @@ func (hsdb *HSDatabase) CreateRegisteredNodeForTest(user *types.User, hostname .
}
var registeredNode *types.Node
err = hsdb.DB.Transaction(func(tx *gorm.DB) error {
var err error
registeredNode, err = RegisterNodeForTest(tx, *node, ipv4, ipv6)
return err
})
if err != nil {

180
hscontrol/state/state.go
View File

@ -280,7 +280,7 @@ func (s *State) CreateUser(user types.User) (*types.User, change.Change, error)
c = change.PolicyChange()
}
log.Info().Str("user.name", user.Name).Msg("User created")
log.Info().Str(zf.UserName, user.Name).Msg("User created")
return &user, c, nil
}
@ -1064,18 +1064,18 @@ func logHostinfoValidation(machineKey, nodeKey, username, hostname string, hosti
if hostinfo == nil {
log.Warn().
Caller().
Str("machine.key", machineKey).
Str("node.key", nodeKey).
Str("user.name", username).
Str("generated.hostname", hostname).
Str(zf.MachineKey, machineKey).
Str(zf.NodeKey, nodeKey).
Str(zf.UserName, username).
Str(zf.GeneratedHostname, hostname).
Msg("Registration had nil hostinfo, generated default hostname")
} else if hostinfo.Hostname == "" {
log.Warn().
Caller().
Str("machine.key", machineKey).
Str("node.key", nodeKey).
Str("user.name", username).
Str("generated.hostname", hostname).
Str(zf.MachineKey, machineKey).
Str(zf.NodeKey, nodeKey).
Str(zf.UserName, username).
Str(zf.GeneratedHostname, hostname).
Msg("Registration had empty hostname, generated default")
}
}
@ -1348,8 +1348,8 @@ func (s *State) createAndSaveNewNode(params newNodeParams) (types.NodeView, erro
nodeToRegister.Expiry = nil
log.Info().
Str("node.name", nodeToRegister.Hostname).
Strs("tags", nodeToRegister.Tags).
Str(zf.NodeName, nodeToRegister.Hostname).
Strs(zf.NodeTags, nodeToRegister.Tags).
Msg("approved advertise-tags during registration")
}
}
@ -1435,23 +1435,23 @@ func (s *State) processReauthTags(
wasAuthKeyTagged := node.AuthKey != nil && node.AuthKey.IsTagged()
logEvent := log.Debug().
Uint64("node.id", uint64(node.ID)).
Str("node.name", node.Hostname).
Strs("request.tags", requestTags).
Strs("current.tags", node.Tags).
Bool("is.tagged", node.IsTagged()).
Bool("was.authkey.tagged", wasAuthKeyTagged)
Uint64(zf.NodeID, uint64(node.ID)).
Str(zf.NodeName, node.Hostname).
Strs(zf.RequestTags, requestTags).
Strs(zf.CurrentTags, node.Tags).
Bool(zf.IsTagged, node.IsTagged()).
Bool(zf.WasAuthKeyTagged, wasAuthKeyTagged)
logEvent.Msg("Processing RequestTags during reauth")
// Empty RequestTags means untag node (transition to user-owned)
if len(requestTags) == 0 {
if node.IsTagged() {
log.Info().
Uint64("node.id", uint64(node.ID)).
Str("node.name", node.Hostname).
Strs("removed.tags", node.Tags).
Str("user.name", user.Name).
Bool("was.authkey.tagged", wasAuthKeyTagged).
Uint64(zf.NodeID, uint64(node.ID)).
Str(zf.NodeName, node.Hostname).
Strs(zf.RemovedTags, node.Tags).
Str(zf.UserName, user.Name).
Bool(zf.WasAuthKeyTagged, wasAuthKeyTagged).
Msg("Reauth: removing all tags, returning node ownership to user")
node.Tags = []string{}
@ -1475,9 +1475,9 @@ func (s *State) processReauthTags(
if len(rejectedTags) > 0 {
log.Warn().
Uint64("node.id", uint64(node.ID)).
Str("node.name", node.Hostname).
Strs("rejected.tags", rejectedTags).
Uint64(zf.NodeID, uint64(node.ID)).
Str(zf.NodeName, node.Hostname).
Strs(zf.RejectedTags, rejectedTags).
Msg("Reauth: requested tags are not permitted")
return rejectedTags
@ -1493,17 +1493,17 @@ func (s *State) processReauthTags(
// Note: UserID is preserved as "created by" tracking, consistent with SetNodeTags
if !wasTagged {
log.Info().
Uint64("node.id", uint64(node.ID)).
Str("node.name", node.Hostname).
Strs("new.tags", approvedTags).
Str("old.user", user.Name).
Uint64(zf.NodeID, uint64(node.ID)).
Str(zf.NodeName, node.Hostname).
Strs(zf.NewTags, approvedTags).
Str(zf.OldUser, user.Name).
Msg("Reauth: applying tags, transferring node to tagged-devices")
} else {
log.Info().
Uint64("node.id", uint64(node.ID)).
Str("node.name", node.Hostname).
Strs("old.tags", oldTags).
Strs("new.tags", approvedTags).
Uint64(zf.NodeID, uint64(node.ID)).
Str(zf.NodeName, node.Hostname).
Strs(zf.OldTags, oldTags).
Strs(zf.NewTags, approvedTags).
Msg("Reauth: updating tags on already-tagged node")
}
}
@ -1564,10 +1564,10 @@ func (s *State) HandleNodeFromAuthPath(
// Create logger with common fields for all auth operations
logger := log.With().
Str("registration_id", registrationID.String()).
Str("user.name", user.Name).
Str("machine.key", machineKey.ShortString()).
Str("method", registrationMethod).
Str(zf.RegistrationID, registrationID.String()).
Str(zf.UserName, user.Name).
Str(zf.MachineKey, machineKey.ShortString()).
Str(zf.Method, registrationMethod).
Logger()
// Common params for update operations
@ -1601,9 +1601,9 @@ func (s *State) HandleNodeFromAuthPath(
oldUser := existingNodeAnyUser.User()
logger.Info().
Str("existing.node.name", existingNodeAnyUser.Hostname()).
Uint64("existing.node.id", existingNodeAnyUser.ID().Uint64()).
Str("old.user", oldUser.Name()).
Str(zf.ExistingNodeName, existingNodeAnyUser.Hostname()).
Uint64(zf.ExistingNodeID, existingNodeAnyUser.ID().Uint64()).
Str(zf.OldUser, oldUser.Name()).
Msg("Creating new node for different user (same machine key exists for another user)")
finalNode, err = s.createNewNodeFromAuth(
@ -1740,16 +1740,16 @@ func (s *State) HandleNodeFromPreAuthKey(
// containers that run "tailscale up --authkey=KEY" on every restart.
log.Debug().
Caller().
Uint64("node.id", existingNodeSameUser.ID().Uint64()).
Str("node.name", existingNodeSameUser.Hostname()).
Str("machine.key", machineKey.ShortString()).
Str("node.key.existing", existingNodeSameUser.NodeKey().ShortString()).
Str("node.key.request", regReq.NodeKey.ShortString()).
Uint64("authkey.id", pak.ID).
Bool("authkey.used", pak.Used).
Bool("authkey.expired", pak.Expiration != nil && pak.Expiration.Before(time.Now())).
Bool("authkey.reusable", pak.Reusable).
Bool("nodekey.rotation", isNodeKeyRotation).
Uint64(zf.NodeID, existingNodeSameUser.ID().Uint64()).
Str(zf.NodeName, existingNodeSameUser.Hostname()).
Str(zf.MachineKey, machineKey.ShortString()).
Str(zf.NodeKeyExisting, existingNodeSameUser.NodeKey().ShortString()).
Str(zf.NodeKeyRequest, regReq.NodeKey.ShortString()).
Uint64(zf.AuthKeyID, pak.ID).
Bool(zf.AuthKeyUsed, pak.Used).
Bool(zf.AuthKeyExpired, pak.Expiration != nil && pak.Expiration.Before(time.Now())).
Bool(zf.AuthKeyReusable, pak.Reusable).
Bool(zf.NodeKeyRotation, isNodeKeyRotation).
Msg("Existing node re-registering with same NodeKey and auth key, skipping validation")
} else {
// New node or NodeKey rotation: require valid auth key.
@ -1780,10 +1780,10 @@ func (s *State) HandleNodeFromPreAuthKey(
log.Debug().
Caller().
Str("node.name", hostname).
Str("machine.key", machineKey.ShortString()).
Str("node.key", regReq.NodeKey.ShortString()).
Str("user.name", pakUsername()).
Str(zf.NodeName, hostname).
Str(zf.MachineKey, machineKey.ShortString()).
Str(zf.NodeKey, regReq.NodeKey.ShortString()).
Str(zf.UserName, pakUsername()).
Msg("Registering node with pre-auth key")
var finalNode types.NodeView
@ -1793,11 +1793,11 @@ func (s *State) HandleNodeFromPreAuthKey(
if existsSameUser && existingNodeSameUser.Valid() {
log.Trace().
Caller().
Str("node.name", existingNodeSameUser.Hostname()).
Uint64("node.id", existingNodeSameUser.ID().Uint64()).
Str("machine.key", machineKey.ShortString()).
Str("node.key", existingNodeSameUser.NodeKey().ShortString()).
Str("user.name", pakUsername()).
Str(zf.NodeName, existingNodeSameUser.Hostname()).
Uint64(zf.NodeID, existingNodeSameUser.ID().Uint64()).
Str(zf.MachineKey, machineKey.ShortString()).
Str(zf.NodeKey, existingNodeSameUser.NodeKey().ShortString()).
Str(zf.UserName, pakUsername()).
Msg("Node re-registering with existing machine key and user, updating in place")
// Update existing node - NodeStore first, then database
@ -1858,11 +1858,11 @@ func (s *State) HandleNodeFromPreAuthKey(
log.Trace().
Caller().
Str("node.name", updatedNodeView.Hostname()).
Uint64("node.id", updatedNodeView.ID().Uint64()).
Str("machine.key", machineKey.ShortString()).
Str("node.key", updatedNodeView.NodeKey().ShortString()).
Str("user.name", pakUsername()).
Str(zf.NodeName, updatedNodeView.Hostname()).
Uint64(zf.NodeID, updatedNodeView.ID().Uint64()).
Str(zf.MachineKey, machineKey.ShortString()).
Str(zf.NodeKey, updatedNodeView.NodeKey().ShortString()).
Str(zf.UserName, pakUsername()).
Msg("Node re-authorized")
finalNode = updatedNodeView
@ -1880,11 +1880,11 @@ func (s *State) HandleNodeFromPreAuthKey(
oldUser := existingNodeAnyUser.User()
log.Info().
Caller().
Str("existing.node.name", existingNodeAnyUser.Hostname()).
Uint64("existing.node.id", existingNodeAnyUser.ID().Uint64()).
Str("machine.key", machineKey.ShortString()).
Str("old.user", oldUser.Name()).
Str("new.user", pakUsername()).
Str(zf.ExistingNodeName, existingNodeAnyUser.Hostname()).
Uint64(zf.ExistingNodeID, existingNodeAnyUser.ID().Uint64()).
Str(zf.MachineKey, machineKey.ShortString()).
Str(zf.OldUser, oldUser.Name()).
Str(zf.NewUser, pakUsername()).
Msg("Creating new node for different user (same machine key exists for another user)")
}
@ -2026,10 +2026,10 @@ func (s *State) autoApproveNodes() ([]change.Change, error) {
approved, changed := policy.ApproveRoutesWithPolicy(s.polMan, nv, nv.ApprovedRoutes().AsSlice(), nv.AnnouncedRoutes())
if changed {
log.Debug().
Uint64("node.id", nv.ID().Uint64()).
Str("node.name", nv.Hostname()).
Strs("routes.approved.old", util.PrefixesToString(nv.ApprovedRoutes().AsSlice())).
Strs("routes.approved.new", util.PrefixesToString(approved)).
Uint64(zf.NodeID, nv.ID().Uint64()).
Str(zf.NodeName, nv.Hostname()).
Strs(zf.RoutesApprovedOld, util.PrefixesToString(nv.ApprovedRoutes().AsSlice())).
Strs(zf.RoutesApprovedNew, util.PrefixesToString(approved)).
Msg("Routes auto-approved by policy")
_, c, err := s.SetApprovedRoutes(nv.ID(), approved)
@ -2066,7 +2066,7 @@ func (s *State) autoApproveNodes() ([]change.Change, error) {
func (s *State) UpdateNodeFromMapRequest(id types.NodeID, req tailcfg.MapRequest) (change.Change, error) {
log.Trace().
Caller().
Uint64("node.id", id.Uint64()).
Uint64(zf.NodeID, id.Uint64()).
Interface("request", req).
Msg("Processing MapRequest for node")
@ -2136,11 +2136,11 @@ func (s *State) UpdateNodeFromMapRequest(id types.NodeID, req tailcfg.MapRequest
if routesChanged(currentNode.View(), hi) {
log.Debug().
Caller().
Uint64("node.id", id.Uint64()).
Strs("oldAnnouncedRoutes", util.PrefixesToString(currentNode.AnnouncedRoutes())).
Strs("newAnnouncedRoutes", util.PrefixesToString(hi.RoutableIPs)).
Strs("approvedRoutes", util.PrefixesToString(currentNode.ApprovedRoutes)).
Bool("routeChange", routeChange).
Uint64(zf.NodeID, id.Uint64()).
Strs(zf.OldAnnouncedRoutes, util.PrefixesToString(currentNode.AnnouncedRoutes())).
Strs(zf.NewAnnouncedRoutes, util.PrefixesToString(hi.RoutableIPs)).
Strs(zf.ApprovedRoutes, util.PrefixesToString(currentNode.ApprovedRoutes)).
Bool(zf.RouteChanged, routeChange).
Msg("announced routes changed but approved routes did not")
}
}
@ -2167,10 +2167,10 @@ func (s *State) UpdateNodeFromMapRequest(id types.NodeID, req tailcfg.MapRequest
// This fixes the bug where routes weren't properly cleared when
// auto-approvers were removed from the policy.
log.Info().
Uint64("node.id", id.Uint64()).
Strs("oldApprovedRoutes", util.PrefixesToString(currentNode.ApprovedRoutes)).
Strs("newApprovedRoutes", util.PrefixesToString(autoApprovedRoutes)).
Bool("routeChanged", routeChange).
Uint64(zf.NodeID, id.Uint64()).
Strs(zf.OldApprovedRoutes, util.PrefixesToString(currentNode.ApprovedRoutes)).
Strs(zf.NewApprovedRoutes, util.PrefixesToString(autoApprovedRoutes)).
Bool(zf.RouteChanged, routeChange).
Msg("applying route approval results")
}
}
@ -2182,8 +2182,8 @@ func (s *State) UpdateNodeFromMapRequest(id types.NodeID, req tailcfg.MapRequest
if routeChange {
log.Debug().
Uint64("node.id", id.Uint64()).
Strs("autoApprovedRoutes", util.PrefixesToString(autoApprovedRoutes)).
Uint64(zf.NodeID, id.Uint64()).
Strs(zf.AutoApprovedRoutes, util.PrefixesToString(autoApprovedRoutes)).
Msg("Persisting auto-approved routes from MapRequest")
// SetApprovedRoutes will update both database and PrimaryRoutes table
@ -2311,17 +2311,17 @@ func (s *State) maybeUpdateNodeRoutes(
log.Debug().
Caller().
Uint64("node.id", id.Uint64()).
Uint64(zf.NodeID, id.Uint64()).
Msg("updating routes because announced routes changed but approved routes did not")
// SetNodeRoutes sets the active/distributed routes using AllApprovedRoutes()
// which returns only the intersection of announced AND approved routes.
log.Debug().
Caller().
Uint64("node.id", id.Uint64()).
Strs("announcedRoutes", util.PrefixesToString(node.AnnouncedRoutes())).
Strs("approvedRoutes", util.PrefixesToString(node.ApprovedRoutes().AsSlice())).
Strs("allApprovedRoutes", util.PrefixesToString(node.AllApprovedRoutes())).
Uint64(zf.NodeID, id.Uint64()).
Strs(zf.RoutesAnnounced, util.PrefixesToString(node.AnnouncedRoutes())).
Strs(zf.ApprovedRoutes, util.PrefixesToString(node.ApprovedRoutes().AsSlice())).
Strs(zf.AllApprovedRoutes, util.PrefixesToString(node.AllApprovedRoutes())).
Msg("updating node routes for distribution")
return s.SetNodeRoutes(id, node.AllApprovedRoutes()...)