hscontrol: use EmbedObject for node logging

Replace manual Uint64("node.id")/Str("node.name") field patterns with
EmbedObject(node) which automatically includes all standard node fields
(id, name, machine key, node key, online status, tags, user).

This reduces code repetition and ensures consistent logging across:
- state.go: Connect/Disconnect, persistNodeToDB, AutoApproveRoutes
- auth.go: handleLogout, handleRegisterWithAuthKey
This commit is contained in:
Kristoffer Dalby
2026-02-05 09:44:23 +00:00
parent b5090a01ec
commit 91730e2a1d
10 changed files with 33 additions and 51 deletions

View File

@@ -147,12 +147,12 @@ func NewHeadscale(cfg *types.Config) (*Headscale, error) {
policyChanged, err := app.state.DeleteNode(node) policyChanged, err := app.state.DeleteNode(node)
if err != nil { if err != nil {
log.Error().Err(err).Uint64("node.id", ni.Uint64()).Str("node.name", node.Hostname()).Msg("Ephemeral node deletion failed") log.Error().Err(err).EmbedObject(node).Msg("Ephemeral node deletion failed")
return return
} }
app.Change(policyChanged) app.Change(policyChanged)
log.Debug().Caller().Uint64("node.id", ni.Uint64()).Str("node.name", node.Hostname()).Msg("Ephemeral node deleted because garbage collection timeout reached") log.Debug().Caller().EmbedObject(node).Msg("Ephemeral node deleted because garbage collection timeout reached")
}) })
app.ephemeralGC = ephemeralGC app.ephemeralGC = ephemeralGC

View File

@@ -42,8 +42,7 @@ func (h *Headscale) handleRegister(
// This is a logout attempt (expiry in the past) // This is a logout attempt (expiry in the past)
if node, ok := h.state.GetNodeByNodeKey(req.NodeKey); ok { if node, ok := h.state.GetNodeByNodeKey(req.NodeKey); ok {
log.Debug(). log.Debug().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Str("node.name", node.Hostname()).
Bool("is_ephemeral", node.IsEphemeral()). Bool("is_ephemeral", node.IsEphemeral()).
Bool("has_authkey", node.AuthKey().Valid()). Bool("has_authkey", node.AuthKey().Valid()).
Msg("Found existing node for logout, calling handleLogout") Msg("Found existing node for logout, calling handleLogout")
@@ -155,8 +154,8 @@ func (h *Headscale) handleLogout(
// force the client to re-authenticate. // force the client to re-authenticate.
// TODO(kradalby): I wonder if this is a path we ever hit? // TODO(kradalby): I wonder if this is a path we ever hit?
if node.IsExpired() { if node.IsExpired() {
log.Trace().Str("node.name", node.Hostname()). log.Trace().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Interface("reg.req", req). Interface("reg.req", req).
Bool("unexpected", true). Bool("unexpected", true).
Msg("Node key expired, forcing re-authentication") Msg("Node key expired, forcing re-authentication")
@@ -182,8 +181,7 @@ func (h *Headscale) handleLogout(
// Zero expiry is handled in handleRegister() before calling this function. // Zero expiry is handled in handleRegister() before calling this function.
if req.Expiry.Before(time.Now()) { if req.Expiry.Before(time.Now()) {
log.Debug(). log.Debug().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Str("node.name", node.Hostname()).
Bool("is_ephemeral", node.IsEphemeral()). Bool("is_ephemeral", node.IsEphemeral()).
Bool("has_authkey", node.AuthKey().Valid()). Bool("has_authkey", node.AuthKey().Valid()).
Time("req.expiry", req.Expiry). Time("req.expiry", req.Expiry).
@@ -191,8 +189,7 @@ func (h *Headscale) handleLogout(
if node.IsEphemeral() { if node.IsEphemeral() {
log.Info(). log.Info().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Str("node.name", node.Hostname()).
Msg("Deleting ephemeral node during logout") Msg("Deleting ephemeral node during logout")
c, err := h.state.DeleteNode(node) c, err := h.state.DeleteNode(node)
@@ -209,8 +206,7 @@ func (h *Headscale) handleLogout(
} }
log.Debug(). log.Debug().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Str("node.name", node.Hostname()).
Msg("Node is not ephemeral, setting expiry instead of deleting") Msg("Node is not ephemeral, setting expiry instead of deleting")
} }
@@ -397,8 +393,7 @@ func (h *Headscale) handleRegisterWithAuthKey(
Caller(). Caller().
Interface("reg.resp", resp). Interface("reg.resp", resp).
Interface("reg.req", req). Interface("reg.req", req).
Str("node.name", node.Hostname()). EmbedObject(node).
Uint64("node.id", node.ID().Uint64()).
Msg("RegisterResponse") Msg("RegisterResponse")
return resp, nil return resp, nil

View File

@@ -652,8 +652,7 @@ AND auth_key_id NOT IN (
if len(validatedTags) == 0 { if len(validatedTags) == 0 {
if len(rejectedTags) > 0 { if len(rejectedTags) > 0 {
log.Debug(). log.Debug().
Uint64("node.id", uint64(node.ID)). EmbedObject(node).
Str("node.name", node.Hostname).
Strs("rejected_tags", rejectedTags). Strs("rejected_tags", rejectedTags).
Msg("RequestTags rejected during migration (not authorized)") Msg("RequestTags rejected during migration (not authorized)")
} }
@@ -676,8 +675,7 @@ AND auth_key_id NOT IN (
} }
log.Info(). log.Info().
Uint64("node.id", uint64(node.ID)). EmbedObject(node).
Str("node.name", node.Hostname).
Strs("validated_tags", validatedTags). Strs("validated_tags", validatedTags).
Strs("rejected_tags", rejectedTags). Strs("rejected_tags", rejectedTags).
Strs("existing_tags", existingTags). Strs("existing_tags", existingTags).

View File

@@ -283,7 +283,7 @@ func (db *HSDatabase) BackfillNodeIPs(i *IPAllocator) ([]string, error) {
} }
for _, node := range nodes { for _, node := range nodes {
log.Trace().Caller().Uint64("node.id", node.ID.Uint64()).Str("node.name", node.Hostname).Msg("IP backfill check started because node found in database") log.Trace().Caller().EmbedObject(node).Msg("IP backfill check started because node found in database")
changed := false changed := false
// IPv4 prefix is set, but node ip is missing, alloc // IPv4 prefix is set, but node ip is missing, alloc

View File

@@ -406,7 +406,7 @@ func (api headscaleV1APIServer) SetApprovedRoutes(
log.Debug(). log.Debug().
Caller(). Caller().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Strs("approvedRoutes", util.PrefixesToString(node.ApprovedRoutes().AsSlice())). Strs("approvedRoutes", util.PrefixesToString(node.ApprovedRoutes().AsSlice())).
Strs("primaryRoutes", util.PrefixesToString(primaryRoutes)). Strs("primaryRoutes", util.PrefixesToString(primaryRoutes)).
Strs("finalSubnetRoutes", proto.SubnetRoutes). Strs("finalSubnetRoutes", proto.SubnetRoutes).

View File

@@ -79,8 +79,7 @@ func generateUserProfiles(
user := node.Owner() user := node.Owner()
if !user.Valid() { if !user.Valid() {
log.Error(). log.Error().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Str("node.name", node.Hostname()).
Msg("node has no valid owner, skipping user profile generation") Msg("node has no valid owner, skipping user profile generation")
return nil return nil

View File

@@ -136,8 +136,7 @@ func ApproveRoutesWithPolicy(pm PolicyManager, nv types.NodeView, currentApprove
if len(added) > 0 { if len(added) > 0 {
log.Debug(). log.Debug().
Uint64("node.id", nv.ID().Uint64()). EmbedObject(nv).
Str("node.name", nv.Hostname()).
Strs("routes.added", util.PrefixesToString(added)). Strs("routes.added", util.PrefixesToString(added)).
Strs("routes.kept", util.PrefixesToString(kept)). Strs("routes.kept", util.PrefixesToString(kept)).
Int("routes.total", len(newApproved)). Int("routes.total", len(newApproved)).

View File

@@ -132,7 +132,7 @@ func (m *mapSession) serve() {
func (m *mapSession) serveLongPoll() { func (m *mapSession) serveLongPoll() {
m.beforeServeLongPoll() m.beforeServeLongPoll()
log.Trace().Caller().Uint64("node.id", m.node.ID.Uint64()).Str("node.name", m.node.Hostname).Msg("Long poll session started because client connected") log.Trace().Caller().EmbedObject(m.node).Msg("Long poll session started because client connected")
// Clean up the session when the client disconnects // Clean up the session when the client disconnects
defer func() { defer func() {
@@ -214,10 +214,11 @@ func (m *mapSession) serveLongPoll() {
// time between the node connecting and the batcher being ready. // time between the node connecting and the batcher being ready.
if err := m.h.mapBatcher.AddNode(m.node.ID, m.ch, m.capVer); err != nil { if err := m.h.mapBatcher.AddNode(m.node.ID, m.ch, m.capVer); err != nil {
m.errf(err, "failed to add node to batcher") m.errf(err, "failed to add node to batcher")
log.Error().Uint64("node.id", m.node.ID.Uint64()).Str("node.name", m.node.Hostname).Err(err).Msg("AddNode failed in poll session") log.Error().EmbedObject(m.node).Err(err).Msg("AddNode failed in poll session")
return return
} }
log.Debug().Caller().Uint64("node.id", m.node.ID.Uint64()).Str("node.name", m.node.Hostname).Msg("AddNode succeeded in poll session because node added to batcher")
log.Debug().Caller().EmbedObject(m.node).Msg("AddNode succeeded in poll session because node added to batcher")
m.h.Change(mapReqChange) m.h.Change(mapReqChange)
m.h.Change(connectChanges...) m.h.Change(connectChanges...)

View File

@@ -22,6 +22,7 @@ import (
"github.com/juanfont/headscale/hscontrol/types" "github.com/juanfont/headscale/hscontrol/types"
"github.com/juanfont/headscale/hscontrol/types/change" "github.com/juanfont/headscale/hscontrol/types/change"
"github.com/juanfont/headscale/hscontrol/util" "github.com/juanfont/headscale/hscontrol/util"
"github.com/juanfont/headscale/hscontrol/util/zlog/zf"
"github.com/rs/zerolog" "github.com/rs/zerolog"
"github.com/rs/zerolog/log" "github.com/rs/zerolog/log"
"golang.org/x/sync/errgroup" "golang.org/x/sync/errgroup"
@@ -397,8 +398,7 @@ func (s *State) persistNodeToDB(node types.NodeView) (types.NodeView, change.Cha
_, exists := s.nodeStore.GetNode(node.ID()) _, exists := s.nodeStore.GetNode(node.ID())
if !exists { if !exists {
log.Warn(). log.Warn().
Uint64("node.id", node.ID().Uint64()). EmbedObject(node).
Str("node.name", node.Hostname()).
Bool("is_ephemeral", node.IsEphemeral()). Bool("is_ephemeral", node.IsEphemeral()).
Msg("Node no longer exists in NodeStore, skipping database persist to prevent race condition") Msg("Node no longer exists in NodeStore, skipping database persist to prevent race condition")
@@ -487,7 +487,7 @@ func (s *State) Connect(id types.NodeID) []change.Change {
c := []change.Change{change.NodeOnlineFor(node)} c := []change.Change{change.NodeOnlineFor(node)}
log.Info().Uint64("node.id", id.Uint64()).Str("node.name", node.Hostname()).Msg("Node connected") log.Info().EmbedObject(node).Msg("Node connected")
// Use the node's current routes for primary route update // Use the node's current routes for primary route update
// AllApprovedRoutes() returns only the intersection of announced AND approved routes // AllApprovedRoutes() returns only the intersection of announced AND approved routes
@@ -515,7 +515,7 @@ func (s *State) Disconnect(id types.NodeID) ([]change.Change, error) {
return nil, fmt.Errorf("node not found: %d", id) return nil, fmt.Errorf("node not found: %d", id)
} }
log.Info().Uint64("node.id", id.Uint64()).Str("node.name", node.Hostname()).Msg("Node disconnected") log.Info().EmbedObject(node).Msg("Node disconnected")
// Special error handling for disconnect - we log errors but continue // Special error handling for disconnect - we log errors but continue
// because NodeStore is already updated and we need to notify peers // because NodeStore is already updated and we need to notify peers
@@ -523,7 +523,7 @@ func (s *State) Disconnect(id types.NodeID) ([]change.Change, error) {
if err != nil { if err != nil {
// Log error but don't fail the disconnection - NodeStore is already updated // Log error but don't fail the disconnection - NodeStore is already updated
// and we need to send change notifications to peers // and we need to send change notifications to peers
log.Error().Err(err).Uint64("node.id", id.Uint64()).Str("node.name", node.Hostname()).Msg("Failed to update last seen in database") log.Error().Err(err).EmbedObject(node).Msg("Failed to update last seen in database")
c = change.Change{} c = change.Change{}
} }
@@ -887,8 +887,7 @@ func (s *State) AutoApproveRoutes(nv types.NodeView) (change.Change, error) {
approved, changed := policy.ApproveRoutesWithPolicy(s.polMan, nv, nv.ApprovedRoutes().AsSlice(), nv.AnnouncedRoutes()) approved, changed := policy.ApproveRoutesWithPolicy(s.polMan, nv, nv.ApprovedRoutes().AsSlice(), nv.AnnouncedRoutes())
if changed { if changed {
log.Debug(). log.Debug().
Uint64("node.id", nv.ID().Uint64()). EmbedObject(nv).
Str("node.name", nv.Hostname()).
Strs("routes.announced", util.PrefixesToString(nv.AnnouncedRoutes())). Strs("routes.announced", util.PrefixesToString(nv.AnnouncedRoutes())).
Strs("routes.approved.old", util.PrefixesToString(nv.ApprovedRoutes().AsSlice())). Strs("routes.approved.old", util.PrefixesToString(nv.ApprovedRoutes().AsSlice())).
Strs("routes.approved.new", util.PrefixesToString(approved)). Strs("routes.approved.new", util.PrefixesToString(approved)).
@@ -899,15 +898,14 @@ func (s *State) AutoApproveRoutes(nv types.NodeView) (change.Change, error) {
_, c, err := s.SetApprovedRoutes(nv.ID(), approved) _, c, err := s.SetApprovedRoutes(nv.ID(), approved)
if err != nil { if err != nil {
log.Error(). log.Error().
Uint64("node.id", nv.ID().Uint64()). EmbedObject(nv).
Str("node.name", nv.Hostname()).
Err(err). Err(err).
Msg("Failed to persist auto-approved routes") Msg("Failed to persist auto-approved routes")
return change.Change{}, err return change.Change{}, err
} }
log.Info().Uint64("node.id", nv.ID().Uint64()).Str("node.name", nv.Hostname()).Strs("routes.approved", util.PrefixesToString(approved)).Msg("Routes approved") log.Info().EmbedObject(nv).Strs(zf.RoutesApproved, util.PrefixesToString(approved)).Msg("Routes approved")
return c, nil return c, nil
} }
@@ -1139,14 +1137,12 @@ func (s *State) applyAuthNodeUpdate(params authNodeUpdateParams) (types.NodeView
// Log the operation type // Log the operation type
if params.IsConvertFromTag { if params.IsConvertFromTag {
log.Info(). log.Info().
Str("node.name", params.ExistingNode.Hostname()). EmbedObject(params.ExistingNode).
Uint64("node.id", params.ExistingNode.ID().Uint64()).
Strs("old.tags", params.ExistingNode.Tags().AsSlice()). Strs("old.tags", params.ExistingNode.Tags().AsSlice()).
Msg("Converting tagged node to user-owned node") Msg("Converting tagged node to user-owned node")
} else { } else {
log.Info(). log.Info().
Str("node.name", params.ExistingNode.Hostname()). EmbedObject(params.ExistingNode).
Uint64("node.id", params.ExistingNode.ID().Uint64()).
Interface("hostinfo", params.RegEntry.Node.Hostinfo). Interface("hostinfo", params.RegEntry.Node.Hostinfo).
Msg("Updating existing node registration via reauth") Msg("Updating existing node registration via reauth")
} }
@@ -1258,15 +1254,11 @@ func (s *State) applyAuthNodeUpdate(params authNodeUpdateParams) (types.NodeView
// Log completion // Log completion
if params.IsConvertFromTag { if params.IsConvertFromTag {
log.Trace(). log.Trace().
Str("node.name", updatedNodeView.Hostname()). EmbedObject(updatedNodeView).
Uint64("node.id", updatedNodeView.ID().Uint64()).
Str("node.key", updatedNodeView.NodeKey().ShortString()).
Msg("Tagged node converted to user-owned") Msg("Tagged node converted to user-owned")
} else { } else {
log.Trace(). log.Trace().
Str("node.name", updatedNodeView.Hostname()). EmbedObject(updatedNodeView).
Uint64("node.id", updatedNodeView.ID().Uint64()).
Str("node.key", updatedNodeView.NodeKey().ShortString()).
Msg("Node re-authorized") Msg("Node re-authorized")
} }

View File

@@ -47,8 +47,7 @@ func validateNodeOwnership(node *types.Node) error {
func logTagOperation(existingNode types.NodeView, newTags []string) { func logTagOperation(existingNode types.NodeView, newTags []string) {
if existingNode.IsTagged() { if existingNode.IsTagged() {
log.Info(). log.Info().
Uint64("node.id", existingNode.ID().Uint64()). EmbedObject(existingNode).
Str("node.name", existingNode.Hostname()).
Strs("old.tags", existingNode.Tags().AsSlice()). Strs("old.tags", existingNode.Tags().AsSlice()).
Strs("new.tags", newTags). Strs("new.tags", newTags).
Msg("Updating tags on already-tagged node") Msg("Updating tags on already-tagged node")
@@ -59,8 +58,7 @@ func logTagOperation(existingNode types.NodeView, newTags []string) {
} }
log.Info(). log.Info().
Uint64("node.id", existingNode.ID().Uint64()). EmbedObject(existingNode).
Str("node.name", existingNode.Hostname()).
Uint("created.by.user", userID). Uint("created.by.user", userID).
Strs("new.tags", newTags). Strs("new.tags", newTags).
Msg("Converting user-owned node to tagged node") Msg("Converting user-owned node to tagged node")