//go:build integration package kvm2 import ( "context" "crypto/rand" "encoding/hex" "errors" "fmt" "net" "os" "strconv" "strings" "sync" "testing" "time" "github.com/digitalocean/go-libvirt" "github.com/go-logr/logr" "github.com/go-logr/logr/funcr" sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/sdk/trace/tracetest" "k8s.io/apimachinery/pkg/types" logf "sigs.k8s.io/controller-runtime/pkg/log" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" ) // The real-hypervisor test of spec entry 21. It runs only with // -tags=integration and skips itself unless KVM2_TEST_* names a host; see // docs/testing.md for the variables and what one run asserts. const ( integrationProvider = "kvm2-integration" integrationHost = "kvm2-test" integrationImage = "test-image" integrationMachine = "small" integrationPort = 3128 // integrationCloudInit is the user-data the VM boots with. Nothing // asserts on the guest running it; it exists so the sentinel check can // prove that no span attribute carries the cloud-init text. integrationCloudInit = "#cloud-config\nruncmd:\n - echo kvm2-integration\n" defaultIntegrationTimeout = 20 * time.Minute defaultIntegrationLogLvl = 1 getPollInterval = 5 * time.Second cleanupBudget = 5 * time.Minute ) type integrationEnv struct { host, user, sshKey, knownHosts, bridge, imageURL string imageSHA256, pool, socket string timeout time.Duration keep bool logLevel int } // loadIntegrationEnv reads the KVM2_TEST_* variables, skipping the test // under -short or when a required one is missing. func loadIntegrationEnv(t *testing.T) integrationEnv { t.Helper() if testing.Short() { t.Skip("real-hypervisor test skipped under -short") } env := integrationEnv{timeout: defaultIntegrationTimeout, logLevel: defaultIntegrationLogLvl} required := []struct { name string dst *string }{ {"KVM2_TEST_HOST", &env.host}, {"KVM2_TEST_USER", &env.user}, {"KVM2_TEST_SSH_KEY", &env.sshKey}, {"KVM2_TEST_BRIDGE", &env.bridge}, {"KVM2_TEST_IMAGE_URL", &env.imageURL}, } for _, r := range required { v := os.Getenv(r.name) if v == "" { t.Skipf("%s is not set; the kvm2 integration test needs a real hypervisor (see docs/testing.md)", r.name) } *r.dst = v } env.knownHosts = os.Getenv("KVM2_TEST_KNOWN_HOSTS") env.imageSHA256 = os.Getenv("KVM2_TEST_IMAGE_SHA256") env.pool = os.Getenv("KVM2_TEST_POOL") env.socket = os.Getenv("KVM2_TEST_SOCKET") env.keep = os.Getenv("KVM2_TEST_KEEP") != "" if v := os.Getenv("KVM2_TEST_TIMEOUT"); v != "" { d, err := time.ParseDuration(v) if err != nil { t.Fatalf("KVM2_TEST_TIMEOUT=%q: %v", v, err) } env.timeout = d } if v := os.Getenv("KVM2_TEST_LOG_LEVEL"); v != "" { n, err := strconv.Atoi(v) if err != nil || n < 0 { t.Fatalf("KVM2_TEST_LOG_LEVEL=%q: want a non-negative integer", v) } env.logLevel = n } return env } // providerConfig is what the operator would load for this host: one host, // one image, one machine type. Host keys are verified only when // KVM2_TEST_KNOWN_HOSTS is set. func (e integrationEnv) providerConfig() provider.ProviderConfig { return provider.ProviderConfig{ Name: integrationProvider, Type: "kvm2", KVM2: &provider.KVMConfig{ SSHKeyFile: e.sshKey, KnownHostsFile: e.knownHosts, InsecureIgnoreHostKey: e.knownHosts == "", Images: map[string]provider.KVMImage{ integrationImage: {URL: e.imageURL, SHA256: e.imageSHA256}, }, MachineTypes: map[string]provider.KVMMachineType{ integrationMachine: {VCPUs: 1, MemoryMiB: 1024}, }, Hosts: []provider.KVMHost{{ Name: integrationHost, Address: e.host, User: e.user, Socket: e.socket, Pool: e.pool, Bridge: e.bridge, }}, }, } } // integrationLog routes the provider's logr output into t.Log through funcr // at the chosen verbosity, keeps every line for assertions, and strips the // key/value pairs that are constant for the run (stated once up front) so // each line stays short. Lines arriving after the test ended are dropped: // t.Log panics then. type integrationLog struct { t *testing.T mu sync.Mutex drop []string lines []string done bool } func newIntegrationLog(t *testing.T, level int, drop ...string) (*integrationLog, logr.Logger) { t.Helper() sink := &integrationLog{t: t, drop: drop} t.Cleanup(func() { sink.mu.Lock() defer sink.mu.Unlock() sink.done = true }) log := funcr.New(func(prefix, args string) { sink.write(prefix, args) }, funcr.Options{Verbosity: level}) return sink, log } // dropValue adds a rendered pair (`"key"="value"`) to strip from later lines. func (l *integrationLog) dropValue(key, value string) { l.mu.Lock() defer l.mu.Unlock() l.drop = append(l.drop, fmt.Sprintf("%q=%q", key, value)) } func (l *integrationLog) write(prefix, args string) { l.mu.Lock() defer l.mu.Unlock() l.lines = append(l.lines, args) if l.done { return } for _, d := range l.drop { args = strings.ReplaceAll(args, " "+d, "") } l.t.Logf("%s %s %s", time.Now().Format("15:04:05.000"), prefix, args) } func (l *integrationLog) matching(substr string) []string { l.mu.Lock() defer l.mu.Unlock() var out []string for _, line := range l.lines { if strings.Contains(line, substr) { out = append(out, line) } } return out } // newIntegrationProvider builds the provider the way New does, plus the span // recorder's tracer on both places the package starts spans: the Provider // (kvm2.download) and the dialer (kvm2.dial and, through observe, every // kvm2.). newLibvirtDialer has no option for it, so the field is set // directly; that is what makes the kvm2.* spans land in the same recorder // as provider.WithTracing's provider.* spans. func newIntegrationProvider(pc provider.ProviderConfig, tp *sdktrace.TracerProvider) *Provider { cfg := withDefaults(*pc.KVM2) opt := tracing.WithTracerProvider(tp) d := newLibvirtDialer(pc.Name, cfg) d.tracing = []tracing.Option{opt} return newProvider(pc.Name, cfg, d, withTracing(opt)) } // randomUID is a UUID-shaped string, so the run's domain never collides with // a previous run's leftovers or with a real Proxy's. func randomUID(t *testing.T) string { t.Helper() var b [16]byte if _, err := rand.Read(b[:]); err != nil { t.Fatalf("reading random bytes: %v", err) } h := hex.EncodeToString(b[:]) return h[0:8] + "-" + h[8:12] + "-" + h[12:16] + "-" + h[16:20] + "-" + h[20:32] } // stepDone logs one lifecycle step with its duration; the log is the record // of how long a cold image download or a boot took on this host. func stepDone(t *testing.T, step string, start time.Time) { t.Helper() t.Logf("step %s: %s", step, time.Since(start).Round(time.Millisecond)) } // waitUntil polls cond every interval until it is true or ctx ends. func waitUntil(ctx context.Context, t *testing.T, interval time.Duration, what string, cond func() bool) { t.Helper() ticker := time.NewTicker(interval) defer ticker.Stop() for !cond() { select { case <-ticker.C: case <-ctx.Done(): t.Fatalf("gave up waiting for %s: %v", what, ctx.Err()) } } } // domainCount lists every domain on the host over a dedicated connection. func domainCount(ctx context.Context, t *testing.T, p *Provider, host provider.KVMHost) int { t.Helper() be, err := p.hosts.dialFresh(ctx, host) if err != nil { t.Fatalf("dialling %s to count domains: %v", host.Name, err) } defer func() { _ = be.Close() }() doms, _, err := be.ConnectListAllDomains(ctx, 1, libvirt.ConnectListDomainsActive|libvirt.ConnectListDomainsInactive) if err != nil { t.Fatalf("listing domains on %s: %v", host.Name, err) } return len(doms) } // poolVolumes reports, for each name, whether the host's pool holds a volume // of that name, over a dedicated connection. Any error other than // ErrNoStorageVol fails the test. func poolVolumes(ctx context.Context, t *testing.T, p *Provider, host provider.KVMHost, names ...string) map[string]bool { t.Helper() be, err := p.hosts.dialFresh(ctx, host) if err != nil { t.Fatalf("dialling %s to inspect the pool: %v", host.Name, err) } defer func() { _ = be.Close() }() pool, err := be.StoragePoolLookupByName(ctx, host.Pool) if err != nil { t.Fatalf("looking up pool %s: %v", host.Pool, err) } out := make(map[string]bool, len(names)) for _, name := range names { _, err := be.StorageVolLookupByName(ctx, pool, name) switch { case err == nil: out[name] = true case hasCode(err, libvirt.ErrNoStorageVol): out[name] = false default: t.Fatalf("looking up volume %s in pool %s: %v", name, host.Pool, err) } } return out } func TestKVM2_lifecycle(t *testing.T) { env := loadIntegrationEnv(t) pc := env.providerConfig() sink, log := newIntegrationLog(t, env.logLevel, fmt.Sprintf("%q=%q", "provider", integrationProvider), fmt.Sprintf("%q=%q", "host", integrationHost)) ctx, cancel := context.WithTimeout(logf.IntoContext(context.Background(), log), env.timeout) defer cancel() t.Logf("provider=%s host=%s address=%s user=%s bridge=%s image=%s budget=%s log level %d; provider, host and name are left off every provider log line", integrationProvider, integrationHost, env.host, env.user, env.bridge, env.imageURL, env.timeout, env.logLevel) if env.knownHosts == "" { t.Log("KVM2_TEST_KNOWN_HOSTS is not set: host keys are NOT verified for this run") } // 1. New returns without dialling. start := time.Now() built, err := New(ctx, pc) elapsed := time.Since(start) if err != nil { t.Fatalf("New() error = %v", err) } if elapsed > 100*time.Millisecond { t.Errorf("New() took %s, want under 100ms: it must not dial", elapsed) } if lines := sink.matching("libvirt host connected"); len(lines) > 0 { t.Errorf("New() dialled the host before any call: %q", lines) } stepDone(t, "1 New", start) // 2. Check reports the host Ready with details. checker, ok := built.(provider.Checker) if !ok { t.Fatalf("New() returned %T, which is not a provider.Checker", built) } start = time.Now() targets := checker.Check(ctx) if len(targets) != 1 { t.Fatalf("Check() returned %d targets, want 1: %+v", len(targets), targets) } ts := targets[0] if !ts.Ready || ts.Reason != provider.ReasonReachable { t.Fatalf("Check() = ready %v reason %q message %q, want Ready/%s (details %v)", ts.Ready, ts.Reason, ts.Message, provider.ReasonReachable, ts.Details) } for _, key := range []string{"hostname", "libvirtVersion", "poolState", "poolAvailableGiB"} { if ts.Details[key] == "" { t.Errorf("Check() details lack %q: %v", key, ts.Details) } } if ts.Details["poolState"] != "running" { t.Errorf("Check() poolState = %q, want running", ts.Details["poolState"]) } t.Logf("host %s: hostname=%s libvirt=%s pool=%s (%s) available=%s GiB capacity=%s GiB latency=%s", ts.Name, ts.Details["hostname"], ts.Details["libvirtVersion"], ts.Details["pool"], ts.Details["poolState"], ts.Details["poolAvailableGiB"], ts.Details["poolCapacityGiB"], ts.Latency.Round(time.Millisecond)) stepDone(t, "2 Check", start) // 3. Every later call goes through the tracing decorator, with the // package's own spans recorded alongside. sr := tracetest.NewSpanRecorder() tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) p := newIntegrationProvider(pc, tp) traced := provider.WithTracing(pc.Name, p, tracing.WithTracerProvider(tp)) host := p.cfg.Hosts[0] // 4. Create. uid := randomUID(t) name := provider.NameFromUID(types.UID(uid)) sink.dropValue("name", name) id := formatProviderID(integrationHost, name) req := provider.CreateRequest{ Name: name, UID: uid, Namespace: "integration", ProxyName: "kvm2-lifecycle", Placement: provider.Placement{Zone: integrationHost, MachineType: integrationMachine, Image: integrationImage}, CloudInit: integrationCloudInit, Port: integrationPort, } t.Logf("domain name %s, uid %s, id %s", name, uid, id) deleted := false if env.keep { t.Logf("KVM2_TEST_KEEP is set: the VM stays behind. Clean up on the host with:\n"+ " virsh undefine --nvram %s\n virsh vol-delete --pool %s %s\n virsh vol-delete --pool %s %s", name, host.Pool, overlayVolumeName(name), host.Pool, seedVolumeName(name)) } else { t.Cleanup(func() { if deleted { return } cctx, ccancel := context.WithTimeout(logf.IntoContext(context.Background(), log), cleanupBudget) defer ccancel() if err := p.Delete(cctx, id); err != nil { t.Errorf("cleanup Delete(%s) error = %v; remove the domain and its volumes by hand", id, err) } }) } start = time.Now() gotID, err := traced.Create(ctx, req) if err != nil { t.Fatalf("Create() error = %v", err) } if gotID != id { t.Fatalf("Create() = %q, want %q", gotID, id) } createReturned := time.Now() stepDone(t, "4 Create (includes the image download on a cold pool)", start) // 5. Create again: same ID, nothing new on the host. start = time.Now() before := domainCount(ctx, t, p, host) again, err := traced.Create(ctx, req) if err != nil { t.Fatalf("second Create() error = %v", err) } if again != id { t.Errorf("second Create() = %q, want %q", again, id) } if after := domainCount(ctx, t, p, host); after != before { t.Errorf("second Create() changed the host's domain count from %d to %d", before, after) } stepDone(t, "5 Create again", start) // 6. Get reaches Running with an IPv4. start = time.Now() var inst *provider.Instance waitUntil(ctx, t, getPollInterval, "the domain to be Running with an IPv4", func() bool { var err error inst, err = traced.Get(ctx, id) if err != nil { t.Fatalf("Get(%s) error = %v", id, err) } return inst.State == provider.StateRunning && inst.IP != "" }) if inst.UID != uid { t.Errorf("Get() UID = %q, want %q", inst.UID, uid) } if inst.CreatedAt.IsZero() { t.Error("Get() CreatedAt is zero; the metadata mark did not round-trip") } else if skew := time.Since(inst.CreatedAt).Abs(); skew > 5*time.Minute { t.Errorf("Get() CreatedAt = %s, %s from now; want within a few minutes", inst.CreatedAt, skew) } t.Logf("domain running at %s, %s after Create returned (createdAt %s)", inst.IP, time.Since(createReturned).Round(time.Millisecond), inst.CreatedAt.Format(time.RFC3339)) stepDone(t, "6 Get until Running", start) // 7. ListByTag contains it. start = time.Now() list, err := traced.ListByTag(ctx) if err != nil { t.Fatalf("ListByTag() error = %v", err) } found := false for _, li := range list { if li.ID == id { found = true if li.UID != uid { t.Errorf("ListByTag() entry %s has UID %q, want %q", id, li.UID, uid) } } } if !found { t.Errorf("ListByTag() = %d instances, none with ID %s", len(list), id) } stepDone(t, "7 ListByTag", start) // 8. Reachability, logged only: this machine may not route to the bridge. start = time.Now() addr := net.JoinHostPort(inst.IP, "22") if conn, err := net.DialTimeout("tcp", addr, 3*time.Second); err != nil { t.Logf("TCP connect to %s failed (informational; the test host may not route to the bridge): %v", addr, err) } else { _ = conn.Close() t.Logf("TCP connect to %s succeeded", addr) } stepDone(t, "8 TCP connect", start) if env.keep { t.Log("KVM2_TEST_KEEP is set: skipping Delete and the pool inspection") } else { // 9. Delete, Get is NotFound, Delete again. start = time.Now() if err := traced.Delete(ctx, id); err != nil { t.Fatalf("Delete() error = %v", err) } deleted = true if _, err := traced.Get(ctx, id); !errors.Is(err, provider.ErrNotFound) { t.Errorf("Get() after Delete error = %v, want ErrNotFound", err) } if err := traced.Delete(ctx, id); err != nil { t.Errorf("second Delete() error = %v, want nil", err) } stepDone(t, "9 Delete, Get, Delete", start) // 10. The pool keeps the shared base image and its marker, and holds // no per-VM volume. start = time.Now() base := baseVolumeName(integrationProvider, integrationImage, provider.KVMFormatQcow2) marker := markerVolumeName(base) overlay, seed := overlayVolumeName(name), seedVolumeName(name) present := poolVolumes(ctx, t, p, host, base, marker, overlay, seed) for _, want := range []string{base, marker} { if !present[want] { t.Errorf("pool %s lacks %s after Delete; the base image cache must stay", host.Pool, want) } } for _, gone := range []string{overlay, seed} { if present[gone] { t.Errorf("pool %s still holds %s after Delete", host.Pool, gone) } } stepDone(t, "10 pool inspection", start) } // 11. Spans: the package's spans are children of the decorator's. assertLifecycleSpans(t, sr.Ended()) } // assertLifecycleSpans checks that at least one provider.create span has a // kvm2.DomainDefineXML and a kvm2.dial child (the first Create dials the // pooled connection and defines the domain), and that no attribute of any // span carries the cloud-init text. func assertLifecycleSpans(t *testing.T, spans []sdktrace.ReadOnlySpan) { t.Helper() var creates []sdktrace.ReadOnlySpan for _, s := range spans { if s.Name() == "provider.create" { creates = append(creates, s) } } if len(creates) == 0 { t.Fatalf("no provider.create span among %d spans: %v", len(spans), spanNames(spans)) } satisfied := false for _, create := range creates { parent := create.SpanContext().SpanID() var children, define, dial int for _, s := range spans { if s.Parent().SpanID() != parent || !strings.HasPrefix(s.Name(), "kvm2.") { continue } children++ switch s.Name() { case "kvm2.DomainDefineXML": define++ case "kvm2.dial": dial++ } } t.Logf("provider.create span %s: %d kvm2.* children (%d DomainDefineXML, %d dial)", parent, children, define, dial) if define > 0 && dial > 0 { satisfied = true } } if !satisfied { t.Errorf("no provider.create span has both a kvm2.DomainDefineXML and a kvm2.dial child; spans: %v", spanNames(spans)) } for _, s := range spans { for _, a := range s.Attributes() { v := a.Value.Emit() if strings.Contains(v, integrationCloudInit) || strings.Contains(v, "#cloud-config") { t.Errorf("span %s attribute %s carries the cloud-init text", s.Name(), a.Key) } } } } // TestKVM2Check_realHost runs the health check against the host and creates // nothing. func TestKVM2Check_realHost(t *testing.T) { env := loadIntegrationEnv(t) pc := env.providerConfig() _, log := newIntegrationLog(t, env.logLevel, fmt.Sprintf("%q=%q", "provider", integrationProvider), fmt.Sprintf("%q=%q", "host", integrationHost)) ctx, cancel := context.WithTimeout(logf.IntoContext(context.Background(), log), env.timeout) defer cancel() if env.knownHosts == "" { t.Log("KVM2_TEST_KNOWN_HOSTS is not set: host keys are NOT verified for this run") } built, err := New(ctx, pc) if err != nil { t.Fatalf("New() error = %v", err) } checker, ok := built.(provider.Checker) if !ok { t.Fatalf("New() returned %T, which is not a provider.Checker", built) } targets := checker.Check(ctx) if len(targets) != 1 { t.Fatalf("Check() returned %d targets, want 1: %+v", len(targets), targets) } ts := targets[0] if !ts.Ready || ts.Reason != provider.ReasonReachable { t.Fatalf("Check() = ready %v reason %q message %q, want Ready/%s (details %v)", ts.Ready, ts.Reason, ts.Message, provider.ReasonReachable, ts.Details) } if ts.Details["poolState"] != "running" { t.Errorf("Check() poolState = %q, want running", ts.Details["poolState"]) } t.Logf("host %s (%s): hostname=%s libvirt=%s pool=%s (%s) available=%s GiB latency=%s", ts.Name, ts.Address, ts.Details["hostname"], ts.Details["libvirtVersion"], ts.Details["pool"], ts.Details["poolState"], ts.Details["poolAvailableGiB"], ts.Latency.Round(time.Millisecond)) }