diff --git a/hscontrol/app.go b/hscontrol/app.go index aa011503..f0217172 100644 --- a/hscontrol/app.go +++ b/hscontrol/app.go @@ -147,12 +147,12 @@ func NewHeadscale(cfg *types.Config) (*Headscale, error) { policyChanged, err := app.state.DeleteNode(node) 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 } 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 diff --git a/hscontrol/auth.go b/hscontrol/auth.go index ac5968e3..d502cd31 100644 --- a/hscontrol/auth.go +++ b/hscontrol/auth.go @@ -42,8 +42,7 @@ func (h *Headscale) handleRegister( // This is a logout attempt (expiry in the past) if node, ok := h.state.GetNodeByNodeKey(req.NodeKey); ok { log.Debug(). - Uint64("node.id", node.ID().Uint64()). - Str("node.name", node.Hostname()). + EmbedObject(node). Bool("is_ephemeral", node.IsEphemeral()). Bool("has_authkey", node.AuthKey().Valid()). Msg("Found existing node for logout, calling handleLogout") @@ -155,8 +154,8 @@ func (h *Headscale) handleLogout( // force the client to re-authenticate. // TODO(kradalby): I wonder if this is a path we ever hit? if node.IsExpired() { - log.Trace().Str("node.name", node.Hostname()). - Uint64("node.id", node.ID().Uint64()). + log.Trace(). + EmbedObject(node). Interface("reg.req", req). Bool("unexpected", true). 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. if req.Expiry.Before(time.Now()) { log.Debug(). - Uint64("node.id", node.ID().Uint64()). - Str("node.name", node.Hostname()). + EmbedObject(node). Bool("is_ephemeral", node.IsEphemeral()). Bool("has_authkey", node.AuthKey().Valid()). Time("req.expiry", req.Expiry). @@ -191,8 +189,7 @@ func (h *Headscale) handleLogout( if node.IsEphemeral() { log.Info(). - Uint64("node.id", node.ID().Uint64()). - Str("node.name", node.Hostname()). + EmbedObject(node). Msg("Deleting ephemeral node during logout") c, err := h.state.DeleteNode(node) @@ -209,8 +206,7 @@ func (h *Headscale) handleLogout( } log.Debug(). - Uint64("node.id", node.ID().Uint64()). - Str("node.name", node.Hostname()). + EmbedObject(node). Msg("Node is not ephemeral, setting expiry instead of deleting") } @@ -397,8 +393,7 @@ func (h *Headscale) handleRegisterWithAuthKey( Caller(). Interface("reg.resp", resp). Interface("reg.req", req). - Str("node.name", node.Hostname()). - Uint64("node.id", node.ID().Uint64()). + EmbedObject(node). Msg("RegisterResponse") return resp, nil diff --git a/hscontrol/db/db.go b/hscontrol/db/db.go index a1429aa6..dcc9e78d 100644 --- a/hscontrol/db/db.go +++ b/hscontrol/db/db.go @@ -652,8 +652,7 @@ AND auth_key_id NOT IN ( if len(validatedTags) == 0 { if len(rejectedTags) > 0 { log.Debug(). - Uint64("node.id", uint64(node.ID)). - Str("node.name", node.Hostname). + EmbedObject(node). Strs("rejected_tags", rejectedTags). Msg("RequestTags rejected during migration (not authorized)") } @@ -676,8 +675,7 @@ AND auth_key_id NOT IN ( } log.Info(). - Uint64("node.id", uint64(node.ID)). - Str("node.name", node.Hostname). + EmbedObject(node). Strs("validated_tags", validatedTags). Strs("rejected_tags", rejectedTags). Strs("existing_tags", existingTags). diff --git a/hscontrol/db/ip.go b/hscontrol/db/ip.go index 972d8e72..c6a223bc 100644 --- a/hscontrol/db/ip.go +++ b/hscontrol/db/ip.go @@ -283,7 +283,7 @@ func (db *HSDatabase) BackfillNodeIPs(i *IPAllocator) ([]string, error) { } 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 // IPv4 prefix is set, but node ip is missing, alloc diff --git a/hscontrol/grpcv1.go b/hscontrol/grpcv1.go index a35a73af..b216e5e6 100644 --- a/hscontrol/grpcv1.go +++ b/hscontrol/grpcv1.go @@ -406,7 +406,7 @@ func (api headscaleV1APIServer) SetApprovedRoutes( log.Debug(). Caller(). - Uint64("node.id", node.ID().Uint64()). + EmbedObject(node). Strs("approvedRoutes", util.PrefixesToString(node.ApprovedRoutes().AsSlice())). Strs("primaryRoutes", util.PrefixesToString(primaryRoutes)). Strs("finalSubnetRoutes", proto.SubnetRoutes). diff --git a/hscontrol/mapper/mapper.go b/hscontrol/mapper/mapper.go index d7807784..a3b932d6 100644 --- a/hscontrol/mapper/mapper.go +++ b/hscontrol/mapper/mapper.go @@ -79,8 +79,7 @@ func generateUserProfiles( user := node.Owner() if !user.Valid() { log.Error(). - Uint64("node.id", node.ID().Uint64()). - Str("node.name", node.Hostname()). + EmbedObject(node). Msg("node has no valid owner, skipping user profile generation") return nil diff --git a/hscontrol/policy/policy.go b/hscontrol/policy/policy.go index 677cb854..9d9545f8 100644 --- a/hscontrol/policy/policy.go +++ b/hscontrol/policy/policy.go @@ -136,8 +136,7 @@ func ApproveRoutesWithPolicy(pm PolicyManager, nv types.NodeView, currentApprove if len(added) > 0 { log.Debug(). - Uint64("node.id", nv.ID().Uint64()). - Str("node.name", nv.Hostname()). + EmbedObject(nv). Strs("routes.added", util.PrefixesToString(added)). Strs("routes.kept", util.PrefixesToString(kept)). Int("routes.total", len(newApproved)). diff --git a/hscontrol/poll.go b/hscontrol/poll.go index 02275751..679dab69 100644 --- a/hscontrol/poll.go +++ b/hscontrol/poll.go @@ -132,7 +132,7 @@ func (m *mapSession) serve() { func (m *mapSession) serveLongPoll() { 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 defer func() { @@ -214,10 +214,11 @@ func (m *mapSession) serveLongPoll() { // 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 { 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 } - 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(connectChanges...) diff --git a/hscontrol/state/state.go b/hscontrol/state/state.go index 48d32766..e51d35aa 100644 --- a/hscontrol/state/state.go +++ b/hscontrol/state/state.go @@ -22,6 +22,7 @@ import ( "github.com/juanfont/headscale/hscontrol/types" "github.com/juanfont/headscale/hscontrol/types/change" "github.com/juanfont/headscale/hscontrol/util" + "github.com/juanfont/headscale/hscontrol/util/zlog/zf" "github.com/rs/zerolog" "github.com/rs/zerolog/log" "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()) if !exists { log.Warn(). - Uint64("node.id", node.ID().Uint64()). - Str("node.name", node.Hostname()). + EmbedObject(node). Bool("is_ephemeral", node.IsEphemeral()). 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)} - 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 // 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) } - 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 // 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 { // Log error but don't fail the disconnection - NodeStore is already updated // 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{} } @@ -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()) if changed { log.Debug(). - Uint64("node.id", nv.ID().Uint64()). - Str("node.name", nv.Hostname()). + EmbedObject(nv). Strs("routes.announced", util.PrefixesToString(nv.AnnouncedRoutes())). Strs("routes.approved.old", util.PrefixesToString(nv.ApprovedRoutes().AsSlice())). 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) if err != nil { log.Error(). - Uint64("node.id", nv.ID().Uint64()). - Str("node.name", nv.Hostname()). + EmbedObject(nv). Err(err). Msg("Failed to persist auto-approved routes") 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 } @@ -1139,14 +1137,12 @@ func (s *State) applyAuthNodeUpdate(params authNodeUpdateParams) (types.NodeView // Log the operation type if params.IsConvertFromTag { log.Info(). - Str("node.name", params.ExistingNode.Hostname()). - Uint64("node.id", params.ExistingNode.ID().Uint64()). + EmbedObject(params.ExistingNode). Strs("old.tags", params.ExistingNode.Tags().AsSlice()). Msg("Converting tagged node to user-owned node") } else { log.Info(). - Str("node.name", params.ExistingNode.Hostname()). - Uint64("node.id", params.ExistingNode.ID().Uint64()). + EmbedObject(params.ExistingNode). Interface("hostinfo", params.RegEntry.Node.Hostinfo). Msg("Updating existing node registration via reauth") } @@ -1258,15 +1254,11 @@ func (s *State) applyAuthNodeUpdate(params authNodeUpdateParams) (types.NodeView // Log completion if params.IsConvertFromTag { log.Trace(). - Str("node.name", updatedNodeView.Hostname()). - Uint64("node.id", updatedNodeView.ID().Uint64()). - Str("node.key", updatedNodeView.NodeKey().ShortString()). + EmbedObject(updatedNodeView). Msg("Tagged node converted to user-owned") } else { log.Trace(). - Str("node.name", updatedNodeView.Hostname()). - Uint64("node.id", updatedNodeView.ID().Uint64()). - Str("node.key", updatedNodeView.NodeKey().ShortString()). + EmbedObject(updatedNodeView). Msg("Node re-authorized") } diff --git a/hscontrol/state/tags.go b/hscontrol/state/tags.go index ef210425..56dff16e 100644 --- a/hscontrol/state/tags.go +++ b/hscontrol/state/tags.go @@ -47,8 +47,7 @@ func validateNodeOwnership(node *types.Node) error { func logTagOperation(existingNode types.NodeView, newTags []string) { if existingNode.IsTagged() { log.Info(). - Uint64("node.id", existingNode.ID().Uint64()). - Str("node.name", existingNode.Hostname()). + EmbedObject(existingNode). Strs("old.tags", existingNode.Tags().AsSlice()). Strs("new.tags", newTags). Msg("Updating tags on already-tagged node") @@ -59,8 +58,7 @@ func logTagOperation(existingNode types.NodeView, newTags []string) { } log.Info(). - Uint64("node.id", existingNode.ID().Uint64()). - Str("node.name", existingNode.Hostname()). + EmbedObject(existingNode). Uint("created.by.user", userID). Strs("new.tags", newTags). Msg("Converting user-owned node to tagged node")