logtail: add tests

+ add a test for parseAndRemoveLogLevel()
+ add a test for drainPendingMessages()
+ test JSON log encoding including several special cases

Other tests frequently send logs but a) don't check the result and
b) do so by happenstance, such that the code in encode() was not
consistently being exercised and leading to spurious changes in
code coverage. These tests attempt to more systematically test
the logging function.

This is the second attempt to add these tests, the first attempt
(in https://github.com/tailscale/tailscale/pull/1114) had two issues:
1. httptest.NewServer creates multiple goroutine handlers, and
   logtail uses goroutines to upload, but the first version had no
   locking in the server to guard this.
   Moved data handling into channels to get synchronization.
2. The channel to notify the test of the arrival of data had a depth
   of 1, in cases where the Logger sent multiple uploads it would
   block the server.

This resulted in the first iteration of these tests being flaky,
and we reverted it.

This new version of the tests has passed with
    go test -race -count=10000
and seems solid.

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"
 )
@@ -23,28 +27,201 @@ func TestFastShutdown(t *testing.T) {
 	l := NewLogger(Config{
 		BaseURL: testServ.URL,
 	}, t.Logf)
-	l.Shutdown(ctx)
+	err := l.Shutdown(ctx)
+	if err != nil {
+		t.Error(err)
+	}
 }
 
-func TestUploadMessages(t *testing.T) {
+// maximum number of times a test will call l.Write()
-	ctx, cancel := context.WithCancel(context.Background())
+const logLines = 3
-	uploads := 0
+
-	testServ := httptest.NewServer(http.HandlerFunc(
+type LogtailTestServer struct {
+	srv      *httptest.Server // Log server
+	uploaded chan []byte
+}
+
+func NewLogtailTestHarness(t *testing.T) (*LogtailTestServer, *Logger) {
+	ts := LogtailTestServer{}
+
+	// max channel backlog = 1 "started" + #logLines x "log line" + 1 "closed"
+	ts.uploaded = make(chan []byte, 2+logLines)
+
+	ts.srv = 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")
+			}
+			ts.uploaded <- body
 		}))
-	defer testServ.Close()
 
-	l := NewLogger(Config{BaseURL: testServ.URL}, t.Logf)
+	t.Cleanup(ts.srv.Close)
-	for i := 1; i < 10; i++ {
+
+	l := NewLogger(Config{BaseURL: ts.srv.URL}, t.Logf)
+
+	// There is always an initial "logtail started" message
+	body := <-ts.uploaded
+	if !strings.Contains(string(body), "started") {
+		t.Errorf("unknown start logging statement: %q", string(body))
+	}
+
+	return &ts, l
+}
+
+func TestDrainPendingMessages(t *testing.T) {
+	ts, l := NewLogtailTestHarness(t)
+
+	for i := 0; i < logLines; i++ {
 		l.Write([]byte("log line"))
 	}
 
-	l.Shutdown(ctx)
+	// all of the "log line" messages usually arrive at once, but poll if needed.
-	cancel()
+	body := ""
-	if uploads == 0 {
+	for i := 0; i <= logLines; i++ {
-		t.Error("no log uploads")
+		body += string(<-ts.uploaded)
+		count := strings.Count(body, "log line")
+		if count == logLines {
+			break
+		}
+		// if we never find count == logLines, the test will eventually time out.
+	}
+
+	err := l.Shutdown(context.Background())
+	if err != nil {
+		t.Error(err)
+	}
+}
+
+func TestEncodeAndUploadMessages(t *testing.T) {
+	ts, l := NewLogtailTestHarness(t)
+
+	tests := []struct {
+		name string
+		log  string
+		want string
+	}{
+		{
+			"plain text",
+			"log line",
+			"log line",
+		},
+		{
+			"simple JSON",
+			`{"text": "log line"}`,
+			"log line",
+		},
+	}
+
+	for _, tt := range tests {
+		io.WriteString(l, tt.log)
+		body := <-ts.uploaded
+
+		data := make(map[string]interface{})
+		err := json.Unmarshal(body, &data)
+		if err != nil {
+			t.Error(err)
+		}
+
+		got := data["text"]
+		if got != tt.want {
+			t.Errorf("%s: got %q; want %q", tt.name, got.(string), tt.want)
+		}
+
+		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)
+		}
+	}
+
+	err := l.Shutdown(context.Background())
+	if err != nil {
+		t.Error(err)
+	}
+}
+
+func TestEncodeSpecialCases(t *testing.T) {
+	ts, l := NewLogtailTestHarness(t)
+
+	// -------------------------------------------------------------------------
+
+	// JSON log message already contains a logtail field.
+	io.WriteString(l, `{"logtail": "LOGTAIL", "text": "text"}`)
+	body := <-ts.uploaded
+	data := make(map[string]interface{})
+	err := json.Unmarshal(body, &data)
+	if err != nil {
+		t.Error(err)
+	}
+	errorHasLogtail, ok := data["error_has_logtail"]
+	if ok {
+		if errorHasLogtail != "LOGTAIL" {
+			t.Errorf("error_has_logtail: got:%q; want:%q",
+				errorHasLogtail, "LOGTAIL")
+		}
+	} else {
+		t.Errorf("no error_has_logtail field: %v", data)
+	}
+
+	// -------------------------------------------------------------------------
+
+	// special characters
+	io.WriteString(l, "\b\f\n\r\t"+`"\`)
+	bodytext := string(<-ts.uploaded)
+	// json.Unmarshal would unescape the characters, we have to look at the encoded text
+	escaped := strings.Contains(bodytext, `\b\f\n\r\t\"\`)
+	if !escaped {
+		t.Errorf("special characters got %s", bodytext)
+	}
+
+	// -------------------------------------------------------------------------
+
+	// skipClientTime to omit the logtail metadata
+	l.skipClientTime = true
+	io.WriteString(l, "text")
+	body = <-ts.uploaded
+	data = make(map[string]interface{})
+	err = json.Unmarshal(body, &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)
+	body = <-ts.uploaded
+	data = make(map[string]interface{})
+	err = json.Unmarshal(body, &data)
+	if err != nil {
+		t.Error(err)
+	}
+	text, ok := data["text"]
+	if !ok {
+		t.Errorf("lowMem: no text %v", data)
+	}
+	if n := len(text.(string)); n > 300 {
+		t.Errorf("lowMem: got %d chars; want <300 chars", n)
+	}
+
+	// -------------------------------------------------------------------------
+
+	err = l.Shutdown(context.Background())
+	if err != nil {
+		t.Error(err)
 	}
 }
 
@@ -75,3 +252,54 @@ 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("parseAndRemoveLogLevel(%q): got:%d; want %d",
+				tt.log, gotLevel, tt.wantLevel)
+		}
+		if string(gotLog) != tt.wantLog {
+			t.Errorf("parseAndRemoveLogLevel(%q): got:%q; want %q",
+				tt.log, gotLog, tt.wantLog)
+		}
+	}
+}