egress-proxies-operator/internal/provider/kvm2/observe_test.go

package kvm2

import (
	"context"
	"errors"
	"reflect"
	"strconv"
	"strings"
	"sync"
	"testing"

	"github.com/digitalocean/go-libvirt"
	"github.com/go-logr/logr/funcr"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/codes"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/sdk/trace/tracetest"
	logf "sigs.k8s.io/controller-runtime/pkg/log"

	"gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing"
)

// logCapture collects funcr output at a verbosity, safe for concurrent use.
type logCapture struct {
	mu    sync.Mutex
	lines []string
}

func (c *logCapture) all() []string {
	c.mu.Lock()
	defer c.mu.Unlock()
	return append([]string(nil), c.lines...)
}

func (c *logCapture) matching(substr string) []string {
	var out []string
	for _, l := range c.all() {
		if strings.Contains(l, substr) {
			out = append(out, l)
		}
	}
	return out
}

// observeFixture is a decorated fake with a span recorder and a log capture
// wired into ctx.
type observeFixture struct {
	fake *fakeBackend
	b    backend
	sr   *tracetest.SpanRecorder
	tp   *sdktrace.TracerProvider
	logs *logCapture
}

func newObserveFixture(t *testing.T, verbosity int) (*observeFixture, context.Context) {
	t.Helper()
	sr := tracetest.NewSpanRecorder()
	tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr))
	t.Cleanup(func() { _ = tp.Shutdown(context.Background()) })
	logs := &logCapture{}
	log := funcr.New(func(prefix, args string) {
		logs.mu.Lock()
		defer logs.mu.Unlock()
		logs.lines = append(logs.lines, prefix+" "+args)
	}, funcr.Options{Verbosity: verbosity})
	fake := newFakeBackend()
	fx := &observeFixture{
		fake: fake,
		b:    observe(fake, "kvm2-home", "beelink", tracing.WithTracerProvider(tp)),
		sr:   sr,
		tp:   tp,
		logs: logs,
	}
	return fx, logf.IntoContext(context.Background(), log)
}

func TestObserve_everySeamMethodInstrumented(t *testing.T) {
	t.Parallel()
	seam := reflect.TypeOf((*backend)(nil)).Elem()
	for i := range seam.NumMethod() {
		m := seam.Method(i)
		if m.Name == "Close" {
			continue
		}
		t.Run(m.Name, func(t *testing.T) {
			t.Parallel()
			fx, ctx := newObserveFixture(t, 1)
			args := make([]reflect.Value, m.Type.NumIn())
			args[0] = reflect.ValueOf(ctx)
			for j := 1; j < m.Type.NumIn(); j++ {
				args[j] = reflect.Zero(m.Type.In(j))
			}
			reflect.ValueOf(fx.b).MethodByName(m.Name).Call(args)

			ended := fx.sr.Ended()
			if len(ended) != 1 {
				t.Fatalf("got %d spans, want 1", len(ended))
			}
			if got, want := ended[0].Name(), "kvm2."+m.Name; got != want {
				t.Errorf("span name = %q, want %q", got, want)
			}
			if !hasAttr(ended[0].Attributes(), attribute.String("kvm2.host", "beelink")) {
				t.Errorf("span attributes %v lack kvm2.host", ended[0].Attributes())
			}
			lines := fx.logs.matching(`"msg"="libvirt call"`)
			if len(lines) != 1 {
				t.Fatalf("got %d 'libvirt call' lines, want 1:\n%s", len(lines), strings.Join(fx.logs.all(), "\n"))
			}
			for _, want := range []string{`"rpc"="` + m.Name + `"`, `"provider"="kvm2-home"`, `"host"="beelink"`, `"duration"=`, `"traceID"=`} {
				if !strings.Contains(lines[0], want) {
					t.Errorf("log line lacks %s: %s", want, lines[0])
				}
			}
			if fx.fake.callCount(m.Name) != 1 {
				t.Errorf("inner %s called %d times, want 1", m.Name, fx.fake.callCount(m.Name))
			}
		})
	}
}

func TestObserve_childSpansUnderParent(t *testing.T) {
	t.Parallel()
	fx, ctx := newObserveFixture(t, 1)
	ctx, parent := tracing.StartSpan(ctx, fx.tp.Tracer("test"), "provider.get")
	_, _ = fx.b.DomainLookupByName(ctx, "proxy-x")
	parent.End()

	var child sdktrace.ReadOnlySpan
	for _, s := range fx.sr.Ended() {
		if s.Name() == "kvm2.DomainLookupByName" {
			child = s
		}
	}
	if child == nil {
		t.Fatal("no kvm2.DomainLookupByName span recorded")
	}
	if child.Parent().SpanID() != parent.SpanContext().SpanID() {
		t.Errorf("child parent = %s, want %s", child.Parent().SpanID(), parent.SpanContext().SpanID())
	}
	if child.SpanContext().TraceID() != parent.SpanContext().TraceID() {
		t.Error("child is in a different trace than its parent")
	}
	if !hasAttr(child.Attributes(), attribute.String("kvm2.domain", "proxy-x")) {
		t.Errorf("child attributes %v lack kvm2.domain", child.Attributes())
	}
	lines := fx.logs.matching(`"msg"="libvirt call"`)
	if len(lines) != 1 || !strings.Contains(lines[0], `"spanID"="`+child.SpanContext().SpanID().String()+`"`) {
		t.Errorf("log line does not carry the child's spanID: %v", lines)
	}
}

func TestObserve_logsOneLinePerCallAtV1(t *testing.T) {
	t.Parallel()
	fx, ctx := newObserveFixture(t, 1)
	fx.fake.addDomain("proxy-x", libvirt.DomainRunning, "")
	pool, _ := fx.b.StoragePoolLookupByName(ctx, fakePoolName)
	_, _ = fx.b.DomainLookupByName(ctx, "proxy-x")
	_, _ = fx.b.StorageVolLookupByName(ctx, pool, "proxy-x.qcow2")

	lines := fx.logs.matching(`"msg"="libvirt call"`)
	if len(lines) != 3 {
		t.Fatalf("got %d lines, want 3:\n%s", len(lines), strings.Join(fx.logs.all(), "\n"))
	}
	if len(fx.logs.all()) != 3 {
		t.Errorf("got %d lines in total, want only the 3 call lines:\n%s", len(fx.logs.all()), strings.Join(fx.logs.all(), "\n"))
	}
	wants := []string{
		`"rpc"="StoragePoolLookupByName" "pool"="default"`,
		`"rpc"="DomainLookupByName" "domain"="proxy-x"`,
		`"rpc"="StorageVolLookupByName" "pool"="default" "volume"="proxy-x.qcow2"`,
	}
	for i, want := range wants {
		if !strings.Contains(lines[i], want) {
			t.Errorf("line %d = %s, want %s in it", i, lines[i], want)
		}
		if !strings.Contains(lines[i], `"level"=1`) {
			t.Errorf("line %d is not V(1): %s", i, lines[i])
		}
	}
}

func TestObserve_detailOnlyAtV2(t *testing.T) {
	t.Parallel()
	const xmlDoc = "<domain><name>proxy-x</name><metadata><instance><uid>u1</uid></instance></metadata></domain>"
	tests := []struct {
		name      string
		verbosity int
		wantXML   bool
	}{
		{name: "V1 has no xml", verbosity: 1, wantXML: false},
		{name: "V2 has xml", verbosity: 2, wantXML: true},
	}
	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			t.Parallel()
			fx, ctx := newObserveFixture(t, tc.verbosity)
			dom, err := fx.b.DomainDefineXML(ctx, xmlDoc)
			if err != nil {
				t.Fatalf("DomainDefineXML error = %v", err)
			}
			_, _ = fx.b.DomainGetMetadata(ctx, dom, int32(libvirt.DomainMetadataElement), libvirt.OptString{metadataURI}, 0)
			_, _, _ = fx.b.ConnectListAllDomains(ctx, 1, 0)
			all := strings.Join(fx.logs.all(), "\n")
			if got := strings.Contains(all, "<domain>"); got != tc.wantXML {
				t.Errorf("xml logged = %v, want %v:\n%s", got, tc.wantXML, all)
			}
			if got := strings.Contains(all, `"metadata"="<instance>`); got != tc.wantXML {
				t.Errorf("metadata logged = %v, want %v:\n%s", got, tc.wantXML, all)
			}
			if got := strings.Contains(all, `"domains"=["proxy-x"]`); got != tc.wantXML {
				t.Errorf("domain names logged = %v, want %v:\n%s", got, tc.wantXML, all)
			}
			if got := len(fx.logs.matching(`"msg"="libvirt call"`)); got != 3 {
				t.Errorf("got %d call lines, want 3", got)
			}
		})
	}
}

func TestObserve_uploadBodyNeverLogged(t *testing.T) {
	t.Parallel()
	const sentinel = "SENTINEL-CLOUDINIT-3c7a"
	fx, ctx := newObserveFixture(t, 2)
	pool, _ := fx.b.StoragePoolLookupByName(ctx, fakePoolName)
	vol, err := fx.b.StorageVolCreateXML(ctx, pool, "<volume><name>proxy-x-seed.iso</name><capacity>1024</capacity></volume>", 0)
	if err != nil {
		t.Fatalf("StorageVolCreateXML error = %v", err)
	}
	body := "#cloud-config\npassword: " + sentinel + "\n"
	if err := fx.b.StorageVolUpload(ctx, vol, strings.NewReader(body), 0, uint64(len(body)), 0); err != nil {
		t.Fatalf("StorageVolUpload error = %v", err)
	}
	var sink strings.Builder
	if err := fx.b.StorageVolDownload(ctx, vol, &sink, 0, 0, 0); err != nil {
		t.Fatalf("StorageVolDownload error = %v", err)
	}
	if sink.String() != body {
		t.Errorf("downloaded %q, want the uploaded body", sink.String())
	}
	all := strings.Join(fx.logs.all(), "\n")
	if strings.Contains(all, sentinel) {
		t.Errorf("upload body leaked into logs:\n%s", all)
	}
	uploads := fx.logs.matching(`"rpc"="StorageVolUpload"`)
	if len(uploads) != 1 || !strings.Contains(uploads[0], `"length"=`+strconv.Itoa(len(body))) {
		t.Errorf("upload line lacks length: %v", uploads)
	}
	for _, s := range fx.sr.Ended() {
		for _, a := range s.Attributes() {
			if strings.Contains(a.Value.Emit(), sentinel) {
				t.Errorf("span %s attribute %s carries the body", s.Name(), a.Key)
			}
		}
	}
}

func TestObserve_errorFieldsOnFailure(t *testing.T) {
	t.Parallel()
	fx, ctx := newObserveFixture(t, 1)
	_, err := fx.b.DomainLookupByName(ctx, "missing")
	if !hasCode(err, libvirt.ErrNoDomain) {
		t.Fatalf("error = %v, want ErrNoDomain through the decorator", err)
	}
	lines := fx.logs.matching(`"msg"="libvirt call"`)
	if len(lines) != 1 {
		t.Fatalf("got %d lines, want 1", len(lines))
	}
	for _, want := range []string{`"error"="Domain not found`, `"libvirtCode"=42`, `"libvirtError"="ErrNoDomain"`} {
		if !strings.Contains(lines[0], want) {
			t.Errorf("line lacks %s: %s", want, lines[0])
		}
	}
	ended := fx.sr.Ended()
	if len(ended) != 1 {
		t.Fatalf("got %d spans, want 1", len(ended))
	}
	if ended[0].Status().Code != codes.Error {
		t.Errorf("span status = %v, want Error", ended[0].Status().Code)
	}
	if !hasAttr(ended[0].Attributes(), attribute.Int("kvm2.libvirt_code", 42)) {
		t.Errorf("span attributes %v lack kvm2.libvirt_code=42", ended[0].Attributes())
	}

	fx.fake.failWith("ConnectGetHostname", errors.New("plain failure"))
	_, _ = fx.b.ConnectGetHostname(ctx)
	lines = fx.logs.matching(`"rpc"="ConnectGetHostname"`)
	if len(lines) != 1 || strings.Contains(lines[0], "libvirtCode") || !strings.Contains(lines[0], `"error"="plain failure"`) {
		t.Errorf("non-libvirt failure line = %v, want error without libvirt fields", lines)
	}
}

func TestObserve_v0Silent(t *testing.T) {
	t.Parallel()
	fx, ctx := newObserveFixture(t, 0)
	fx.fake.addDomain("proxy-x", libvirt.DomainRunning, "")
	_, _ = fx.b.DomainLookupByName(ctx, "proxy-x")
	_, _ = fx.b.DomainLookupByName(ctx, "missing")
	if lines := fx.logs.all(); len(lines) != 0 {
		t.Errorf("got %d lines at V(0), want none:\n%s", len(lines), strings.Join(lines, "\n"))
	}
	if got := len(fx.sr.Ended()); got != 2 {
		t.Errorf("got %d spans, want 2: spans do not depend on verbosity", got)
	}
}

func TestObserve_closeAndLivenessPassThrough(t *testing.T) {
	t.Parallel()
	fx, _ := newObserveFixture(t, 1)
	if isDead(fx.b) {
		t.Error("decorated live backend reported dead")
	}
	fx.fake.markDead()
	if !isDead(fx.b) {
		t.Error("decorated dead backend reported live")
	}
	if err := fx.b.Close(); err != nil || fx.fake.closed != 1 {
		t.Errorf("Close() = %v, closed %d times, want nil and 1", err, fx.fake.closed)
	}
	if got := len(fx.sr.Ended()); got != 0 {
		t.Errorf("Close produced %d spans, want none", got)
	}
	if lines := fx.logs.all(); len(lines) != 0 {
		t.Errorf("Close produced log lines: %v", lines)
	}
}

func hasAttr(attrs []attribute.KeyValue, want attribute.KeyValue) bool {
	for _, a := range attrs {
		if a.Key == want.Key && a.Value == want.Value {
			return true
		}
	}
	return false
}