Add a simple benchmark to e2e tests (slackhq#739)

Makefile

@@ -66,6 +66,9 @@ e2evvv: e2ev
 e2evvvv: TEST_ENV += TEST_LOGS=3
 e2evvvv: e2ev
 
+e2e-bench: TEST_FLAGS = -bench=. -benchmem -run=^$
+e2e-bench: e2e
+
 all: $(ALL:%=build/%/nebula) $(ALL:%=build/%/nebula-cert)
 
 release: $(ALL:%=build/nebula-%.tar.gz)

e2e/handshakes_test.go

@@ -16,6 +16,30 @@ import (
  "github.com/stretchr/testify/assert"
 )
 
+func BenchmarkHotPath(b *testing.B) {
+ ca, _, caKey, _ := newTestCaCert(time.Now(), time.Now().Add(10*time.Minute), []*net.IPNet{}, []*net.IPNet{}, []string{})
+ myControl, _, _ := newSimpleServer(ca, caKey, "me", net.IP{10, 0, 0, 1}, nil)
+ theirControl, theirVpnIp, theirUdpAddr := newSimpleServer(ca, caKey, "them", net.IP{10, 0, 0, 2}, nil)
+
+ // Put their info in our lighthouse
+ myControl.InjectLightHouseAddr(theirVpnIp, theirUdpAddr)
+
+ // Start the servers
+ myControl.Start()
+ theirControl.Start()
+
+ r := router.NewR(b, myControl, theirControl)
+ r.CancelFlowLogs()
+
+ for n := 0; n < b.N; n++ {
+ myControl.InjectTunUDPPacket(theirVpnIp, 80, 80, []byte("Hi from me"))
+ _ = r.RouteForAllUntilTxTun(theirControl)
+ }
+
+ myControl.Stop()
+ theirControl.Stop()
+}
+
 func TestGoodHandshake(t *testing.T) {
  ca, _, caKey, _ := newTestCaCert(time.Now(), time.Now().Add(10*time.Minute), []*net.IPNet{}, []*net.IPNet{}, []string{})
  myControl, myVpnIp, myUdpAddr := newSimpleServer(ca, caKey, "me", net.IP{10, 0, 0, 1}, nil)

e2e/helpers_test.go

@@ -7,7 +7,6 @@ import (
  "crypto/rand"
  "fmt"
  "io"
- "io/ioutil"
  "net"
  "os"
  "testing"
@@ -304,7 +303,8 @@ func NewTestLogger() *logrus.Logger {
 
  v := os.Getenv("TEST_LOGS")
  if v == "" {
- l.SetOutput(ioutil.Discard)
+ l.SetOutput(io.Discard)
+ l.SetLevel(logrus.PanicLevel)
  return l
  }
 

e2e/router/router.go

@@ -47,7 +47,7 @@ type R struct {
 
  fn string
  cancelRender context.CancelFunc
- t *testing.T
+ t testing.TB
 }
 
 type flowEntry struct {
@@ -63,6 +63,12 @@ type packet struct {
  rx bool // the packet was received by a udp device
 }
 
+func (p *packet) WasReceived() {
+ if p != nil {
+ p.rx = true
+ }
+}
+
 type ExitType int
 
 const (
@@ -79,7 +85,7 @@ type ExitFunc func(packet *udp.Packet, receiver *nebula.Control) ExitType
 // NewR creates a new router to pass packets in a controlled fashion between the provided controllers.
 // The packet flow will be recorded in a file within the mermaid directory under the same name as the test.
 // Renders will occur automatically, roughly every 100ms, until a call to RenderFlow() is made
-func NewR(t *testing.T, controls ...*nebula.Control) *R {
+func NewR(t testing.TB, controls ...*nebula.Control) *R {
  ctx, cancel := context.WithCancel(context.Background())
 
  if err := os.MkdirAll("mermaid", 0755); err != nil {
@@ -91,6 +97,7 @@ func NewR(t *testing.T, controls ...*nebula.Control) *R {
  vpnControls: make(map[iputil.VpnIp]*nebula.Control),
  inNat: make(map[string]*nebula.Control),
  outNat: make(map[string]net.UDPAddr),
+ flow: []flowEntry{},
  fn: filepath.Join("mermaid", fmt.Sprintf("%s.md", t.Name())),
  t: t,
  cancelRender: cancel,
@@ -148,14 +155,24 @@ func (r *R) RenderFlow() {
  r.renderFlow()
 }
 
+// CancelFlowLogs stops flow logs from being tracked and destroys any logs already collected
+func (r *R) CancelFlowLogs() {
+ r.cancelRender()
+ r.flow = nil
+}
+
 func (r *R) renderFlow() {
+ if r.flow == nil {
+ return
+ }
+
  f, err := os.OpenFile(r.fn, os.O_CREATE|os.O_TRUNC|os.O_RDWR, 0644)
  if err != nil {
  panic(err)
  }
 
  var participants = map[string]struct{}{}
- var participansVals []string
+ var participantsVals []string
 
  fmt.Fprintln(f, "```mermaid")
  fmt.Fprintln(f, "sequenceDiagram")
@@ -172,7 +189,7 @@ func (r *R) renderFlow() {
  }
  participants[addr] = struct{}{}
  sanAddr := strings.Replace(addr, ":", "#58;", 1)
- participansVals = append(participansVals, sanAddr)
+ participantsVals = append(participantsVals, sanAddr)
  fmt.Fprintf(
  f, " participant %s as Nebula: %s<br/>UDP: %s\n",
  sanAddr, e.packet.from.GetVpnIp(), sanAddr,
@@ -183,7 +200,7 @@ func (r *R) renderFlow() {
  h := &header.H{}
  for _, e := range r.flow {
  if e.packet == nil {
- fmt.Fprintf(f, " note over %s: %s\n", strings.Join(participansVals, ", "), e.note)
+ fmt.Fprintf(f, " note over %s: %s\n", strings.Join(participantsVals, ", "), e.note)
  continue
  }
 
@@ -222,28 +239,42 @@ func (r *R) InjectFlow(from, to *nebula.Control, p *udp.Packet) {
 }
 
 func (r *R) Log(arg ...any) {
+ if r.flow == nil {
+ return
+ }
+
  r.Lock()
  r.flow = append(r.flow, flowEntry{note: fmt.Sprint(arg...)})
  r.t.Log(arg...)
  r.Unlock()
 }
 
 func (r *R) Logf(format string, arg ...any) {
+ if r.flow == nil {
+ return
+ }
+
  r.Lock()
  r.flow = append(r.flow, flowEntry{note: fmt.Sprintf(format, arg...)})
  r.t.Logf(format, arg...)
  r.Unlock()
 }
 
 // unlockedInjectFlow is used by the router to record a packet has been transmitted, the packet is returned and
-// should be marked as received AFTER it has been placed on the receivers channel
+// should be marked as received AFTER it has been placed on the receivers channel.
+// If flow logs have been disabled this function will return nil
 func (r *R) unlockedInjectFlow(from, to *nebula.Control, p *udp.Packet, tun bool) *packet {
+ if r.flow == nil {
+ return nil
+ }
+
  fp := &packet{
  from: from,
  to: to,
  packet: p.Copy(),
  tun: tun,
  }
+
  r.flow = append(r.flow, flowEntry{packet: fp})
  return fp
 }
@@ -285,7 +316,7 @@ func (r *R) RouteUntilTxTun(sender *nebula.Control, receiver *nebula.Control) []
  }
  fp := r.unlockedInjectFlow(sender, c, p, false)
  c.InjectUDPPacket(p)
- fp.rx = true
+ fp.WasReceived()
  r.Unlock()
  }
  }
@@ -344,7 +375,7 @@ func (r *R) RouteForAllUntilTxTun(receiver *nebula.Control) []byte {
  }
  fp := r.unlockedInjectFlow(cm[x], c, p, false)
  c.InjectUDPPacket(p)
- fp.rx = true
+ fp.WasReceived()
  }
  r.Unlock()
  }
@@ -381,14 +412,14 @@ func (r *R) RouteExitFunc(sender *nebula.Control, whatDo ExitFunc) {
  case RouteAndExit:
  fp := r.unlockedInjectFlow(sender, receiver, p, false)
  receiver.InjectUDPPacket(p)
- fp.rx = true
+ fp.WasReceived()
  r.Unlock()
  return
 
  case KeepRouting:
  fp := r.unlockedInjectFlow(sender, receiver, p, false)
  receiver.InjectUDPPacket(p)
- fp.rx = true
+ fp.WasReceived()
 
  default:
  panic(fmt.Sprintf("Unknown exitFunc return: %v", e))
@@ -439,7 +470,7 @@ func (r *R) InjectUDPPacket(sender, receiver *nebula.Control, packet *udp.Packet
 
  fp := r.unlockedInjectFlow(sender, receiver, packet, false)
  receiver.InjectUDPPacket(packet)
- fp.rx = true
+ fp.WasReceived()
 }
 
 // RouteForUntilAfterToAddr will route for sender and return only after it sees and sends a packet destined for toAddr
@@ -503,14 +534,14 @@ func (r *R) RouteForAllExitFunc(whatDo ExitFunc) {
  case RouteAndExit:
  fp := r.unlockedInjectFlow(cm[x], receiver, p, false)
  receiver.InjectUDPPacket(p)
- fp.rx = true
+ fp.WasReceived()
  r.Unlock()
  return
 
  case KeepRouting:
  fp := r.unlockedInjectFlow(cm[x], receiver, p, false)
  receiver.InjectUDPPacket(p)
- fp.rx = true
+ fp.WasReceived()
 
  default:
  panic(fmt.Sprintf("Unknown exitFunc return: %v", e))

inside.go

@@ -14,7 +14,9 @@ import (
 func (f *Interface) consumeInsidePacket(packet []byte, fwPacket *firewall.Packet, nb, out []byte, q int, localCache firewall.ConntrackCache) {
  err := newPacket(packet, false, fwPacket)
  if err != nil {
- f.l.WithField("packet", packet).Debugf("Error while validating outbound packet: %s", err)
+ if f.l.Level >= logrus.DebugLevel {
+ f.l.WithField("packet", packet).Debugf("Error while validating outbound packet: %s", err)
+ }
  return
  }
 

overlay/tun_tester.go

@@ -7,6 +7,7 @@ import (
  "fmt"
  "io"
  "net"
+ "os"
 
  "github.com/sirupsen/logrus"
  "github.com/slackhq/nebula/cidr"
@@ -49,7 +50,9 @@ func newTunFromFd(_ *logrus.Logger, _ int, _ *net.IPNet, _ int, _ []Route, _ int
 // These are unencrypted ip layer frames destined for another nebula node.
 // packets should exit the udp side, capture them with udpConn.Get
 func (t *TestTun) Send(packet []byte) {
- t.l.WithField("dataLen", len(packet)).Info("Tun receiving injected packet")
+ if t.l.Level >= logrus.InfoLevel {
+ t.l.WithField("dataLen", len(packet)).Info("Tun receiving injected packet")
+ }
  t.rxPackets <- packet
 }
 
@@ -107,7 +110,10 @@ func (t *TestTun) Close() error {
 }
 
 func (t *TestTun) Read(b []byte) (int, error) {
- p := <-t.rxPackets
+ p, ok := <-t.rxPackets
+ if !ok {
+ return 0, os.ErrClosed
+ }
  copy(b, p)
  return len(p), nil
 }

udp/udp_tester.go

@@ -62,10 +62,12 @@ func (u *Conn) Send(packet *Packet) {
  if err := h.Parse(packet.Data); err != nil {
  panic(err)
  }
- u.l.WithField("header", h).
- WithField("udpAddr", fmt.Sprintf("%v:%v", packet.FromIp, packet.FromPort)).
- WithField("dataLen", len(packet.Data)).
- Info("UDP receiving injected packet")
+ if u.l.Level >= logrus.InfoLevel {
+ u.l.WithField("header", h).
+ WithField("udpAddr", fmt.Sprintf("%v:%v", packet.FromIp, packet.FromPort)).
+ WithField("dataLen", len(packet.Data)).
+ Info("UDP receiving injected packet")
+ }
  u.RxPackets <- packet
 }
 
@@ -114,7 +116,10 @@ func (u *Conn) ListenOut(r EncReader, lhf LightHouseHandlerFunc, cache *firewall
  nb := make([]byte, 12, 12)
 
  for {
- p := <-u.RxPackets
+ p, ok := <-u.RxPackets
+ if !ok {
+ return
+ }
  ua.Port = p.FromPort
  copy(ua.IP, p.FromIp.To16())
  r(ua, nil, plaintext[:0], p.Data, h, fwPacket, lhf, nb, q, cache.Get(u.l))