From 1a6c6574517307beb1f4417993e2f6dfedce77d3 Mon Sep 17 00:00:00 2001 From: Nate Brown Date: Thu, 30 Mar 2023 15:07:31 -0500 Subject: [PATCH] Normalize logs (#837) --- LOGGING.md | 38 ++++++++++++++++++++++++ handshake_manager.go | 22 +++++++------- inside.go | 6 ++-- lighthouse.go | 2 +- outside.go | 6 ++-- relay_manager.go | 70 ++++++++++++++++++++++---------------------- 6 files changed, 91 insertions(+), 53 deletions(-) create mode 100644 LOGGING.md diff --git a/LOGGING.md b/LOGGING.md new file mode 100644 index 0000000..bd2fdef --- /dev/null +++ b/LOGGING.md @@ -0,0 +1,38 @@ +### Logging conventions + +A log message (the string/format passed to `Info`, `Error`, `Debug` etc, as well as their `Sprintf` counterparts) should +be a descriptive message about the event and may contain specific identifying characteristics. Regardless of the +level of detail in the message identifying characteristics should always be included via `WithField`, `WithFields` or +`WithError` + +If an error is being logged use `l.WithError(err)` so that there is better discoverability about the event as well +as the specific error condition. + +#### Common fields + +- `cert` - a `cert.NebulaCertificate` object, do not `.String()` this manually, `logrus` will marshal objects properly + for the formatter it is using. +- `fingerprint` - a single `NebeulaCertificate` hex encoded fingerprint +- `fingerprints` - an array of `NebulaCertificate` hex encoded fingerprints +- `fwPacket` - a FirewallPacket object +- `handshake` - an object containing: + - `stage` - the current stage counter + - `style` - noise handshake style `ix_psk0`, `xx`, etc +- `header` - a nebula header object +- `udpAddr` - a `net.UDPAddr` object +- `udpIp` - a udp ip address +- `vpnIp` - vpn ip of the host (remote or local) +- `relay` - the vpnIp of the relay host that is or should be handling the relay packet +- `relayFrom` - The vpnIp of the initial sender of the relayed packet +- `relayTo` - The vpnIp of the final destination of a relayed packet + +#### Example: + +``` +l.WithError(err). + WithField("vpnIp", IntIp(hostinfo.hostId)). + WithField("udpAddr", addr). + WithField("handshake", m{"stage": 1, "style": "ix"}). + WithField("cert", remoteCert). + Info("Invalid certificate from host") +``` \ No newline at end of file diff --git a/handshake_manager.go b/handshake_manager.go index a324852..e93cbee 100644 --- a/handshake_manager.go +++ b/handshake_manager.go @@ -203,7 +203,7 @@ func (c *HandshakeManager) handleOutbound(vpnIp iputil.VpnIp, f udp.EncWriter, l } if c.config.useRelays && len(hostinfo.remotes.relays) > 0 { - hostinfo.logger(c.l).WithField("relayIps", hostinfo.remotes.relays).Info("Attempt to relay through hosts") + hostinfo.logger(c.l).WithField("relays", hostinfo.remotes.relays).Info("Attempt to relay through hosts") // Send a RelayRequest to all known Relay IP's for _, relay := range hostinfo.remotes.relays { // Don't relay to myself, and don't relay through the host I'm trying to connect to @@ -212,7 +212,7 @@ func (c *HandshakeManager) handleOutbound(vpnIp iputil.VpnIp, f udp.EncWriter, l } relayHostInfo, err := c.mainHostMap.QueryVpnIp(*relay) if err != nil || relayHostInfo.remote == nil { - hostinfo.logger(c.l).WithError(err).WithField("relay", relay.String()).Info("Establish tunnel to relay target.") + hostinfo.logger(c.l).WithError(err).WithField("relay", relay.String()).Info("Establish tunnel to relay target") f.Handshake(*relay) continue } @@ -239,17 +239,17 @@ func (c *HandshakeManager) handleOutbound(vpnIp iputil.VpnIp, f udp.EncWriter, l } else { f.SendMessageToVpnIp(header.Control, 0, *relay, msg, make([]byte, 12), make([]byte, mtu)) c.l.WithFields(logrus.Fields{ - "relayFrom": iputil.VpnIp(c.lightHouse.myVpnIp), - "relayTarget": iputil.VpnIp(vpnIp), - "initiatorIdx": existingRelay.LocalIndex, - "vpnIp": *relay}). + "relayFrom": c.lightHouse.myVpnIp, + "relayTo": vpnIp, + "initiatorRelayIndex": existingRelay.LocalIndex, + "relay": *relay}). Info("send CreateRelayRequest") } default: hostinfo.logger(c.l). WithField("vpnIp", vpnIp). WithField("state", existingRelay.State). - WithField("relayVpnIp", relayHostInfo.vpnIp). + WithField("relay", relayHostInfo.vpnIp). Errorf("Relay unexpected state") } } else { @@ -274,10 +274,10 @@ func (c *HandshakeManager) handleOutbound(vpnIp iputil.VpnIp, f udp.EncWriter, l } else { f.SendMessageToVpnIp(header.Control, 0, *relay, msg, make([]byte, 12), make([]byte, mtu)) c.l.WithFields(logrus.Fields{ - "relayFrom": iputil.VpnIp(c.lightHouse.myVpnIp), - "relayTarget": iputil.VpnIp(vpnIp), - "initiatorIdx": idx, - "vpnIp": *relay}). + "relayFrom": c.lightHouse.myVpnIp, + "relayTo": vpnIp, + "initiatorRelayIndex": idx, + "relay": *relay}). Info("send CreateRelayRequest") } } diff --git a/inside.go b/inside.go index ddfaa20..21e2ab7 100644 --- a/inside.go +++ b/inside.go @@ -362,14 +362,14 @@ func (f *Interface) sendNoMetrics(t header.MessageType, st header.MessageSubType for _, relayIP := range hostinfo.relayState.CopyRelayIps() { relayHostInfo, err := f.hostMap.QueryVpnIp(relayIP) if err != nil { - hostinfo.logger(f.l).WithField("relayIp", relayIP).WithError(err).Info("sendNoMetrics failed to find HostInfo") + hostinfo.logger(f.l).WithField("relay", relayIP).WithError(err).Info("sendNoMetrics failed to find HostInfo") continue } relay, ok := relayHostInfo.relayState.QueryRelayForByIp(hostinfo.vpnIp) if !ok { hostinfo.logger(f.l). - WithField("relayIp", relayHostInfo.vpnIp). - WithField("relayTarget", hostinfo.vpnIp). + WithField("relay", relayHostInfo.vpnIp). + WithField("relayTo", hostinfo.vpnIp). Info("sendNoMetrics relay missing object for target") continue } diff --git a/lighthouse.go b/lighthouse.go index 402caff..5b34a3e 100644 --- a/lighthouse.go +++ b/lighthouse.go @@ -299,7 +299,7 @@ func (lh *LightHouse) reload(c *config.C, initial bool) error { case false: relaysForMe := []iputil.VpnIp{} for _, v := range c.GetStringSlice("relay.relays", nil) { - lh.l.WithField("RelayIP", v).Info("Read relay from config") + lh.l.WithField("relay", v).Info("Read relay from config") configRIP := net.ParseIP(v) if configRIP != nil { diff --git a/outside.go b/outside.go index ef547dc..9d51786 100644 --- a/outside.go +++ b/outside.go @@ -104,13 +104,13 @@ func (f *Interface) readOutsidePackets(addr *udp.Addr, via interface{}, out []by // Find the target HostInfo relay object targetHI, err := f.hostMap.QueryVpnIp(relay.PeerIp) if err != nil { - hostinfo.logger(f.l).WithField("peerIp", relay.PeerIp).WithError(err).Info("Failed to find target host info by ip") + hostinfo.logger(f.l).WithField("relayTo", relay.PeerIp).WithError(err).Info("Failed to find target host info by ip") return } // find the target Relay info object targetRelay, ok := targetHI.relayState.QueryRelayForByIp(hostinfo.vpnIp) if !ok { - hostinfo.logger(f.l).WithFields(logrus.Fields{"peerIp": relay.PeerIp, "vpnIp": hostinfo.vpnIp}).Info("Failed to find relay in hostinfo") + hostinfo.logger(f.l).WithFields(logrus.Fields{"relayTo": relay.PeerIp, "relayFrom": hostinfo.vpnIp}).Info("Failed to find relay in hostinfo") return } @@ -126,7 +126,7 @@ func (f *Interface) readOutsidePackets(addr *udp.Addr, via interface{}, out []by hostinfo.logger(f.l).Error("Unexpected Relay Type of Terminal") } } else { - hostinfo.logger(f.l).WithFields(logrus.Fields{"peerIp": relay.PeerIp, "vpnIp": hostinfo.vpnIp, "targetRelayState": targetRelay.State}).Info("Unexpected target relay state") + hostinfo.logger(f.l).WithFields(logrus.Fields{"relayTo": relay.PeerIp, "relayFrom": hostinfo.vpnIp, "targetRelayState": targetRelay.State}).Info("Unexpected target relay state") return } } diff --git a/relay_manager.go b/relay_manager.go index 3b4c904..bf75708 100644 --- a/relay_manager.go +++ b/relay_manager.go @@ -90,7 +90,7 @@ func AddRelay(l *logrus.Logger, relayHostInfo *HostInfo, hm *HostMap, vpnIp iput func (rm *relayManager) EstablishRelay(relayHostInfo *HostInfo, m *NebulaControl) (*Relay, error) { relay, ok := relayHostInfo.relayState.CompleteRelayByIdx(m.InitiatorRelayIndex, m.ResponderRelayIndex) if !ok { - rm.l.WithFields(logrus.Fields{"relayHostInfo": relayHostInfo.vpnIp, + rm.l.WithFields(logrus.Fields{"relay": relayHostInfo.vpnIp, "initiatorRelayIndex": m.InitiatorRelayIndex, "relayFrom": m.RelayFromIp, "relayTo": m.RelayToIp}).Info("relayManager failed to update relay") @@ -113,17 +113,17 @@ func (rm *relayManager) HandleControlMsg(h *HostInfo, m *NebulaControl, f *Inter func (rm *relayManager) handleCreateRelayResponse(h *HostInfo, f *Interface, m *NebulaControl) { rm.l.WithFields(logrus.Fields{ - "relayFrom": iputil.VpnIp(m.RelayFromIp), - "relayTarget": iputil.VpnIp(m.RelayToIp), - "initiatorIdx": m.InitiatorRelayIndex, - "responderIdx": m.ResponderRelayIndex, - "vpnIp": h.vpnIp}). + "relayFrom": iputil.VpnIp(m.RelayFromIp), + "relayTo": iputil.VpnIp(m.RelayToIp), + "initiatorRelayIndex": m.InitiatorRelayIndex, + "responderRelayIndex": m.ResponderRelayIndex, + "vpnIp": h.vpnIp}). Info("handleCreateRelayResponse") target := iputil.VpnIp(m.RelayToIp) relay, err := rm.EstablishRelay(h, m) if err != nil { - rm.l.WithError(err).WithField("target", target.String()).Error("Failed to update relay for target") + rm.l.WithError(err).Error("Failed to update relay for relayTo") return } // Do I need to complete the relays now? @@ -133,12 +133,12 @@ func (rm *relayManager) handleCreateRelayResponse(h *HostInfo, f *Interface, m * // I'm the middle man. Let the initiator know that the I've established the relay they requested. peerHostInfo, err := rm.hostmap.QueryVpnIp(relay.PeerIp) if err != nil { - rm.l.WithError(err).WithField("relayPeerIp", relay.PeerIp).Error("Can't find a HostInfo for peer IP") + rm.l.WithError(err).WithField("relayTo", relay.PeerIp).Error("Can't find a HostInfo for peer") return } peerRelay, ok := peerHostInfo.relayState.QueryRelayForByIp(target) if !ok { - rm.l.WithField("peerIp", peerHostInfo.vpnIp).WithField("target", target.String()).Error("peerRelay does not have Relay state for target IP", peerHostInfo.vpnIp.String(), target.String()) + rm.l.WithField("relayTo", peerHostInfo.vpnIp).Error("peerRelay does not have Relay state for relayTo") return } peerRelay.State = Established @@ -156,11 +156,11 @@ func (rm *relayManager) handleCreateRelayResponse(h *HostInfo, f *Interface, m * } else { f.SendMessageToVpnIp(header.Control, 0, peerHostInfo.vpnIp, msg, make([]byte, 12), make([]byte, mtu)) rm.l.WithFields(logrus.Fields{ - "relayFrom": iputil.VpnIp(resp.RelayFromIp), - "relayTarget": iputil.VpnIp(resp.RelayToIp), - "initiatorIdx": resp.InitiatorRelayIndex, - "responderIdx": resp.ResponderRelayIndex, - "vpnIp": peerHostInfo.vpnIp}). + "relayFrom": iputil.VpnIp(resp.RelayFromIp), + "relayTo": iputil.VpnIp(resp.RelayToIp), + "initiatorRelayIndex": resp.InitiatorRelayIndex, + "responderRelayIndex": resp.ResponderRelayIndex, + "vpnIp": peerHostInfo.vpnIp}). Info("send CreateRelayResponse") } } @@ -171,10 +171,10 @@ func (rm *relayManager) handleCreateRelayRequest(h *HostInfo, f *Interface, m *N target := iputil.VpnIp(m.RelayToIp) logMsg := rm.l.WithFields(logrus.Fields{ - "relayFrom": from, - "relayTarget": target, - "initiatorIdx": m.InitiatorRelayIndex, - "vpnIp": h.vpnIp}) + "relayFrom": from, + "relayTo": target, + "initiatorRelayIndex": m.InitiatorRelayIndex, + "vpnIp": h.vpnIp}) logMsg.Info("handleCreateRelayRequest") // Is the target of the relay me? @@ -193,7 +193,7 @@ func (rm *relayManager) handleCreateRelayRequest(h *HostInfo, f *Interface, m *N // We got a brand new Relay request, because its index is different than what we saw before. // This should never happen. The peer should never change an index, once created. logMsg.WithFields(logrus.Fields{ - "existingRemoteIdx": existingRelay.RemoteIndex}).Error("Existing relay mismatch with CreateRelayRequest") + "existingRemoteIndex": existingRelay.RemoteIndex}).Error("Existing relay mismatch with CreateRelayRequest") return } } @@ -225,11 +225,11 @@ func (rm *relayManager) handleCreateRelayRequest(h *HostInfo, f *Interface, m *N } else { f.SendMessageToVpnIp(header.Control, 0, h.vpnIp, msg, make([]byte, 12), make([]byte, mtu)) rm.l.WithFields(logrus.Fields{ - "relayFrom": iputil.VpnIp(resp.RelayFromIp), - "relayTarget": iputil.VpnIp(resp.RelayToIp), - "initiatorIdx": resp.InitiatorRelayIndex, - "responderIdx": resp.ResponderRelayIndex, - "vpnIp": h.vpnIp}). + "relayFrom": iputil.VpnIp(resp.RelayFromIp), + "relayTo": iputil.VpnIp(resp.RelayToIp), + "initiatorRelayIndex": resp.InitiatorRelayIndex, + "responderRelayIndex": resp.ResponderRelayIndex, + "vpnIp": h.vpnIp}). Info("send CreateRelayResponse") } return @@ -280,11 +280,11 @@ func (rm *relayManager) handleCreateRelayRequest(h *HostInfo, f *Interface, m *N } else { f.SendMessageToVpnIp(header.Control, 0, target, msg, make([]byte, 12), make([]byte, mtu)) rm.l.WithFields(logrus.Fields{ - "relayFrom": iputil.VpnIp(req.RelayFromIp), - "relayTarget": iputil.VpnIp(req.RelayToIp), - "initiatorIdx": req.InitiatorRelayIndex, - "responderIdx": req.ResponderRelayIndex, - "vpnIp": target}). + "relayFrom": iputil.VpnIp(req.RelayFromIp), + "relayTo": iputil.VpnIp(req.RelayToIp), + "initiatorRelayIndex": req.InitiatorRelayIndex, + "responderRelayIndex": req.ResponderRelayIndex, + "vpnIp": target}). Info("send CreateRelayRequest") } } @@ -309,7 +309,7 @@ func (rm *relayManager) handleCreateRelayRequest(h *HostInfo, f *Interface, m *N // We got a brand new Relay request, because its index is different than what we saw before. // This should never happen. The peer should never change an index, once created. logMsg.WithFields(logrus.Fields{ - "existingRemoteIdx": relay.RemoteIndex}).Error("Existing relay mismatch with CreateRelayRequest") + "existingRemoteIndex": relay.RemoteIndex}).Error("Existing relay mismatch with CreateRelayRequest") return } resp := NebulaControl{ @@ -326,11 +326,11 @@ func (rm *relayManager) handleCreateRelayRequest(h *HostInfo, f *Interface, m *N } else { f.SendMessageToVpnIp(header.Control, 0, h.vpnIp, msg, make([]byte, 12), make([]byte, mtu)) rm.l.WithFields(logrus.Fields{ - "relayFrom": iputil.VpnIp(resp.RelayFromIp), - "relayTarget": iputil.VpnIp(resp.RelayToIp), - "initiatorIdx": resp.InitiatorRelayIndex, - "responderIdx": resp.ResponderRelayIndex, - "vpnIp": h.vpnIp}). + "relayFrom": iputil.VpnIp(resp.RelayFromIp), + "relayTo": iputil.VpnIp(resp.RelayToIp), + "initiatorRelayIndex": resp.InitiatorRelayIndex, + "responderRelayIndex": resp.ResponderRelayIndex, + "vpnIp": h.vpnIp}). Info("send CreateRelayResponse") }