diff --git a/hscontrol/db/node.go b/hscontrol/db/node.go index bf407bb4..a9101938 100644 --- a/hscontrol/db/node.go +++ b/hscontrol/db/node.go @@ -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 { diff --git a/hscontrol/state/state.go b/hscontrol/state/state.go index e51d35aa..0d91a24a 100644 --- a/hscontrol/state/state.go +++ b/hscontrol/state/state.go @@ -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()...)