Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

log certName alongside vpnIp #200

Merged
merged 1 commit into from Apr 6, 2020
Merged

log certName alongside vpnIp #200

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
6 changes: 3 additions & 3 deletions connection_manager.go
View file
Open in desktop
Expand Up @@ -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")

Expand All @@ -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)
}
Expand Down Expand Up @@ -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")
Expand Down
15 changes: 15 additions & 0 deletions handshake_ix.go
View file
Open in desktop
Expand Up @@ -125,22 +125,26 @@ 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
}

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")
Expand All @@ -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
}
Expand All @@ -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")
Expand All @@ -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")
Expand All @@ -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")
Expand All @@ -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
Expand Down Expand Up @@ -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).
Expand Down Expand Up @@ -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")
Expand All @@ -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
Expand Down
4 changes: 2 additions & 2 deletions handshake_manager.go
View file
Open in desktop
Expand Up @@ -113,15 +113,15 @@ 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"}).
WithError(err).Error("Failed to send handshake message")
} 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"}).
Expand Down
22 changes: 19 additions & 3 deletions hostmap.go
View file
Open in desktop
Expand Up @@ -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")
Expand All @@ -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 {
Expand Down Expand Up @@ -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 {
Expand Down
6 changes: 3 additions & 3 deletions inside.go
View file
Open in desktop
Expand Up @@ -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")
}
}
Expand Down Expand Up @@ -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")
Expand All @@ -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")
}
}
Expand Down
22 changes: 11 additions & 11 deletions outside.go
View file
Open in desktop
Expand Up @@ -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")

Expand All @@ -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")

Expand Down Expand Up @@ -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
}

Expand All @@ -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
Expand Down Expand Up @@ -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")
}
Expand All @@ -257,27 +257,27 @@ 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
}

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