Normalize logs (#837)

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")
+```

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")
 					}
 				}

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
 			}

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 {

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
 				}
 			}

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")
 				}