internal/envoy: improve handleLogs (#929)

The log line has a well defined structure that we can process by simple
string manipulation, instead of relying on regex.

name            old time/op    new time/op    delta
_handleLogs-12    17.3µs ±23%     1.1µs ±11%  -93.81%  (p=0.000 n=10+10)

name            old alloc/op   new alloc/op   delta
_handleLogs-12    20.1kB ± 0%     4.1kB ± 0%  -79.59%  (p=0.002 n=8+10)

name            old allocs/op  new allocs/op  delta
_handleLogs-12       141 ± 0%         1 ± 0%  -99.29%  (p=0.000 n=10+10)

internal/envoy/envoy.go

@@ -309,12 +309,22 @@ func (srv *Server) addTraceConfig(traceOpts *config.TracingOptions, bootCfg *env
 	return nil
 }
 
+var fileNameAndNumberRE = regexp.MustCompile(`^(\[[a-zA-Z0-9/-_.]+:[0-9]+])\s(.*)$`)
+
+func (srv *Server) parseLog(line string) (name string, logLevel string, msg string) {
+	// format: [LOG_FORMAT]level--name--message
+	// message is c-escaped
+	parts := strings.SplitN(line, "--", 3)
+	if len(parts) == 3 {
+		logLevel = strings.TrimPrefix(parts[0], "[LOG_FORMAT]")
+		name = parts[1]
+		msg = parts[2]
+	}
+	return
+}
+
 func (srv *Server) handleLogs(rc io.ReadCloser) {
 	defer rc.Close()
-
-	logFormatRE := regexp.MustCompile(`^[[]LOG_FORMAT[]](.*?)--(.*?)--(.*?)$`)
-	fileNameAndNumberRE := regexp.MustCompile(`^(\[[a-zA-Z0-9/-_.]+:[0-9]+])\s(.*)$`)
-
 	s := bufio.NewReader(rc)
 	for {
 		ln, err := s.ReadString('\n')
@@ -327,19 +337,16 @@ func (srv *Server) handleLogs(rc io.ReadCloser) {
 		}
 		ln = strings.TrimRight(ln, "\r\n")
 
-		// format: [LOG_FORMAT]level--name--message
-		// message is c-escaped
-
+		name, logLevel, msg := srv.parseLog(ln)
+		if name == "" {
+			name = "envoy"
+		}
 		lvl := zerolog.DebugLevel
-		name := "envoy"
-		msg := ln
-		parts := logFormatRE.FindStringSubmatch(ln)
-		if len(parts) == 4 {
-			if x, err := zerolog.ParseLevel(parts[1]); err == nil {
-				lvl = x
-			}
-			name = parts[2]
-			msg = parts[3]
+		if x, err := zerolog.ParseLevel(logLevel); err == nil {
+			lvl = x
+		}
+		if msg == "" {
+			msg = ln
 		}
 
 		msg = fileNameAndNumberRE.ReplaceAllString(msg, "\"$2\"")

internal/envoy/envoy_test.go

@@ -2,12 +2,16 @@ package envoy
 
 import (
 	"fmt"
+	"io/ioutil"
 	"net/url"
+	"regexp"
+	"strings"
 	"testing"
 
 	envoy_config_bootstrap_v3 "github.com/envoyproxy/go-control-plane/envoy/config/bootstrap/v3"
 	"github.com/golang/protobuf/proto"
 	"github.com/nsf/jsondiff"
+	"github.com/rs/zerolog"
 	"github.com/stretchr/testify/assert"
 	"google.golang.org/protobuf/encoding/protojson"
 
@@ -88,3 +92,41 @@ func Test_buildStatsConfig(t *testing.T) {
 		})
 	}
 }
+
+func TestServer_handleLogs(t *testing.T) {
+	logFormatRE := regexp.MustCompile(`^[[]LOG_FORMAT[]](.*?)--(.*?)--(.*?)$`)
+	line := "[LOG_FORMAT]debug--filter--[external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:78] tls inspector: new connection accepted"
+	old := func(s string) string {
+		msg := s
+		parts := logFormatRE.FindStringSubmatch(s)
+		if len(parts) == 4 {
+			msg = parts[3]
+		}
+		return msg
+	}
+	srv := &Server{}
+	expectedMsg := old(line)
+	name, logLevel, gotMsg := srv.parseLog(line)
+	if name != "filter" {
+		t.Errorf("unexpected name, want filter, got: %s", name)
+	}
+	if logLevel != "debug" {
+		t.Errorf("unexpected log level, want debug, got: %s", logLevel)
+	}
+	if gotMsg != expectedMsg {
+		t.Errorf("unexpected msg, want %s, got: %s", expectedMsg, gotMsg)
+	}
+}
+
+func Benchmark_handleLogs(b *testing.B) {
+	line := `[LOG_FORMAT]debug--http--[external/envoy/source/common/http/conn_manager_impl.cc:781] [C25][S14758077654018620250] request headers complete (end_stream=false):\\n\\':authority\\', \\'enabled-ws-echo.localhost.pomerium.io\\'\\n\\':path\\', \\'/\\'\\n\\':method\\', \\'GET\\'\\n\\'upgrade\\', \\'websocket\\'\\n\\'connection\\', \\'upgrade\\'\\n\\'x-request-id\\', \\'30ac7726e0b9e00a9c9ab2bf66d692ac\\'\\n\\'x-real-ip\\', \\'172.17.0.1\\'\\n\\'x-forwarded-for\\', \\'172.17.0.1\\'\\n\\'x-forwarded-host\\', \\'enabled-ws-echo.localhost.pomerium.io\\'\\n\\'x-forwarded-port\\', \\'443\\'\\n\\'x-forwarded-proto\\', \\'https\\'\\n\\'x-scheme\\', \\'https\\'\\n\\'user-agent\\', \\'Go-http-client/1.1\\'\\n\\'sec-websocket-key\\', \\'4bh7+YFVzrJiblaSu/CVfg==\\'\\n\\'sec-websocket-version\\', \\'13\\'`
+	rc := ioutil.NopCloser(strings.NewReader(line))
+	srv := &Server{}
+	zerolog.SetGlobalLevel(zerolog.InfoLevel)
+
+	b.ResetTimer()
+	b.ReportAllocs()
+	for i := 0; i < b.N; i++ {
+		srv.handleLogs(rc)
+	}
+}