egress-proxies-operator/internal/provider/kvm/trace_test.go

package kvm

import (
	"bytes"
	"context"
	"errors"
	"io"
	"reflect"
	"strings"
	"sync"
	"testing"

	libvirt "github.com/digitalocean/go-libvirt"
	"github.com/go-logr/logr"
	"github.com/go-logr/logr/funcr"
)

// captureLogger returns a funcr logger capped at verbosity (the test
// stand-in for --zap-log-level=<verbosity>) and a snapshot function for the
// lines it recorded. The sink is mutex-guarded: a cancelled call logs from
// the abandoned goroutine.
func captureLogger(verbosity int) (logr.Logger, func() []string) {
	var mu sync.Mutex
	var lines []string
	log := funcr.New(func(prefix, args string) {
		mu.Lock()
		defer mu.Unlock()
		lines = append(lines, prefix+" "+args)
	}, funcr.Options{Verbosity: verbosity})
	return log, func() []string {
		mu.Lock()
		defer mu.Unlock()
		return append([]string(nil), lines...)
	}
}

func captureContext(verbosity int) (context.Context, func() []string) {
	log, snapshot := captureLogger(verbosity)
	return logr.NewContext(context.Background(), log), snapshot
}

const stoppedName = "proxy-stopped"

// tracedHost is a fake with one managed running domain and its volumes, so
// every method of the seam has something to act on.
func tracedHost(t *testing.T) *fakeAPI {
	t.Helper()
	api := readyHost()
	managedDomain(t, api, testName, testUID, true, map[uint32][]libvirt.DomainInterface{
		uint32(libvirt.DomainInterfaceAddressesSrcArp): {{Name: "vnet0", Addrs: []libvirt.DomainIPAddr{ipv4("192.168.1.50")}}},
	})
	api.putDomain(&fakeDomain{name: stoppedName})
	return api
}

func TestTracingAPI_logsEveryMethod(t *testing.T) {
	t.Parallel()
	pool := libvirt.StoragePool{Name: "default"}
	dom := libvirt.Domain{Name: testName}
	overlay := libvirt.StorageVol{Pool: "default", Name: overlayVolumeName(testName)}
	cases := []struct {
		method string
		call   func(api libvirtAPI) error
	}{
		{"DomainLookupByName", func(api libvirtAPI) error { _, err := api.DomainLookupByName(testName); return err }},
		{"DomainDefineXML", func(api libvirtAPI) error {
			xml, err := buildDomainXML(testDomainParams())
			if err != nil {
				return err
			}
			_, err = api.DomainDefineXML(xml)
			return err
		}},
		{"DomainCreate", func(api libvirtAPI) error { return api.DomainCreate(libvirt.Domain{Name: stoppedName}) }},
		{"DomainDestroy", func(api libvirtAPI) error { return api.DomainDestroy(dom) }},
		{"DomainUndefineFlags", func(api libvirtAPI) error { return api.DomainUndefineFlags(dom, undefineFlags) }},
		{"DomainGetState", func(api libvirtAPI) error { _, _, err := api.DomainGetState(dom, 0); return err }},
		{"DomainGetMetadata", func(api libvirtAPI) error {
			_, err := api.DomainGetMetadata(dom, int32(libvirt.DomainMetadataElement), libvirt.OptString{metadataURI}, 0)
			return err
		}},
		{"DomainInterfaceAddresses", func(api libvirtAPI) error {
			_, err := api.DomainInterfaceAddresses(dom, uint32(libvirt.DomainInterfaceAddressesSrcArp), 0)
			return err
		}},
		{"ConnectListAllDomains", func(api libvirtAPI) error { _, _, err := api.ConnectListAllDomains(1, 0); return err }},
		{"StoragePoolLookupByName", func(api libvirtAPI) error { _, err := api.StoragePoolLookupByName("default"); return err }},
		{"StoragePoolRefresh", func(api libvirtAPI) error { return api.StoragePoolRefresh(pool, 0) }},
		{"StorageVolLookupByName", func(api libvirtAPI) error { _, err := api.StorageVolLookupByName(pool, overlay.Name); return err }},
		{"StorageVolGetPath", func(api libvirtAPI) error { _, err := api.StorageVolGetPath(overlay); return err }},
		{"StorageVolCreateXML", func(api libvirtAPI) error {
			xml, err := buildVolumeXML(rawVolume("new.iso", 3))
			if err != nil {
				return err
			}
			_, err = api.StorageVolCreateXML(pool, xml, 0)
			return err
		}},
		{"StorageVolUpload", func(api libvirtAPI) error {
			return api.StorageVolUpload(overlay, strings.NewReader("abc"), 0, 3, 0)
		}},
		{"StorageVolDownload", func(api libvirtAPI) error {
			return api.StorageVolDownload(overlay, io.Discard, 0, 0, 0)
		}},
		{"StorageVolDelete", func(api libvirtAPI) error { return api.StorageVolDelete(overlay, 0) }},
		{"ConnectGetLibVersion", func(api libvirtAPI) error { _, err := api.ConnectGetLibVersion(); return err }},
		{"ConnectGetHostname", func(api libvirtAPI) error { _, err := api.ConnectGetHostname(); return err }},
		{"StoragePoolGetInfo", func(api libvirtAPI) error { _, _, _, _, err := api.StoragePoolGetInfo(pool); return err }},
	}
	if n := reflect.TypeOf((*libvirtAPI)(nil)).Elem().NumMethod(); n != len(cases) {
		t.Fatalf("libvirtAPI has %d methods, this test covers %d; trace the new one", n, len(cases))
	}
	for _, tc := range cases {
		t.Run(tc.method, func(t *testing.T) {
			t.Parallel()
			log, snapshot := captureLogger(1)
			api := &tracingAPI{inner: tracedHost(t), log: log}
			if err := tc.call(api); err != nil {
				t.Fatalf("%s: %v", tc.method, err)
			}
			lines := snapshot()
			if len(lines) != 1 {
				t.Fatalf("logged %d lines, want exactly 1:\n%s", len(lines), strings.Join(lines, "\n"))
			}
			for _, want := range []string{`"msg"="libvirt call"`, `"rpc"="vir` + tc.method + `"`, `"duration"=`} {
				if !strings.Contains(lines[0], want) {
					t.Errorf("line missing %s:\n%s", want, lines[0])
				}
			}
			if strings.Contains(lines[0], `"error"=`) {
				t.Errorf("successful call logged an error:\n%s", lines[0])
			}
		})
	}
}

func TestTracingAPI_passesResultsThrough(t *testing.T) {
	t.Parallel()
	inner := tracedHost(t)
	log, _ := captureLogger(1)
	traced := &tracingAPI{inner: inner, log: log}
	dom := libvirt.Domain{Name: testName}

	wantState, wantReason, err := inner.DomainGetState(dom, 0)
	if err != nil {
		t.Fatal(err)
	}
	state, reason, err := traced.DomainGetState(dom, 0)
	if err != nil || state != wantState || reason != wantReason {
		t.Errorf("DomainGetState = %d/%d/%v, want %d/%d/nil", state, reason, err, wantState, wantReason)
	}

	overlay := libvirt.StorageVol{Pool: "default", Name: overlayVolumeName(testName)}
	wantPath, _ := inner.StorageVolGetPath(overlay)
	if path, err := traced.StorageVolGetPath(overlay); err != nil || path != wantPath {
		t.Errorf("StorageVolGetPath = %q/%v, want %q", path, err, wantPath)
	}

	wantDoms, _, _ := inner.ConnectListAllDomains(1, 0)
	doms, _, err := traced.ConnectListAllDomains(1, 0)
	if err != nil || !reflect.DeepEqual(doms, wantDoms) {
		t.Errorf("ConnectListAllDomains = %v/%v, want %v", doms, err, wantDoms)
	}

	inner.fail["DomainCreate"] = lvError(libvirt.ErrOperationInvalid, "already running")
	if err := traced.DomainCreate(dom); !hasCode(err, libvirt.ErrOperationInvalid) {
		t.Errorf("DomainCreate error = %v, want the injected libvirt error unchanged", err)
	}
}

func TestTracingAPI_errorFields(t *testing.T) {
	t.Parallel()
	tests := []struct {
		name    string
		inject  error
		want    []string
		notWant []string
	}{
		{
			name:   "libvirt error carries code, name and message",
			inject: lvError(libvirt.ErrNoDomain, "Domain not found: no domain with matching name"),
			want:   []string{`"error"="Domain not found`, `"libvirtError"="ErrNoDomain"`, `"libvirtCode"=42`},
		},
		{
			name:    "transport error has no libvirt fields",
			inject:  io.EOF,
			want:    []string{`"error"="EOF"`},
			notWant: []string{`"libvirtError"`, `"libvirtCode"`},
		},
	}
	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			t.Parallel()
			inner := tracedHost(t)
			inner.fail["DomainLookupByName"] = tc.inject
			log, snapshot := captureLogger(1)
			api := &tracingAPI{inner: inner, log: log}
			if _, err := api.DomainLookupByName(testName); !errors.Is(err, tc.inject) {
				t.Fatalf("error = %v, want the injected one", err)
			}
			joined := strings.Join(snapshot(), "\n")
			for _, want := range tc.want {
				if !strings.Contains(joined, want) {
					t.Errorf("output missing %s:\n%s", want, joined)
				}
			}
			for _, absent := range tc.notWant {
				if strings.Contains(joined, absent) {
					t.Errorf("output unexpectedly contains %s:\n%s", absent, joined)
				}
			}
		})
	}
}

func TestTracingAPI_detailOnlyAtV2(t *testing.T) {
	t.Parallel()
	dom := libvirt.Domain{Name: testName}
	calls := []struct {
		method string
		call   func(api libvirtAPI) error
		always string
		detail string
	}{
		{"DomainDefineXML", func(api libvirtAPI) error {
			xml, err := buildDomainXML(testDomainParams())
			if err != nil {
				return err
			}
			_, err = api.DomainDefineXML(xml)
			return err
		}, `"xmlBytes"=`, `"xml"="<domain`},
		{"StorageVolCreateXML", func(api libvirtAPI) error {
			xml, err := buildVolumeXML(rawVolume("new.iso", 3))
			if err != nil {
				return err
			}
			_, err = api.StorageVolCreateXML(libvirt.StoragePool{Name: "default"}, xml, 0)
			return err
		}, `"xmlBytes"=`, `"xml"="<volume`},
		{"DomainGetMetadata", func(api libvirtAPI) error {
			_, err := api.DomainGetMetadata(dom, int32(libvirt.DomainMetadataElement), libvirt.OptString{metadataURI}, 0)
			return err
		}, `"metadataBytes"=`, `"metadata"="<instance`},
		{"DomainInterfaceAddresses", func(api libvirtAPI) error {
			_, err := api.DomainInterfaceAddresses(dom, uint32(libvirt.DomainInterfaceAddressesSrcArp), 0)
			return err
		}, `"interfaces"=1`, `"addresses"=["vnet0=192.168.1.50/24"]`},
		{"ConnectListAllDomains", func(api libvirtAPI) error {
			_, _, err := api.ConnectListAllDomains(1, 0)
			return err
		}, `"count"=2`, `"names"=[`},
	}
	for _, verbosity := range []int{1, 2} {
		for _, tc := range calls {
			t.Run(tc.method+"/v"+string(rune('0'+verbosity)), func(t *testing.T) {
				t.Parallel()
				log, snapshot := captureLogger(verbosity)
				api := &tracingAPI{inner: tracedHost(t), log: log}
				if err := tc.call(api); err != nil {
					t.Fatal(err)
				}
				joined := strings.Join(snapshot(), "\n")
				if !strings.Contains(joined, tc.always) {
					t.Errorf("v%d output missing %s:\n%s", verbosity, tc.always, joined)
				}
				if has := strings.Contains(joined, tc.detail); has != (verbosity >= 2) {
					t.Errorf("v%d output contains %s = %v, want %v:\n%s", verbosity, tc.detail, has, verbosity >= 2, joined)
				}
			})
		}
	}
}

func TestTracingAPI_uploadLogsSizeNotContent(t *testing.T) {
	t.Parallel()
	const sentinel = "SENTINEL-seed-content-must-never-be-logged"
	log, snapshot := captureLogger(2)
	api := &tracingAPI{inner: tracedHost(t), log: log}
	vol := libvirt.StorageVol{Pool: "default", Name: seedVolumeName(testName)}
	if err := api.StorageVolUpload(vol, bytes.NewReader([]byte(sentinel)), 0, uint64(len(sentinel)), 0); err != nil {
		t.Fatal(err)
	}
	joined := strings.Join(snapshot(), "\n")
	if !strings.Contains(joined, `"length"=42`) {
		t.Errorf("upload line missing the length:\n%s", joined)
	}
	if strings.Contains(joined, sentinel) {
		t.Errorf("upload content leaked into logs:\n%s", joined)
	}
}

func TestTracingAPI_silentBelowV1(t *testing.T) {
	t.Parallel()
	log, snapshot := captureLogger(0)
	api := &tracingAPI{inner: tracedHost(t), log: log}
	if _, err := api.DomainLookupByName(testName); err != nil {
		t.Fatal(err)
	}
	if lines := snapshot(); len(lines) != 0 {
		t.Errorf("verbosity 0 logged %d lines:\n%s", len(lines), strings.Join(lines, "\n"))
	}
}