log `certName` alongside `vpnIp` (#200)

This change adds a new helper, `(*HostInfo).logger()`, that starts a new
logrus.Entry with `vpnIp` and `certName`. We don't use the helper inside
of handshake_ix though since the certificate has not been attached to
the HostInfo yet.

Fixes: #84

connection_manager.go

@@ -182,7 +182,7 @@ func (n *connectionManager) HandleMonitorTick(now time.Time) {
 			continue
 		}
 
-		l.WithField("vpnIp", IntIp(vpnIP)).
+		hostinfo.logger().
 			WithField("tunnelCheck", m{"state": "testing", "method": "active"}).
 			Debug("Tunnel status")
 
@@ -191,7 +191,7 @@ func (n *connectionManager) HandleMonitorTick(now time.Time) {
 			n.intf.SendMessageToVpnIp(test, testRequest, vpnIP, []byte(""), make([]byte, 12, 12), make([]byte, mtu))
 
 		} else {
-			l.Debugf("Hostinfo sadness: %s", IntIp(vpnIP))
+			hostinfo.logger().Debugf("Hostinfo sadness: %s", IntIp(vpnIP))
 		}
 		n.AddPendingDeletion(vpnIP)
 	}
@@ -233,7 +233,7 @@ func (n *connectionManager) HandleDeletionTick(now time.Time) {
 			if hostinfo.ConnectionState != nil && hostinfo.ConnectionState.peerCert != nil {
 				cn = hostinfo.ConnectionState.peerCert.Details.Name
 			}
-			l.WithField("vpnIp", IntIp(vpnIP)).
+			hostinfo.logger().
 				WithField("tunnelCheck", m{"state": "dead", "method": "active"}).
 				WithField("certName", cn).
 				Info("Tunnel status")

handshake_ix.go

@@ -125,10 +125,12 @@ func ixHandshakeStage1(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 			return true
 		}
 		vpnIP := ip2int(remoteCert.Details.Ips[0].IP)
+		certName := remoteCert.Details.Name
 
 		myIndex, err := generateIndex()
 		if err != nil {
 			l.WithError(err).WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", addr).
+				WithField("certName", certName).
 				WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).Error("Failed to generate index")
 			return true
 		}
@@ -136,11 +138,13 @@ func ixHandshakeStage1(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 		hostinfo, err = f.handshakeManager.AddIndex(myIndex, ci)
 		if err != nil {
 			l.WithError(err).WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", addr).
+				WithField("certName", certName).
 				WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).Error("Error adding index to connection manager")
 
 			return true
 		}
 		l.WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", addr).
+			WithField("certName", certName).
 			WithField("initiatorIndex", hs.Details.InitiatorIndex).WithField("responderIndex", hs.Details.ResponderIndex).
 			WithField("remoteIndex", h.RemoteIndex).WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).
 			Info("Handshake message received")
@@ -152,6 +156,7 @@ func ixHandshakeStage1(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 		hsBytes, err := proto.Marshal(hs)
 		if err != nil {
 			l.WithError(err).WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("udpAddr", addr).
+				WithField("certName", certName).
 				WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).Error("Failed to marshal handshake message")
 			return true
 		}
@@ -160,12 +165,14 @@ func ixHandshakeStage1(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 		msg, dKey, eKey, err := ci.H.WriteMessage(header, hsBytes)
 		if err != nil {
 			l.WithError(err).WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("udpAddr", addr).
+				WithField("certName", certName).
 				WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).Error("Failed to call noise.WriteMessage")
 			return true
 		}
 
 		if f.hostMap.CheckHandshakeCompleteIP(vpnIP) && vpnIP < ip2int(f.certState.certificate.Details.Ips[0].IP) {
 			l.WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", addr).
+				WithField("certName", certName).
 				WithField("initiatorIndex", hs.Details.InitiatorIndex).WithField("responderIndex", hs.Details.ResponderIndex).
 				WithField("remoteIndex", h.RemoteIndex).WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).
 				Info("Prevented a handshake race")
@@ -187,11 +194,13 @@ func ixHandshakeStage1(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 			err := f.outside.WriteTo(msg, addr)
 			if err != nil {
 				l.WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", addr).
+					WithField("certName", certName).
 					WithField("initiatorIndex", hs.Details.InitiatorIndex).WithField("responderIndex", hs.Details.ResponderIndex).
 					WithField("remoteIndex", h.RemoteIndex).WithField("handshake", m{"stage": 2, "style": "ix_psk0"}).
 					WithError(err).Error("Failed to send handshake")
 			} else {
 				l.WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", addr).
+					WithField("certName", certName).
 					WithField("initiatorIndex", hs.Details.InitiatorIndex).WithField("responderIndex", hs.Details.ResponderIndex).
 					WithField("remoteIndex", h.RemoteIndex).WithField("handshake", m{"stage": 2, "style": "ix_psk0"}).
 					Info("Handshake message sent")
@@ -214,6 +223,7 @@ func ixHandshakeStage1(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 			ho, err := f.hostMap.QueryVpnIP(vpnIP)
 			if err == nil && ho.localIndexId != 0 {
 				l.WithField("vpnIp", vpnIP).
+					WithField("certName", certName).
 					WithField("action", "removing stale index").
 					WithField("index", ho.localIndexId).
 					Debug("Handshake processing")
@@ -226,6 +236,7 @@ func ixHandshakeStage1(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 			hostinfo.handshakeComplete()
 		} else {
 			l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("udpAddr", addr).
+				WithField("certName", certName).
 				WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).
 				Error("Noise did not arrive at a key")
 			return true
@@ -284,9 +295,11 @@ func ixHandshakeStage2(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 		return true
 	}
 	vpnIP := ip2int(remoteCert.Details.Ips[0].IP)
+	certName := remoteCert.Details.Name
 
 	duration := time.Since(hostinfo.handshakeStart).Nanoseconds()
 	l.WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", addr).
+		WithField("certName", certName).
 		WithField("initiatorIndex", hs.Details.InitiatorIndex).WithField("responderIndex", hs.Details.ResponderIndex).
 		WithField("remoteIndex", h.RemoteIndex).WithField("handshake", m{"stage": 2, "style": "ix_psk0"}).
 		WithField("durationNs", duration).
@@ -324,6 +337,7 @@ func ixHandshakeStage2(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 		ho, err := f.hostMap.QueryVpnIP(vpnIP)
 		if err == nil && ho.localIndexId != 0 {
 			l.WithField("vpnIp", vpnIP).
+				WithField("certName", certName).
 				WithField("action", "removing stale index").
 				WithField("index", ho.localIndexId).
 				Debug("Handshake processing")
@@ -337,6 +351,7 @@ func ixHandshakeStage2(f *Interface, addr *udpAddr, hostinfo *HostInfo, packet [
 		f.metricHandshakes.Update(duration)
 	} else {
 		l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("udpAddr", addr).
+			WithField("certName", certName).
 			WithField("handshake", m{"stage": 2, "style": "ix_psk0"}).
 			Error("Noise did not arrive at a key")
 		return true

handshake_manager.go

@@ -113,7 +113,7 @@ func (c *HandshakeManager) NextOutboundHandshakeTimerTick(now time.Time, f EncWr
 			if hostinfo.HandshakeReady && hostinfo.remote != nil {
 				err := c.outside.WriteTo(hostinfo.HandshakePacket[0], hostinfo.remote)
 				if err != nil {
-					l.WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", hostinfo.remote).
+					hostinfo.logger().WithField("udpAddr", hostinfo.remote).
 						WithField("initiatorIndex", hostinfo.localIndexId).
 						WithField("remoteIndex", hostinfo.remoteIndexId).
 						WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).
@@ -121,7 +121,7 @@ func (c *HandshakeManager) NextOutboundHandshakeTimerTick(now time.Time, f EncWr
 				} else {
 					//TODO: this log line is assuming a lot of stuff around the cached stage 0 handshake packet, we should
 					// keep the real packet struct around for logging purposes
-					l.WithField("vpnIp", IntIp(vpnIP)).WithField("udpAddr", hostinfo.remote).
+					hostinfo.logger().WithField("udpAddr", hostinfo.remote).
 						WithField("initiatorIndex", hostinfo.localIndexId).
 						WithField("remoteIndex", hostinfo.remoteIndexId).
 						WithField("handshake", m{"stage": 1, "style": "ix_psk0"}).

hostmap.go

@@ -532,13 +532,13 @@ func (i *HostInfo) cachePacket(t NebulaMessageType, st NebulaMessageSubType, pac
 		copy(tempPacket, packet)
 		//l.WithField("trace", string(debug.Stack())).Error("Caching packet", tempPacket)
 		i.packetStore = append(i.packetStore, &cachedPacket{t, st, f, tempPacket})
-		l.WithField("vpnIp", IntIp(i.hostId)).
+		i.logger().
 			WithField("length", len(i.packetStore)).
 			WithField("stored", true).
 			Debugf("Packet store")
 
 	} else if l.Level >= logrus.DebugLevel {
-		l.WithField("vpnIp", IntIp(i.hostId)).
+		i.logger().
 			WithField("length", len(i.packetStore)).
 			WithField("stored", false).
 			Debugf("Packet store")
@@ -556,7 +556,7 @@ func (i *HostInfo) handshakeComplete() {
 	//TODO: this should be managed by the handshake state machine to set it based on how many handshake were seen.
 	// Clamping it to 2 gets us out of the woods for now
 	*i.ConnectionState.messageCounter = 2
-	l.WithField("vpnIp", IntIp(i.hostId)).Debugf("Sending %d stored packets", len(i.packetStore))
+	i.logger().Debugf("Sending %d stored packets", len(i.packetStore))
 	nb := make([]byte, 12, 12)
 	out := make([]byte, mtu)
 	for _, cp := range i.packetStore {
@@ -639,6 +639,22 @@ func (i *HostInfo) CreateRemoteCIDR(c *cert.NebulaCertificate) {
 	i.remoteCidr = remoteCidr
 }
 
+func (i *HostInfo) logger() *logrus.Entry {
+	if i == nil {
+		return logrus.NewEntry(l)
+	}
+
+	li := l.WithField("vpnIp", IntIp(i.hostId))
+
+	if connState := i.ConnectionState; connState != nil {
+		if peerCert := connState.peerCert; peerCert != nil {
+			li = li.WithField("certName", peerCert.Details.Name)
+		}
+	}
+
+	return li
+}
+
 //########################
 
 func NewHostInfoDest(addr *udpAddr) *HostInfoDest {

inside.go

@@ -51,7 +51,7 @@ func (f *Interface) consumeInsidePacket(packet []byte, fwPacket *FirewallPacket,
 		}
 
 	} else if l.Level >= logrus.DebugLevel {
-		l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("fwPacket", fwPacket).
+		hostinfo.logger().WithField("fwPacket", fwPacket).
 			Debugln("dropping outbound packet")
 	}
 }
@@ -185,7 +185,7 @@ func (f *Interface) send(t NebulaMessageType, st NebulaMessageSubType, ci *Conne
 	//TODO: see above note on lock
 	//ci.writeLock.Unlock()
 	if err != nil {
-		l.WithError(err).WithField("vpnIp", IntIp(hostinfo.hostId)).
+		hostinfo.logger().WithError(err).
 			WithField("udpAddr", remote).WithField("counter", c).
 			WithField("attemptedCounter", ci.messageCounter).
 			Error("Failed to encrypt outgoing packet")
@@ -194,7 +194,7 @@ func (f *Interface) send(t NebulaMessageType, st NebulaMessageSubType, ci *Conne
 
 	err = f.outside.WriteTo(out, remote)
 	if err != nil {
-		l.WithError(err).WithField("vpnIp", IntIp(hostinfo.hostId)).
+		hostinfo.logger().WithError(err).
 			WithField("udpAddr", remote).Error("Failed to write outgoing packet")
 	}
 }

outside.go

@@ -60,7 +60,7 @@ func (f *Interface) readOutsidePackets(addr *udpAddr, out []byte, packet []byte,
 
 		d, err := f.decrypt(hostinfo, header.MessageCounter, out, packet, header, nb)
 		if err != nil {
-			l.WithError(err).WithField("udpAddr", addr).WithField("vpnIp", IntIp(hostinfo.hostId)).
+			hostinfo.logger().WithError(err).WithField("udpAddr", addr).
 				WithField("packet", packet).
 				Error("Failed to decrypt lighthouse packet")
 
@@ -80,7 +80,7 @@ func (f *Interface) readOutsidePackets(addr *udpAddr, out []byte, packet []byte,
 
 		d, err := f.decrypt(hostinfo, header.MessageCounter, out, packet, header, nb)
 		if err != nil {
-			l.WithError(err).WithField("udpAddr", addr).WithField("vpnIp", IntIp(hostinfo.hostId)).
+			hostinfo.logger().WithError(err).WithField("udpAddr", addr).
 				WithField("packet", packet).
 				Error("Failed to decrypt test packet")
 
@@ -115,14 +115,14 @@ func (f *Interface) readOutsidePackets(addr *udpAddr, out []byte, packet []byte,
 			return
 		}
 
-		l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("udpAddr", addr).
+		hostinfo.logger().WithField("udpAddr", addr).
 			Info("Close tunnel received, tearing down.")
 
 		f.closeTunnel(hostinfo)
 		return
 
 	default:
-		l.Debugf("Unexpected packet received from %s", addr)
+		hostinfo.logger().Debugf("Unexpected packet received from %s", addr)
 		return
 	}
 
@@ -144,13 +144,13 @@ func (f *Interface) handleHostRoaming(hostinfo *HostInfo, addr *udpAddr) {
 	if hostDidRoam(hostinfo.remote, addr) {
 		if !hostinfo.lastRoam.IsZero() && addr.Equals(hostinfo.lastRoamRemote) && time.Since(hostinfo.lastRoam) < RoamingSupressSeconds*time.Second {
 			if l.Level >= logrus.DebugLevel {
-				l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("udpAddr", hostinfo.remote).WithField("newAddr", addr).
+				hostinfo.logger().WithField("udpAddr", hostinfo.remote).WithField("newAddr", addr).
 					Debugf("Supressing roam back to previous remote for %d seconds", RoamingSupressSeconds)
 			}
 			return
 		}
 
-		l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("udpAddr", hostinfo.remote).WithField("newAddr", addr).
+		hostinfo.logger().WithField("udpAddr", hostinfo.remote).WithField("newAddr", addr).
 			Info("Host roamed to new udp ip/port.")
 		hostinfo.lastRoam = time.Now()
 		remoteCopy := *hostinfo.remote
@@ -244,7 +244,7 @@ func (f *Interface) decrypt(hostinfo *HostInfo, mc uint64, out []byte, packet []
 	}
 
 	if !hostinfo.ConnectionState.window.Update(mc) {
-		l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("header", header).
+		hostinfo.logger().WithField("header", header).
 			Debugln("dropping out of window packet")
 		return nil, errors.New("out of window packet")
 	}
@@ -257,7 +257,7 @@ func (f *Interface) decryptToTun(hostinfo *HostInfo, messageCounter uint64, out
 
 	out, err = hostinfo.ConnectionState.dKey.DecryptDanger(out, packet[:HeaderLen], packet[HeaderLen:], messageCounter, nb)
 	if err != nil {
-		l.WithError(err).WithField("vpnIp", IntIp(hostinfo.hostId)).Error("Failed to decrypt packet")
+		hostinfo.logger().WithError(err).Error("Failed to decrypt packet")
 		//TODO: maybe after build 64 is out? 06/14/2018 - NB
 		//f.sendRecvError(hostinfo.remote, header.RemoteIndex)
 		return
@@ -265,19 +265,19 @@ func (f *Interface) decryptToTun(hostinfo *HostInfo, messageCounter uint64, out
 
 	err = newPacket(out, true, fwPacket)
 	if err != nil {
-		l.WithError(err).WithField("packet", out).WithField("hostInfo", IntIp(hostinfo.hostId)).
+		hostinfo.logger().WithError(err).WithField("packet", out).
 			Warnf("Error while validating inbound packet")
 		return
 	}
 
 	if !hostinfo.ConnectionState.window.Update(messageCounter) {
-		l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("fwPacket", fwPacket).
+		hostinfo.logger().WithField("fwPacket", fwPacket).
 			Debugln("dropping out of window packet")
 		return
 	}
 
 	if f.firewall.Drop(out, *fwPacket, true, hostinfo, trustedCAs) {
-		l.WithField("vpnIp", IntIp(hostinfo.hostId)).WithField("fwPacket", fwPacket).
+		hostinfo.logger().WithField("fwPacket", fwPacket).
 			Debugln("dropping inbound packet")
 		return
 	}