From b4f2f7ce4ec1c6e53d8d439b0b0898a08a814b05 Mon Sep 17 00:00:00 2001 From: Wade Simmons Date: Mon, 6 Apr 2020 14:34:00 -0400 Subject: [PATCH] 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 | 6 +++--- handshake_ix.go | 15 +++++++++++++++ handshake_manager.go | 4 ++-- hostmap.go | 22 +++++++++++++++++++--- inside.go | 6 +++--- outside.go | 22 +++++++++++----------- 6 files changed, 53 insertions(+), 22 deletions(-) diff --git a/connection_manager.go b/connection_manager.go index 1785444..bcd13b6 100644 --- a/connection_manager.go +++ b/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") diff --git a/handshake_ix.go b/handshake_ix.go index 0e29032..32fbe57 100644 --- a/handshake_ix.go +++ b/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 diff --git a/handshake_manager.go b/handshake_manager.go index e004637..67e990a 100644 --- a/handshake_manager.go +++ b/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"}). diff --git a/hostmap.go b/hostmap.go index aaba557..bb4e9fa 100644 --- a/hostmap.go +++ b/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 { diff --git a/inside.go b/inside.go index d2cd7e6..493afa8 100644 --- a/inside.go +++ b/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") } } diff --git a/outside.go b/outside.go index 7f9544c..c36bb93 100644 --- a/outside.go +++ b/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 }