Add logtail tests (#1114)

* logtail: test parseAndRemoveLogLevel()

Signed-off-by: Denton Gentry <dgentry@tailscale.com>

* logtail: test JSON log encoding.

Expand TestUploadMessages to also exercise the encoding functions
in logtail, like JSON logging and timestamps.

Other tests frequently send logs but a) don't check the result and
b) do so by happenstance, such that the lines in encode() were not
consistently being exercised and leading to spurious changes in
code coverage.

Signed-off-by: Denton Gentry <dgentry@tailscale.com>

* logtail: add a test for drainPendingMessages

Make the client buffer some messages before the upload server
becomes available.

Signed-off-by: Denton Gentry <dgentry@tailscale.com>

* logtail: use %q, raw strings, and io.WriteString

%q escapes binary characters for us.

raw strings avoid so much backslash escaping

Signed-off-by: Denton Gentry <dgentry@tailscale.com>

logtail/logtail_test.go

@@ -6,8 +6,12 @@ package logtail
 
 import (
 	"context"
+	"encoding/json"
+	"io"
+	"io/ioutil"
 	"net/http"
 	"net/http/httptest"
+	"strings"
 	"testing"
 	"time"
 )
@@ -26,26 +30,175 @@ func TestFastShutdown(t *testing.T) {
 	l.Shutdown(ctx)
 }
 
-func TestUploadMessages(t *testing.T) {
+// accumulate some logs before the server becomes available, exercise the drain path
+func TestDrainPendingMessages(t *testing.T) {
 	ctx, cancel := context.WithCancel(context.Background())
-	uploads := 0
+	uploaded := make(chan int)
+	bodytext := ""
 	testServ := httptest.NewServer(http.HandlerFunc(
 		func(w http.ResponseWriter, r *http.Request) {
-			w.Header().Set("Content-Type", "application/json; charset=utf-8")
+			body, err := ioutil.ReadAll(r.Body)
-			uploads += 1
+			if err != nil {
+				t.Error("failed to read HTTP request")
+			}
+			bodytext += "\n" + string(body)
+
+			uploaded <- 0
 		}))
 	defer testServ.Close()
 
 	l := NewLogger(Config{BaseURL: testServ.URL}, t.Logf)
-	for i := 1; i < 10; i++ {
+	for i := 0; i < 3; i++ {
 		l.Write([]byte("log line"))
 	}
 
+	select {
+	case <-uploaded:
+		if strings.Count(bodytext, "log line") == 3 {
+			break
+		}
+	case <-time.After(1 * time.Second):
+		t.Errorf("Timed out waiting for log uploads")
+	}
+
 	l.Shutdown(ctx)
 	cancel()
-	if uploads == 0 {
+	if strings.Count(bodytext, "log line") != 3 {
-		t.Error("no log uploads")
+		t.Errorf("got %q; want: 3 copies of %q", bodytext, "log line")
+	}
+}
+
+func TestEncodeAndUploadMessages(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	var jsonbody []byte
+	uploaded := make(chan int)
+	testServ := httptest.NewServer(http.HandlerFunc(
+		func(w http.ResponseWriter, r *http.Request) {
+			body, err := ioutil.ReadAll(r.Body)
+			if err != nil {
+				t.Error("failed to read HTTP request")
+			}
+			jsonbody = body
+			uploaded <- 0
+		}))
+	defer testServ.Close()
+
+	l := NewLogger(Config{BaseURL: testServ.URL}, t.Logf)
+
+	// There is always an initial "logtail started" message
+	<-uploaded
+	if !strings.Contains(string(jsonbody), "started") {
+		t.Errorf("initialize: got:%q; want:%q", string(jsonbody), "started")
+	}
+
+	tests := []struct {
+		name string
+		log  string
+		want string
+	}{
+		{
+			"plain text",
+			"log line",
+			"log line",
+		},
+		{
+			"simple JSON",
+			`{"text": "log line"}`,
+			"log line",
+		},
+		{
+			"escaped characters",
+			`\b\f\n\r\t"\\`,
+			`\b\f\n\r\t"\\`,
+		},
+	}
+
+	for _, tt := range tests {
+		io.WriteString(l, tt.log)
+		<-uploaded
+
+		data := make(map[string]interface{})
+		err := json.Unmarshal(jsonbody, &data)
+		if err != nil {
+			t.Error(err)
+		}
+
+		got, ok := data["text"]
+		if ok {
+			if got != tt.want {
+				t.Errorf("%s: got %q; want %q", tt.name, got.(string), tt.want)
+			}
+		} else {
+			t.Errorf("no text in: %v", data)
+		}
+
+		ltail, ok := data["logtail"]
+		if ok {
+			logtailmap := ltail.(map[string]interface{})
+			_, ok = logtailmap["client_time"]
+			if !ok {
+				t.Errorf("%s: no client_time present", tt.name)
+			}
+		} else {
+			t.Errorf("%s: no logtail map present", tt.name)
+		}
+	}
+
+	// test some special cases
+
+	// JSON log message already contains a logtail field.
+	io.WriteString(l, `{"logtail": "LOGTAIL", "text": "text"}`)
+	<-uploaded
+	data := make(map[string]interface{})
+	err := json.Unmarshal(jsonbody, &data)
+	if err != nil {
+		t.Error(err)
+	}
+	error_has_logtail, ok := data["error_has_logtail"]
+	if ok {
+		if error_has_logtail.(string) != "LOGTAIL" {
+			t.Errorf("error_has_logtail: got:%q; want:%q",
+				error_has_logtail.(string), "LOGTAIL")
+		}
+	} else {
+		t.Errorf("no error_has_logtail field: %v", data)
+	}
+
+	// skipClientTime to omit the logtail metadata
+	l.skipClientTime = true
+	io.WriteString(l, "text")
+	<-uploaded
+	data = make(map[string]interface{})
+	err = json.Unmarshal(jsonbody, &data)
+	if err != nil {
+		t.Error(err)
+	}
+	_, ok = data["logtail"]
+	if ok {
+		t.Errorf("skipClientTime: unexpected logtail map present: %v", data)
 	}
+
+	// lowMem + long string
+	l.skipClientTime = false
+	l.lowMem = true
+	longStr := strings.Repeat("0", 512)
+	io.WriteString(l, longStr)
+	<-uploaded
+	data = make(map[string]interface{})
+	err = json.Unmarshal(jsonbody, &data)
+	if err != nil {
+		t.Error(err)
+	}
+	text, ok := data["text"]
+	if !ok {
+		t.Errorf("lowMem: no text %v", data)
+	}
+	if len(text.(string)) > 300 {
+		t.Errorf("lowMem: got %d chars; want <300 chars", len(text.(string)))
+	}
+
+	l.Shutdown(ctx)
+	cancel()
 }
 
 var sink []byte
@@ -75,3 +228,52 @@ func TestLoggerWriteLength(t *testing.T) {
 		t.Errorf("logger.Write wrote %d bytes, expected %d", n, len(inBuf))
 	}
 }
+
+func TestParseAndRemoveLogLevel(t *testing.T) {
+	tests := []struct {
+		log       string
+		wantLevel int
+		wantLog   string
+	}{
+		{
+			"no level",
+			0,
+			"no level",
+		},
+		{
+			"[v1] level 1",
+			1,
+			"level 1",
+		},
+		{
+			"level 1 [v1] ",
+			1,
+			"level 1 ",
+		},
+		{
+			"[v2] level 2",
+			2,
+			"level 2",
+		},
+		{
+			"level [v2] 2",
+			2,
+			"level 2",
+		},
+		{
+			"[v3] no level 3",
+			0,
+			"[v3] no level 3",
+		},
+	}
+
+	for _, tt := range tests {
+		gotLevel, gotLog := parseAndRemoveLogLevel([]byte(tt.log))
+		if gotLevel != tt.wantLevel {
+			t.Errorf("%q: got:%d; want %d", tt.log, gotLevel, tt.wantLevel)
+		}
+		if string(gotLog) != tt.wantLog {
+			t.Errorf("%q: got:%q; want %q", tt.log, gotLog, tt.wantLog)
+		}
+	}
+}