transform_test.go

package log

import (
	"bytes"
	"strings"
	"testing"
	"time"
)

var upper = NewTransform(func(dst, src []byte) []byte {
	return append(dst, bytes.ToUpper(src)...)
})

var boom = NewTransform(func(dst, src []byte) []byte { panic("xform boom") })

func TestTransform(t *testing.T) {
	var buf lockedBuffer
	c := New(&buf, nil)
	c.Logger().Info("m",
		upper("u", []byte("shout")),
		upper("empty", nil),
		Str("plain", "left alone"),
	)
	if err := c.Close(); err != nil {
		t.Fatal(err)
	}
	m := parseLines(t, buf.Bytes())[0]
	if m["u"] != "SHOUT" || m["empty"] != "" || m["plain"] != "left alone" {
		t.Fatalf("got %v", m)
	}
}

func TestTransformPanicAndTruncation(t *testing.T) {
	var buf lockedBuffer
	c := New(&buf, nil)
	big := bytes.Repeat([]byte("x"), maxStrLen+100)
	c.Logger().Info("m", boom("b", []byte("v")), upper("big", big))
	if err := c.Close(); err != nil {
		t.Fatal(err)
	}
	m := parseLines(t, buf.Bytes())[0]
	if s, _ := m["b"].(string); !strings.HasPrefix(s, "!PANIC:") {
		t.Fatalf("b = %v", m["b"])
	}
	if got := len(m["big"].(string)); got != maxStrLen {
		t.Fatalf("input not capped before transform: len %d", got)
	}
}

// A Transform fn that logs while the queue is full must not deadlock: the
// consumer's own push bypasses the capacity gate (it is the only drainer).
func TestTransformLogNoSelfDeadlock(t *testing.T) {
	var buf lockedBuffer
	c := New(&buf, &Options{QueueSize: 2})
	l := c.Logger()
	inside := make(chan struct{})
	filled := make(chan struct{})
	reentrant := NewTransform(func(dst, src []byte) []byte {
		close(inside) // consumer is here; its batch is already swapped out
		<-filled
		l.Info("from transform") // queue is full: must bypass, not wait
		return append(dst, src...)
	})
	l.Info("m", reentrant("r", []byte("v")))
	<-inside
	l.Info("f1")
	l.Info("f2") // queue now at capacity while the consumer is inside fn
	close(filled)
	done := make(chan error, 1)
	go func() { done <- c.Close() }()
	select {
	case err := <-done:
		if err != nil {
			t.Fatal(err)
		}
	case <-time.After(5 * time.Second):
		t.Fatal("consumer deadlocked on its own push")
	}
	ms := parseLines(t, buf.Bytes())
	if len(ms) != 4 {
		t.Fatalf("want 4 lines, got %d: %v", len(ms), ms)
	}
	seen := map[string]bool{}
	for _, m := range ms {
		seen[m["msg"].(string)] = true
	}
	if !seen["from transform"] {
		t.Fatalf("transform's log dropped: %v", ms)
	}
}

// The transform output is escaped like any string value — it cannot break
// the JSON structure.
func TestTransformOutputEscaped(t *testing.T) {
	quoteInjector := NewTransform(func(dst, src []byte) []byte {
		return append(dst, `evil",%injected":1,"x":"`...)
	})
	var buf lockedBuffer
	c := New(&buf, nil)
	c.Logger().Info("m", quoteInjector("v", nil))
	if err := c.Close(); err != nil {
		t.Fatal(err)
	}
	m := parseLines(t, buf.Bytes())[0]
	if _, ok := m["%injected"]; ok {
		t.Fatal("transform output broke JSON structure")
	}
	if !strings.Contains(m["v"].(string), `evil"`) {
		t.Fatalf("v = %q", m["v"])
	}
}