mirror of https://github.com/tailscale/tailscale/
You cannot select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
489 lines
12 KiB
Go
489 lines
12 KiB
Go
// Copyright (c) Tailscale Inc & AUTHORS
|
|
// SPDX-License-Identifier: BSD-3-Clause
|
|
|
|
package logtail
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"encoding/json"
|
|
"io"
|
|
"net/http"
|
|
"net/http/httptest"
|
|
"strings"
|
|
"testing"
|
|
"time"
|
|
|
|
"tailscale.com/envknob"
|
|
"tailscale.com/tstest"
|
|
"tailscale.com/tstime"
|
|
)
|
|
|
|
func TestFastShutdown(t *testing.T) {
|
|
ctx, cancel := context.WithCancel(context.Background())
|
|
cancel()
|
|
|
|
testServ := httptest.NewServer(http.HandlerFunc(
|
|
func(w http.ResponseWriter, r *http.Request) {}))
|
|
defer testServ.Close()
|
|
|
|
l := NewLogger(Config{
|
|
BaseURL: testServ.URL,
|
|
}, t.Logf)
|
|
err := l.Shutdown(ctx)
|
|
if err != nil {
|
|
t.Error(err)
|
|
}
|
|
}
|
|
|
|
// 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) {
|
|
body, err := io.ReadAll(r.Body)
|
|
if err != nil {
|
|
t.Error("failed to read HTTP request")
|
|
}
|
|
ts.uploaded <- body
|
|
}))
|
|
|
|
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"))
|
|
}
|
|
|
|
// 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 := unmarshalOne(t, body)
|
|
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]any)
|
|
_, 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 := unmarshalOne(t, body)
|
|
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 = unmarshalOne(t, body)
|
|
_, 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", 5120)
|
|
io.WriteString(l, longStr)
|
|
body = <-ts.uploaded
|
|
data = unmarshalOne(t, body)
|
|
text, ok := data["text"]
|
|
if !ok {
|
|
t.Errorf("lowMem: no text %v", data)
|
|
}
|
|
if n := len(text.(string)); n > 4500 {
|
|
t.Errorf("lowMem: got %d chars; want <4500 chars", n)
|
|
}
|
|
|
|
// -------------------------------------------------------------------------
|
|
|
|
err := l.Shutdown(context.Background())
|
|
if err != nil {
|
|
t.Error(err)
|
|
}
|
|
}
|
|
|
|
var sink []byte
|
|
|
|
func TestLoggerEncodeTextAllocs(t *testing.T) {
|
|
lg := &Logger{clock: tstime.StdClock{}}
|
|
inBuf := []byte("some text to encode")
|
|
procID := uint32(0x24d32ee9)
|
|
procSequence := uint64(0x12346)
|
|
err := tstest.MinAllocsPerRun(t, 1, func() {
|
|
sink = lg.encodeText(inBuf, false, procID, procSequence, 0)
|
|
})
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
}
|
|
|
|
func TestLoggerWriteLength(t *testing.T) {
|
|
lg := &Logger{
|
|
clock: tstime.StdClock{},
|
|
buffer: NewMemoryBuffer(1024),
|
|
}
|
|
inBuf := []byte("some text to encode")
|
|
n, err := lg.Write(inBuf)
|
|
if err != nil {
|
|
t.Error(err)
|
|
}
|
|
if n != len(inBuf) {
|
|
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",
|
|
},
|
|
{
|
|
"some ignored text then [v\x00JSON]5{\"foo\":1234}",
|
|
5,
|
|
`{"foo":1234}`,
|
|
},
|
|
}
|
|
|
|
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)
|
|
}
|
|
}
|
|
}
|
|
|
|
func unmarshalOne(t *testing.T, body []byte) map[string]any {
|
|
t.Helper()
|
|
var entries []map[string]any
|
|
err := json.Unmarshal(body, &entries)
|
|
if err != nil {
|
|
t.Error(err)
|
|
}
|
|
if len(entries) != 1 {
|
|
t.Fatalf("expected one entry, got %d", len(entries))
|
|
}
|
|
return entries[0]
|
|
}
|
|
|
|
func TestEncodeTextTruncation(t *testing.T) {
|
|
lg := &Logger{clock: tstime.StdClock{}, lowMem: true}
|
|
in := bytes.Repeat([]byte("a"), 5120)
|
|
b := lg.encodeText(in, true, 0, 0, 0)
|
|
got := string(b)
|
|
want := `{"text": "` + strings.Repeat("a", 4096) + `…+1024"}` + "\n"
|
|
if got != want {
|
|
t.Errorf("got:\n%qwant:\n%q\n", got, want)
|
|
}
|
|
}
|
|
|
|
type simpleMemBuf struct {
|
|
Buffer
|
|
buf bytes.Buffer
|
|
}
|
|
|
|
func (b *simpleMemBuf) Write(p []byte) (n int, err error) { return b.buf.Write(p) }
|
|
|
|
func TestEncode(t *testing.T) {
|
|
tests := []struct {
|
|
in string
|
|
want string
|
|
}{
|
|
{
|
|
"normal",
|
|
`{"logtail": {"client_time": "1970-01-01T00:02:03.000000456Z","proc_id": 7,"proc_seq": 1}, "text": "normal"}` + "\n",
|
|
},
|
|
{
|
|
"and a [v1] level one",
|
|
`{"logtail": {"client_time": "1970-01-01T00:02:03.000000456Z","proc_id": 7,"proc_seq": 1}, "v":1,"text": "and a level one"}` + "\n",
|
|
},
|
|
{
|
|
"[v2] some verbose two",
|
|
`{"logtail": {"client_time": "1970-01-01T00:02:03.000000456Z","proc_id": 7,"proc_seq": 1}, "v":2,"text": "some verbose two"}` + "\n",
|
|
},
|
|
{
|
|
"{}",
|
|
`{"logtail":{"client_time":"1970-01-01T00:02:03.000000456Z","proc_id":7,"proc_seq":1}}` + "\n",
|
|
},
|
|
{
|
|
`{"foo":"bar"}`,
|
|
`{"foo":"bar","logtail":{"client_time":"1970-01-01T00:02:03.000000456Z","proc_id":7,"proc_seq":1}}` + "\n",
|
|
},
|
|
{
|
|
"foo: [v\x00JSON]0{\"foo\":1}",
|
|
"{\"foo\":1,\"logtail\":{\"client_time\":\"1970-01-01T00:02:03.000000456Z\",\"proc_id\":7,\"proc_seq\":1}}\n",
|
|
},
|
|
{
|
|
"foo: [v\x00JSON]2{\"foo\":1}",
|
|
"{\"foo\":1,\"logtail\":{\"client_time\":\"1970-01-01T00:02:03.000000456Z\",\"proc_id\":7,\"proc_seq\":1},\"v\":2}\n",
|
|
},
|
|
}
|
|
for _, tt := range tests {
|
|
buf := new(simpleMemBuf)
|
|
lg := &Logger{
|
|
clock: tstest.NewClock(tstest.ClockOpts{Start: time.Unix(123, 456).UTC()}),
|
|
buffer: buf,
|
|
procID: 7,
|
|
procSequence: 1,
|
|
}
|
|
io.WriteString(lg, tt.in)
|
|
got := buf.buf.String()
|
|
if got != tt.want {
|
|
t.Errorf("for %q,\n got: %#q\nwant: %#q\n", tt.in, got, tt.want)
|
|
}
|
|
if err := json.Compact(new(bytes.Buffer), buf.buf.Bytes()); err != nil {
|
|
t.Errorf("invalid output JSON for %q: %s", tt.in, got)
|
|
}
|
|
}
|
|
}
|
|
|
|
// Test that even if Logger.Write modifies the input buffer, we still return the
|
|
// length of the input buffer, not what we shrank it down to. Otherwise the
|
|
// caller will think we did a short write, violating the io.Writer contract.
|
|
func TestLoggerWriteResult(t *testing.T) {
|
|
buf := NewMemoryBuffer(100)
|
|
lg := &Logger{
|
|
clock: tstest.NewClock(tstest.ClockOpts{Start: time.Unix(123, 0)}),
|
|
buffer: buf,
|
|
}
|
|
|
|
const in = "[v1] foo"
|
|
n, err := lg.Write([]byte(in))
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if got, want := n, len(in); got != want {
|
|
t.Errorf("Write = %v; want %v", got, want)
|
|
}
|
|
back, err := buf.TryReadLine()
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if got, want := string(back), `{"logtail": {"client_time": "1970-01-01T00:02:03Z"}, "v":1,"text": "foo"}`+"\n"; got != want {
|
|
t.Errorf("mismatch.\n got: %#q\nwant: %#q", back, want)
|
|
}
|
|
}
|
|
func TestRedact(t *testing.T) {
|
|
envknob.Setenv("TS_OBSCURE_LOGGED_IPS", "true")
|
|
tests := []struct {
|
|
in string
|
|
want string
|
|
}{
|
|
// tests for ipv4 addresses
|
|
{
|
|
"120.100.30.47",
|
|
"120.100.x.x",
|
|
},
|
|
{
|
|
"192.167.0.1/65",
|
|
"192.167.x.x/65",
|
|
},
|
|
{
|
|
"node [5Btdd] d:e89a3384f526d251 now using 10.0.0.222:41641 mtu=1360 tx=d81a8a35a0ce",
|
|
"node [5Btdd] d:e89a3384f526d251 now using 10.0.x.x:41641 mtu=1360 tx=d81a8a35a0ce",
|
|
},
|
|
//tests for ipv6 addresses
|
|
{
|
|
"2001:0db8:85a3:0000:0000:8a2e:0370:7334",
|
|
"2001:0db8:x",
|
|
},
|
|
{
|
|
"2345:0425:2CA1:0000:0000:0567:5673:23b5",
|
|
"2345:0425:x",
|
|
},
|
|
{
|
|
"2601:645:8200:edf0::c9de/64",
|
|
"2601:645:x/64",
|
|
},
|
|
{
|
|
"node [5Btdd] d:e89a3384f526d251 now using 2051:0000:140F::875B:131C mtu=1360 tx=d81a8a35a0ce",
|
|
"node [5Btdd] d:e89a3384f526d251 now using 2051:0000:x mtu=1360 tx=d81a8a35a0ce",
|
|
},
|
|
{
|
|
"2601:645:8200:edf0::c9de/64 2601:645:8200:edf0:1ce9:b17d:71f5:f6a3/64",
|
|
"2601:645:x/64 2601:645:x/64",
|
|
},
|
|
//tests for tailscale ip addresses
|
|
{
|
|
"100.64.5.6",
|
|
"100.64.5.6",
|
|
},
|
|
{
|
|
"fd7a:115c:a1e0::/96",
|
|
"fd7a:115c:a1e0::/96",
|
|
},
|
|
//tests for ipv6 and ipv4 together
|
|
{
|
|
"192.167.0.1 2001:0db8:85a3:0000:0000:8a2e:0370:7334",
|
|
"192.167.x.x 2001:0db8:x",
|
|
},
|
|
{
|
|
"node [5Btdd] d:e89a3384f526d251 now using 10.0.0.222:41641 mtu=1360 tx=d81a8a35a0ce 2345:0425:2CA1::0567:5673:23b5",
|
|
"node [5Btdd] d:e89a3384f526d251 now using 10.0.x.x:41641 mtu=1360 tx=d81a8a35a0ce 2345:0425:x",
|
|
},
|
|
{
|
|
"100.64.5.6 2091:0db8:85a3:0000:0000:8a2e:0370:7334",
|
|
"100.64.5.6 2091:0db8:x",
|
|
},
|
|
{
|
|
"192.167.0.1 120.100.30.47 2041:0000:140F::875B:131B",
|
|
"192.167.x.x 120.100.x.x 2041:0000:x",
|
|
},
|
|
{
|
|
"fd7a:115c:a1e0::/96 192.167.0.1 2001:0db8:85a3:0000:0000:8a2e:0370:7334",
|
|
"fd7a:115c:a1e0::/96 192.167.x.x 2001:0db8:x",
|
|
},
|
|
}
|
|
|
|
for _, tt := range tests {
|
|
gotBuf := redactIPs([]byte(tt.in))
|
|
if string(gotBuf) != tt.want {
|
|
t.Errorf("for %q,\n got: %#q\nwant: %#q\n", tt.in, gotBuf, tt.want)
|
|
}
|
|
}
|
|
}
|