From 013da6660e971485612aa2d4f764bf453631899f Mon Sep 17 00:00:00 2001 From: Denton Gentry Date: Tue, 12 Jan 2021 13:31:45 -0800 Subject: [PATCH] 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 --- logtail/logtail_test.go | 256 +++++++++++++++++++++++++++++++++++++--- 1 file changed, 242 insertions(+), 14 deletions(-) diff --git a/logtail/logtail_test.go b/logtail/logtail_test.go index 576cc1888..b4ba8f0e0 100644 --- a/logtail/logtail_test.go +++ b/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) { - ctx, cancel := context.WithCancel(context.Background()) - uploads := 0 - testServ := httptest.NewServer(http.HandlerFunc( +// maximum number of times a test will call l.Write() +const logLines = 3 + +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") - uploads += 1 + body, err := ioutil.ReadAll(r.Body) + if err != nil { + t.Error("failed to read HTTP request") + } + ts.uploaded <- body })) - defer testServ.Close() - l := NewLogger(Config{BaseURL: testServ.URL}, t.Logf) - for i := 1; i < 10; i++ { + t.Cleanup(ts.srv.Close) + + 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) - cancel() - if uploads == 0 { - t.Error("no log uploads") + // all of the "log line" messages usually arrive at once, but poll if needed. + body := "" + for i := 0; i <= logLines; i++ { + 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) + } + } +}