egress-proxies-operator/internal/provider/proxmox/provider_test.go

package proxmox

import (
	"context"
	"errors"
	"net/http"
	"path/filepath"
	"slices"
	"strconv"
	"strings"
	"testing"
	"time"

	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/sdk/trace/tracetest"

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

const (
	testProvider = "proxmox-home"
	testUID      = "0b9c6f3e-2d4a-4e1b-9c7f-5a8d3e2f1b60"
	testVMID     = 150042
)

var (
	testName      = provider.NameFromUID(testUID)
	testCreatedAt = time.Date(2026, 9, 23, 10, 0, 0, 0, time.UTC)
)

// fixture is a Provider over fakeAPI, logging into a capture, with every
// budget shrunk so waits take milliseconds.
type fixture struct {
	t    *testing.T
	p    *Provider
	fake *fakeAPI
	logs *logCapture
	ctx  context.Context
}

func newFixture(t *testing.T, verbosity int) *fixture {
	t.Helper()
	fx := &fixture{t: t, fake: newFakeAPI(), logs: &logCapture{}}
	fx.p = newProvider(testProvider, testConfig(), fx.fake)
	fx.p.budgets = testBudgets()
	fx.ctx = fx.logs.context(verbosity)
	return fx
}

func testBudgets() budgets {
	return budgets{
		clone:      time.Second,
		upload:     time.Second,
		resize:     time.Second,
		start:      time.Second,
		stop:       time.Second,
		destroy:    time.Second,
		seedDelete: time.Second,
		running:    time.Second,
		poll:       time.Millisecond,
	}
}

// addOurVM places a VM carrying the mark for testUID and the tag, as
// Create leaves it.
func (fx *fixture) addOurVM(vmid int, name, status string) *fakeVM {
	fx.t.Helper()
	vm := fx.fake.addVM(vmid, name, status)
	vm.config["description"] = formatDescription(testUID, testCreatedAt)
	vm.config["tags"] = proxyTag
	return vm
}

// id is the providerID of the VM addOurVM(testVMID, testName, …) places.
func (fx *fixture) id() string { return formatProviderID(testVMID, testName) }

func (fx *fixture) get(id string) *provider.Instance {
	fx.t.Helper()
	inst, err := fx.p.Get(fx.ctx, id)
	if err != nil {
		fx.t.Fatalf("Get(%s) error = %v", id, err)
	}
	return inst
}

// assertProviderError checks that err is a *provider.Error from this
// provider for op, in class and in no other class.
func assertProviderError(t *testing.T, err error, op string, class error) {
	t.Helper()
	if err == nil {
		t.Fatalf("error = nil, want op %s class %v", op, class)
	}
	var pe *provider.Error
	if !errors.As(err, &pe) {
		t.Fatalf("error = %T (%v), want *provider.Error", err, err)
	}
	if pe.Provider != testProvider {
		t.Errorf("error.Provider = %q, want %q", pe.Provider, testProvider)
	}
	if pe.Op != op {
		t.Errorf("error.Op = %q, want %q", pe.Op, op)
	}
	if !errors.Is(err, class) {
		t.Errorf("error = %v, want class %v", err, class)
	}
	for _, other := range []error{provider.ErrNotFound, provider.ErrQuotaExceeded, provider.ErrPermanent, provider.ErrTransient} {
		if other != class && errors.Is(err, other) {
			t.Errorf("error = %v, also matches %v", err, other)
		}
	}
}

// within runs fn and fails the test when it has not returned after d, so
// a call that ignores its ctx fails by name instead of hanging the package
// until the test binary's timeout.
func within(t *testing.T, d time.Duration, fn func()) {
	t.Helper()
	done := make(chan struct{})
	go func() {
		defer close(done)
		fn()
	}()
	select {
	case <-done:
	case <-time.After(d):
		t.Fatalf("did not return within %v", d)
	}
}

// cancelWhileBlocked runs call with a ctx it cancels once call has reached
// method, which blocks until then, and fails unless call returns within a
// second of the cancel. Every wait is bounded, so a call that never reaches
// method or never returns fails instead of hanging the package.
func cancelWhileBlocked(t *testing.T, fx *fixture, method string, call func(ctx context.Context)) {
	t.Helper()
	release := fx.fake.blockOn(method)
	defer close(release)
	ctx, cancel := context.WithCancel(fx.ctx)
	defer cancel()
	returned := make(chan struct{})
	go func() {
		defer close(returned)
		call(ctx)
	}()
	deadline := time.After(5 * time.Second)
	for fx.fake.callCount(method) == 0 {
		select {
		case <-returned:
			t.Fatalf("returned before calling %s; calls: %v", method, fx.fake.callLog())
		case <-deadline:
			t.Fatalf("%s was not called within 5s; calls: %v", method, fx.fake.callLog())
		case <-time.After(time.Millisecond):
		}
	}
	cancel()
	select {
	case <-returned:
	case <-time.After(time.Second):
		t.Fatalf("did not return within 1s of the cancel while blocked in %s", method)
	}
}

func TestProvider_cancelledContextReturnsPromptly(t *testing.T) {
	t.Parallel()
	tests := []struct {
		name    string
		blockOn string
		// first: blockOn is the operation's first seam call.
		first bool
		setup func(fx *fixture)
		op    string
		call  func(ctx context.Context, fx *fixture) error
	}{
		{
			name: "create", blockOn: "ClusterResources", first: true, op: "create",
			call: func(ctx context.Context, fx *fixture) error { _, err := fx.p.Create(ctx, fx.req()); return err },
		},
		{
			name: "create mid upload", blockOn: "UploadISO", op: "create",
			call: func(ctx context.Context, fx *fixture) error { _, err := fx.p.Create(ctx, fx.req()); return err },
		},
		{
			name: "get", blockOn: "ClusterResources", first: true, op: "get",
			setup: func(fx *fixture) { fx.addOurVM(testVMID, testName, "running") },
			call:  func(ctx context.Context, fx *fixture) error { _, err := fx.p.Get(ctx, fx.id()); return err },
		},
		{
			name: "delete", blockOn: "ClusterResources", first: true, op: "delete",
			setup: func(fx *fixture) { fx.addOurVM(testVMID, testName, "running") },
			call:  func(ctx context.Context, fx *fixture) error { return fx.p.Delete(ctx, fx.id()) },
		},
		{
			name: "delete mid stop", blockOn: "Stop", op: "delete",
			setup: func(fx *fixture) { fx.addOurVM(testVMID, testName, "running") },
			call:  func(ctx context.Context, fx *fixture) error { return fx.p.Delete(ctx, fx.id()) },
		},
		{
			name: "list", blockOn: "ClusterResources", first: true, op: "list",
			setup: func(fx *fixture) { fx.addOurVM(testVMID, testName, "running") },
			call:  func(ctx context.Context, fx *fixture) error { _, err := fx.p.ListByTag(ctx); return err },
		},
	}
	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			t.Parallel()
			fx := newCreateFixture(t, 1)
			if tc.setup != nil {
				tc.setup(fx)
			}
			var err error
			cancelWhileBlocked(t, fx, tc.blockOn, func(ctx context.Context) { err = tc.call(ctx, fx) })
			if calls := fx.fake.callLog(); tc.first && calls[0] != tc.blockOn {
				t.Errorf("first call = %s, want %s", calls[0], tc.blockOn)
			}
			assertProviderError(t, err, tc.op, provider.ErrTransient)
			if !errors.Is(err, context.Canceled) {
				t.Errorf("error = %v, want it to carry context.Canceled", err)
			}
		})
	}
	t.Run("check", func(t *testing.T) {
		t.Parallel()
		fx := newCheckFixture(t)
		var got []provider.TargetStatus
		cancelWhileBlocked(t, fx, "Version", func(ctx context.Context) { got = fx.p.Check(ctx) })
		if calls := fx.fake.callLog(); calls[0] != "Version" {
			t.Errorf("first call = %s, want Version", calls[0])
		}
		if len(got) != 1 || got[0].Ready || got[0].Reason != provider.ReasonTimeout {
			t.Errorf("Check() = %+v, want one target not ready with reason %s", got, provider.ReasonTimeout)
		}
	})
}

func TestProvider_everyErrorIsWrappedWithConfiguredName(t *testing.T) {
	t.Parallel()
	createWith := func(mutate func(*provider.CreateRequest)) func(context.Context, *fixture) error {
		return func(ctx context.Context, fx *fixture) error {
			req := fx.req()
			if mutate != nil {
				mutate(&req)
			}
			_, err := fx.p.Create(ctx, req)
			return err
		}
	}
	get := func(ctx context.Context, fx *fixture) error { _, err := fx.p.Get(ctx, fx.id()); return err }
	del := func(ctx context.Context, fx *fixture) error { return fx.p.Delete(ctx, fx.id()) }
	list := func(ctx context.Context, fx *fixture) error { _, err := fx.p.ListByTag(ctx); return err }
	holdNameLock := func(fx *fixture, cancel context.CancelFunc) {
		release, err := fx.p.nameLocks.Acquire(context.Background(), testName)
		if err != nil {
			fx.t.Fatalf("Acquire error = %v", err)
		}
		fx.t.Cleanup(release)
		cancel()
	}
	broken := fakeErr(596, "Broken pipe")
	tests := []struct {
		name  string
		setup func(fx *fixture, cancel context.CancelFunc)
		call  func(ctx context.Context, fx *fixture) error
		op    string
		id    string
		class error
	}{
		{name: "create without a name", call: createWith(func(r *provider.CreateRequest) { r.Name = "" }), op: "create", class: provider.ErrPermanent},
		{name: "create unknown zone", call: createWith(func(r *provider.CreateRequest) { r.Placement.Zone = "pv9-9" }), op: "create", class: provider.ErrPermanent},
		{name: "create unknown image", call: createWith(func(r *provider.CreateRequest) { r.Placement.Image = "arch" }), op: "create", class: provider.ErrPermanent},
		{name: "create waiting on the name lock", setup: holdNameLock, call: createWith(nil), op: "create", class: provider.ErrTransient},
		{
			name:  "create resources unreadable",
			setup: func(fx *fixture, _ context.CancelFunc) { fx.fake.failWith("ClusterResources", broken) },
			call:  createWith(nil), op: "create", class: provider.ErrTransient,
		},
		{
			name: "create clone forbidden",
			setup: func(fx *fixture, _ context.CancelFunc) {
				fx.fake.failWith("Clone", loadAPIError(fx.t, "err_forbidden"))
			},
			call: createWith(nil), op: "create", class: provider.ErrPermanent,
		},
		{
			name:  "create start task fails",
			setup: func(fx *fixture, _ context.CancelFunc) { fx.fake.startFailsWith = "fake: start failed" },
			call:  createWith(nil), op: "create", class: provider.ErrTransient,
		},
		{
			name: "get malformed id",
			call: func(ctx context.Context, fx *fixture) error { _, err := fx.p.Get(ctx, "vms/abc/"+testName); return err },
			op:   "get", id: "vms/abc/" + testName, class: provider.ErrPermanent,
		},
		{name: "get missing vm", call: get, op: "get", id: "self", class: provider.ErrNotFound},
		{
			name:  "get locked vm",
			setup: func(fx *fixture, _ context.CancelFunc) { fx.addOurVM(testVMID, testName, "running").lock = "backup" },
			call:  get, op: "get", id: "self", class: provider.ErrTransient,
		},
		{
			name: "get unauthorized",
			setup: func(fx *fixture, _ context.CancelFunc) {
				fx.fake.failWith("ClusterResources", loadAPIError(fx.t, "err_unauthorized"))
			},
			call: get, op: "get", id: "self", class: provider.ErrPermanent,
		},
		{
			name: "delete malformed id",
			call: func(ctx context.Context, fx *fixture) error { return fx.p.Delete(ctx, "vms/150042") },
			op:   "delete", id: "vms/150042", class: provider.ErrPermanent,
		},
		{name: "delete waiting on the name lock", setup: holdNameLock, call: del, op: "delete", id: "self", class: provider.ErrTransient},
		{
			name: "delete hibernated vm",
			setup: func(fx *fixture, _ context.CancelFunc) {
				fx.addOurVM(testVMID, testName, "stopped").lock = lockSuspended
			},
			call: del, op: "delete", id: "self", class: provider.ErrPermanent,
		},
		{
			name: "delete destroy task fails",
			setup: func(fx *fixture, _ context.CancelFunc) {
				fx.addOurVM(testVMID, testName, "stopped")
				fx.fake.destroyFailsWith = "fake: destroy failed"
			},
			call: del, op: "delete", id: "self", class: provider.ErrTransient,
		},
		{
			name: "delete seed forbidden",
			setup: func(fx *fixture, _ context.CancelFunc) {
				fx.addOurVM(testVMID, testName, "stopped")
				fx.fake.failWith("DeleteVolume", loadAPIError(fx.t, "err_forbidden_volume_delete"))
			},
			call: del, op: "delete", id: "self", class: provider.ErrPermanent,
		},
		{
			name:  "list resources unreadable",
			setup: func(fx *fixture, _ context.CancelFunc) { fx.fake.failWith("ClusterResources", broken) },
			call:  list, op: "list", class: provider.ErrTransient,
		},
		{
			name: "list unauthorized",
			setup: func(fx *fixture, _ context.CancelFunc) {
				fx.fake.failWith("ClusterResources", loadAPIError(fx.t, "err_unauthorized"))
			},
			call: list, op: "list", class: provider.ErrPermanent,
		},
		{
			name: "list ended on a candidate",
			setup: func(fx *fixture, cancel context.CancelFunc) {
				fx.addOurVM(testVMID, testName, "running")
				fx.fake.hookOn("VMConfig", func() error {
					cancel()
					return broken
				})
			},
			call: list, op: "list", class: provider.ErrTransient,
		},
	}
	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			t.Parallel()
			fx := newCreateFixture(t, 1)
			ctx, cancel := context.WithCancel(fx.ctx)
			defer cancel()
			if tc.setup != nil {
				tc.setup(fx, cancel)
			}
			var err error
			within(t, 5*time.Second, func() { err = tc.call(ctx, fx) })
			assertProviderError(t, err, tc.op, tc.class)
			wantID := tc.id
			if wantID == "self" {
				wantID = fx.id()
			}
			var pe *provider.Error
			if errors.As(err, &pe) && pe.ID != wantID {
				t.Errorf("error.ID = %q, want %q", pe.ID, wantID)
			}
			if !strings.HasPrefix(err.Error(), "provider "+testProvider+": "+tc.op) {
				t.Errorf("error = %q, want it to start with the configured name and op", err)
			}
		})
	}
}

// logSentinel is in the CloudInit the logging lifecycle creates with; no
// log line at any level may carry it.
const logSentinel = "SENTINEL-cloud-init-7e2a"

// newLoggingFixture is an observed create fixture with a token file, so
// one lifecycle covers every operation, Check and the decorator's lines.
func newLoggingFixture(t *testing.T, verbosity int) *fixture {
	t.Helper()
	fx := newCreateFixture(t, verbosity)
	fx.p.api = observe(fx.fake, testProvider)
	fx.p.cfg.TokenFile = filepath.Join(t.TempDir(), "token")
	writeFile(t, fx.p.cfg.TokenFile, testToken+"\n")
	return fx
}

// sentinelReq is fx.req() with logSentinel in its CloudInit.
func (fx *fixture) sentinelReq() provider.CreateRequest {
	req := fx.req()
	req.CloudInit = "#cloud-config\nwrite_files:\n  - path: /etc/sentinel\n    content: " + logSentinel + "\n"
	return req
}

// lifecycle runs Create with sentinelReq, a Get that finds the address,
// ListByTag, Delete, Delete of the gone VM, and Check.
func (fx *fixture) lifecycle() {
	fx.t.Helper()
	id := fx.create(fx.sentinelReq())
	ifaces := capturedIfaces(fx.t)
	fx.fake.mu.Lock()
	fx.fake.vms[slot(0)].ifaces = ifaces
	fx.fake.mu.Unlock()
	if inst := fx.get(id); inst.State != provider.StateRunning {
		fx.t.Fatalf("Get state = %s, want Running", inst.State)
	}
	if _, err := fx.p.ListByTag(fx.ctx); err != nil {
		fx.t.Fatalf("ListByTag error = %v", err)
	}
	for range 2 {
		if err := fx.p.Delete(fx.ctx, id); err != nil {
			fx.t.Fatalf("Delete error = %v", err)
		}
	}
	if ts := fx.p.Check(fx.ctx); len(ts) != 1 || !ts[0].Ready {
		fx.t.Fatalf("Check = %+v, want one Ready target", ts)
	}
}

// assertNeverLogged checks every line for the cloud-init text and the
// token's secret.
func assertNeverLogged(t *testing.T, lines []string) {
	t.Helper()
	secret := testToken[strings.Index(testToken, "=")+1:]
	for _, l := range lines {
		for _, never := range []string{logSentinel, "#cloud-config", secret} {
			if strings.Contains(l, never) {
				t.Errorf("line carries %q: %s", never, l)
			}
		}
	}
}

func msgLine(msg string) string { return `"msg"="` + msg + `"` }

// assertEveryV1Line checks that each line is from the proxmox logger at
// V(1) with the provider, and that each line about an instance, which is
// all but the decorator's, the list's and the check's, names its vmid and
// name.
func assertEveryV1Line(t *testing.T, lines []string, vmid, name string) {
	t.Helper()
	notInstance := []string{msgLine("proxmox api call"), msgLine("proxmox vms listed"), msgLine("proxmox node checked")}
	for _, l := range lines {
		if !strings.HasPrefix(l, "proxmox ") || !strings.Contains(l, `"provider"="`+testProvider+`"`) {
			t.Errorf("line lacks the proxmox logger or the provider: %s", l)
		}
		if !strings.Contains(l, `"level"=1`) {
			t.Errorf("line is not at V(1): %s", l)
		}
		instance := !slices.ContainsFunc(notInstance, func(m string) bool { return strings.Contains(l, m) })
		if instance && (!strings.Contains(l, vmid) || !strings.Contains(l, name)) {
			t.Errorf("instance line lacks vmid or name: %s", l)
		}
	}
}

func TestLogging_v0SilentV1OutcomeV2Detail(t *testing.T) {
	t.Parallel()
	vmid := `"vmid"=` + strconv.Itoa(slot(0))
	name := `"name"="` + testName + `"`
	t.Run("v0 is silent", func(t *testing.T) {
		t.Parallel()
		fx := newLoggingFixture(t, 0)
		fx.lifecycle()
		if lines := fx.logs.all(); len(lines) != 0 {
			t.Errorf("the lifecycle logged %d lines at V(0), want none:\n%s", len(lines), strings.Join(lines, "\n"))
		}
	})
	t.Run("v1 has one outcome per operation", func(t *testing.T) {
		t.Parallel()
		fx := newLoggingFixture(t, 1)
		fx.lifecycle()
		all := fx.logs.all()
		dump := strings.Join(all, "\n")
		outcomes := map[string][]string{
			"proxmox vm ensured running": {vmid, name, `"node"="pv1-1"`},
			"proxmox vm fetched":         {vmid, name, `"state"="Running"`, `"ip"="192.168.0.150"`, `"uid"="` + testUID + `"`},
			"proxmox vms listed":         {`"candidates"=1`, `"managed"=1`, `"skipped"=0`},
			"proxmox node checked":       {`"node"="pv1-1"`, `"ready"=true`, `"reason"="Reachable"`},
		}
		for msg, keys := range outcomes {
			lines := fx.logs.matching(msgLine(msg))
			if len(lines) != 1 {
				t.Errorf("lines %q = %d, want 1:\n%s", msg, len(lines), dump)
				continue
			}
			for _, k := range keys {
				if !strings.Contains(lines[0], k) {
					t.Errorf("%q line lacks %s: %s", msg, k, lines[0])
				}
			}
		}
		deleted := fx.logs.matching(msgLine("proxmox vm deleted"))
		if len(deleted) != 2 {
			t.Fatalf("deleted lines = %d, want 2 (destroyed, then already gone):\n%s", len(deleted), dump)
		}
		if l := deleted[0]; !strings.Contains(l, `"destroyed"=true`) || !strings.Contains(l, `"node"="pv1-1"`) || !strings.Contains(l, vmid) || !strings.Contains(l, name) {
			t.Errorf("first deleted line = %s, want destroyed=true with node, vmid and name", l)
		}
		if l := deleted[1]; !strings.Contains(l, `"destroyed"=false`) || strings.Contains(l, `"node"=`) || !strings.Contains(l, vmid) || !strings.Contains(l, name) {
			t.Errorf("second deleted line = %s, want destroyed=false with vmid and name and no node", l)
		}
		assertEveryV1Line(t, all, vmid, name)
		for _, v2 := range []string{"cloudInitBytes", "proxmox create resolved", "proxmox guest agent answered", "proxmox listed instance", `"description"=`, `"config"=`, `"params"=`} {
			if got := fx.logs.matching(v2); len(got) != 0 {
				t.Errorf("V(1) carries the V(2) detail %s:\n%s", v2, strings.Join(got, "\n"))
			}
		}
		assertNeverLogged(t, all)
	})
	t.Run("v2 has detail and never the cloud-init", func(t *testing.T) {
		t.Parallel()
		fx := newLoggingFixture(t, 2)
		fx.lifecycle()
		resolved := fx.logs.matching(msgLine("proxmox create resolved"))
		if len(resolved) != 1 {
			t.Fatalf("resolved lines = %d, want 1", len(resolved))
		}
		for _, k := range []string{name, `"cloudInitBytes"=` + strconv.Itoa(len(fx.sentinelReq().CloudInit)), `"machineType"="small"`, `"cores"=1`, `"memoryMiB"=1024`, `"templateVMID"=9001`, `"isoStorage"="proxy-seeds"`} {
			if !strings.Contains(resolved[0], k) {
				t.Errorf("resolved line lacks %s: %s", k, resolved[0])
			}
		}
		details := map[string]string{
			msgLine("proxmox guest agent answered"): `"ip"="192.168.0.150"`,
			msgLine("proxmox listed instance"):      `"uid"="` + testUID + `"`,
			`"call"="Clone"`:                        `"description"="proxy-operator-managed=true`,
			`"call"="VMConfig"`:                     `"config"=`,
			`"call"="UploadISO"`:                    `"bytes"=`,
		}
		for line, k := range details {
			got := fx.logs.matching(line)
			if len(got) == 0 || !strings.Contains(got[0], k) {
				t.Errorf("V(2) %s line lacks %s: %v", line, k, got)
			}
		}
		assertNeverLogged(t, fx.logs.all())
	})
}

// TestLogging_noOpLinesAtV1: spec entry 20's no-op lines of Delete and
// ListByTag are there at V(1), each naming the instance.
func TestLogging_noOpLinesAtV1(t *testing.T) {
	t.Parallel()
	del := func(fx *fixture) error { return fx.p.Delete(fx.ctx, fx.id()) }
	tests := []struct {
		name  string
		setup func(fx *fixture)
		call  func(fx *fixture) error
		msg   string
		want  int
	}{
		{name: "vm already gone", call: del, msg: "proxmox vm already gone", want: 1},
		{
			name:  "foreign vm",
			setup: func(fx *fixture) { fx.addOurVM(testVMID, "proxy-someoneelse00000", "running") },
			call:  del, msg: "proxmox vm at this vmid is not ours, left alone", want: 1,
		},
		{
			name:  "unmarked vm",
			setup: func(fx *fixture) { fx.fake.addVM(testVMID, testName, "running") },
			call:  del, msg: "proxmox vm carries no proxy-operator mark, left alone", want: 1,
		},
		{
			name: "seed delete skipped on each node",
			setup: func(fx *fixture) {
				fx.p.cfg.Nodes = []string{fakeNode, "pv1-2"}
				fx.fake.failWith("DeleteVolume", loadAPIError(fx.t, "err_forbidden_volume_delete"))
			},
			call: del, msg: "proxmox seed delete failed on a node, skipped", want: 2,
		},
		{
			name: "unreadable candidate",
			setup: func(fx *fixture) {
				fx.addOurVM(testVMID, testName, "running")
				fx.fake.failWith("VMConfig", fakeErr(596, "Broken pipe"))
			},
			call: func(fx *fixture) error { _, err := fx.p.ListByTag(fx.ctx); return err },
			msg:  "skipping unreadable proxmox vm", want: 1,
		},
	}
	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			t.Parallel()
			fx := newFixture(t, 1)
			if tc.setup != nil {
				tc.setup(fx)
			}
			if err := tc.call(fx); err != nil {
				t.Fatalf("error = %v, want nil", err)
			}
			lines := fx.logs.matching(msgLine(tc.msg))
			if len(lines) != tc.want {
				t.Fatalf("lines %q = %d, want %d:\n%s", tc.msg, len(lines), tc.want, strings.Join(fx.logs.all(), "\n"))
			}
			for _, l := range lines {
				for _, k := range []string{`"provider"="` + testProvider + `"`, `"vmid"=150042`, `"level"=1`} {
					if !strings.Contains(l, k) {
						t.Errorf("line lacks %s: %s", k, l)
					}
				}
			}
		})
	}
}

// TestTracing_httpSpansUnderOperationSpan runs a Get through
// provider.WithTracing over the real client against Phase 0's captures:
// each of Get's four requests is an HTTP span under provider.get, and no
// span attribute carries the token.
func TestTracing_httpSpansUnderOperationSpan(t *testing.T) {
	t.Parallel()
	const (
		vmid = 199999
		name = "proxy-reconaaaaaaaaaaa"
	)
	cfx := newClientFixture(t, func(w http.ResponseWriter, r *http.Request) {
		path := strings.TrimPrefix(r.URL.Path, "/api2/json/")
		capture := map[string]string{
			"cluster/resources":                                    "cluster_resources_during_destroy",
			"nodes/pv1-1/qemu/199999/config":                       "config_during_destroy",
			"nodes/pv1-1/qemu/199999/status/current":               "status_current_running",
			"nodes/pv1-1/qemu/199999/agent/network-get-interfaces": "agent_network_get_interfaces",
		}[path]
		if r.Method != http.MethodGet || capture == "" {
			t.Errorf("unexpected request %s %s", r.Method, path)
			http.NotFound(w, r)
			return
		}
		serveJSON(w, readCapture(t, capture).Body)
	})
	sr := tracetest.NewSpanRecorder()
	tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr))
	t.Cleanup(func() { _ = tp.Shutdown(context.Background()) })
	opt := tracing.WithTracerProvider(tp)

	cfg := testConfig()
	cfg.URL, cfg.TokenFile, cfg.CAFile = cfx.cfg.URL, cfx.cfg.TokenFile, cfx.cfg.CAFile
	p := newProvider(testProvider, cfg, observe(cfx.api(t, opt), testProvider))
	p.budgets = testBudgets()
	traced := provider.WithTracing(testProvider, p, opt)

	inst, err := traced.Get(context.Background(), formatProviderID(vmid, name))
	if err != nil {
		t.Fatalf("Get error = %v", err)
	}
	if inst.State != provider.StateRunning || inst.IP != "192.168.0.150" {
		t.Errorf("Get = %+v, want Running at 192.168.0.150", inst)
	}

	var (
		op       sdktrace.ReadOnlySpan
		requests []sdktrace.ReadOnlySpan
	)
	for _, s := range sr.Ended() {
		if s.Name() == "provider.get" {
			op = s
		} else {
			requests = append(requests, s)
		}
	}
	if op == nil {
		t.Fatalf("no provider.get span among %d", len(sr.Ended()))
	}
	if len(requests) != 4 {
		t.Errorf("HTTP spans = %d, want one per request of Get (4)", len(requests))
	}
	for _, s := range requests {
		if s.Name() != "HTTP GET" {
			t.Errorf("span %q, want HTTP GET (spec entry 17)", s.Name())
		}
		if s.Parent().SpanID() != op.SpanContext().SpanID() || s.SpanContext().TraceID() != op.SpanContext().TraceID() {
			t.Errorf("span %q is not a child of provider.get", s.Name())
		}
	}
	secret := testToken[strings.Index(testToken, "=")+1:]
	for _, s := range sr.Ended() {
		for _, kv := range s.Attributes() {
			if v := kv.Value.Emit(); strings.Contains(v, secret) || strings.Contains(v, "PVEAPIToken") {
				t.Errorf("span %s attribute %s carries the token: %s", s.Name(), kv.Key, v)
			}
		}
	}
}