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

package kvm

import (
	"fmt"
	"io"
	"time"

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

// tracingAPI wraps a libvirtAPI and logs one V(1) line per call after it
// returns: the libvirt API function (rpc=virDomainLookupByName, ...), the
// identifiers it was given, curated results, duration, and on failure the
// error with libvirt's code name. At V(2) the same line also carries XML
// bodies, metadata and address lists. Upload and download bodies are never
// logged: the seed ISO carries cloud-init.
type tracingAPI struct {
	inner libvirtAPI
	log   logr.Logger
}

type tracedCall struct {
	t      *tracingAPI
	method string
	start  time.Time
	kv     []any
}

// begin names the call by its libvirt API function: go-libvirt's method
// names are the remote procedure names, which are the public vir* API
// names without the prefix.
func (t *tracingAPI) begin(method string, kv ...any) *tracedCall {
	return &tracedCall{t: t, method: "vir" + method, start: time.Now(), kv: kv}
}

// detail adds key/values that are only worth the bytes at V(2).
func (c *tracedCall) detail(kv ...any) *tracedCall {
	if c.t.log.V(2).Enabled() {
		c.kv = append(c.kv, kv...)
	}
	return c
}

func (c *tracedCall) done(err error, kv ...any) {
	fields := make([]any, 0, 2+len(c.kv)+len(kv)+10)
	fields = append(fields, "rpc", c.method)
	fields = append(fields, c.kv...)
	fields = append(fields, kv...)
	fields = append(fields, "duration", time.Since(c.start).Round(time.Microsecond))
	if err != nil {
		fields = append(fields, "error", err.Error())
		fields = append(fields, libvirtErrorFields(err)...)
	}
	c.t.log.V(1).Info("libvirt call", fields...)
}

// flagKV renders a flags value only when something is set; go-libvirt's
// generated stringers do not know bitmask combinations.
func flagKV(v int64) []any {
	if v == 0 {
		return nil
	}
	return []any{"flags", v}
}

func optString(s libvirt.OptString) string {
	if len(s) == 0 {
		return ""
	}
	return s[0]
}

func (t *tracingAPI) DomainLookupByName(name string) (libvirt.Domain, error) {
	c := t.begin("DomainLookupByName", "domain", name)
	d, err := t.inner.DomainLookupByName(name)
	c.done(err)
	return d, err
}

func (t *tracingAPI) DomainDefineXML(xml string) (libvirt.Domain, error) {
	c := t.begin("DomainDefineXML", "xmlBytes", len(xml)).detail("xml", xml)
	d, err := t.inner.DomainDefineXML(xml)
	c.done(err, "domain", d.Name)
	return d, err
}

func (t *tracingAPI) DomainCreate(d libvirt.Domain) error {
	c := t.begin("DomainCreate", "domain", d.Name)
	err := t.inner.DomainCreate(d)
	c.done(err)
	return err
}

func (t *tracingAPI) DomainDestroy(d libvirt.Domain) error {
	c := t.begin("DomainDestroy", "domain", d.Name)
	err := t.inner.DomainDestroy(d)
	c.done(err)
	return err
}

func (t *tracingAPI) DomainUndefineFlags(d libvirt.Domain, flags libvirt.DomainUndefineFlagsValues) error {
	c := t.begin("DomainUndefineFlags", append([]any{"domain", d.Name}, flagKV(int64(flags))...)...)
	err := t.inner.DomainUndefineFlags(d, flags)
	c.done(err)
	return err
}

func (t *tracingAPI) DomainGetState(d libvirt.Domain, flags uint32) (int32, int32, error) {
	c := t.begin("DomainGetState", "domain", d.Name)
	state, reason, err := t.inner.DomainGetState(d, flags)
	c.done(err, "state", libvirt.DomainState(state), "reason", reason)
	return state, reason, err
}

func (t *tracingAPI) DomainGetMetadata(d libvirt.Domain, typ int32, uri libvirt.OptString, flags libvirt.DomainModificationImpact) (string, error) {
	c := t.begin("DomainGetMetadata", "domain", d.Name, "type", typ, "uri", optString(uri))
	s, err := t.inner.DomainGetMetadata(d, typ, uri, flags)
	c.detail("metadata", s).done(err, "metadataBytes", len(s))
	return s, err
}

func (t *tracingAPI) DomainInterfaceAddresses(d libvirt.Domain, source uint32, flags uint32) ([]libvirt.DomainInterface, error) {
	c := t.begin("DomainInterfaceAddresses", "domain", d.Name, "source", libvirt.DomainInterfaceAddressesSource(source))
	ifaces, err := t.inner.DomainInterfaceAddresses(d, source, flags)
	if t.log.V(2).Enabled() {
		c.detail("addresses", formatAddresses(ifaces))
	}
	c.done(err, "interfaces", len(ifaces))
	return ifaces, err
}

func formatAddresses(ifaces []libvirt.DomainInterface) []string {
	var out []string
	for _, iface := range ifaces {
		for _, a := range iface.Addrs {
			out = append(out, fmt.Sprintf("%s=%s/%d", iface.Name, a.Addr, a.Prefix))
		}
	}
	return out
}

func (t *tracingAPI) ConnectListAllDomains(needResults int32, flags libvirt.ConnectListAllDomainsFlags) ([]libvirt.Domain, uint32, error) {
	c := t.begin("ConnectListAllDomains", flagKV(int64(flags))...)
	doms, n, err := t.inner.ConnectListAllDomains(needResults, flags)
	if t.log.V(2).Enabled() {
		names := make([]string, 0, len(doms))
		for _, d := range doms {
			names = append(names, d.Name)
		}
		c.detail("names", names)
	}
	c.done(err, "count", len(doms))
	return doms, n, err
}

func (t *tracingAPI) StoragePoolLookupByName(name string) (libvirt.StoragePool, error) {
	c := t.begin("StoragePoolLookupByName", "pool", name)
	pool, err := t.inner.StoragePoolLookupByName(name)
	c.done(err)
	return pool, err
}

func (t *tracingAPI) StoragePoolRefresh(pool libvirt.StoragePool, flags uint32) error {
	c := t.begin("StoragePoolRefresh", "pool", pool.Name)
	err := t.inner.StoragePoolRefresh(pool, flags)
	c.done(err)
	return err
}

func (t *tracingAPI) StorageVolLookupByName(pool libvirt.StoragePool, name string) (libvirt.StorageVol, error) {
	c := t.begin("StorageVolLookupByName", "pool", pool.Name, "volume", name)
	vol, err := t.inner.StorageVolLookupByName(pool, name)
	c.done(err)
	return vol, err
}

func (t *tracingAPI) StorageVolGetPath(vol libvirt.StorageVol) (string, error) {
	c := t.begin("StorageVolGetPath", "pool", vol.Pool, "volume", vol.Name)
	path, err := t.inner.StorageVolGetPath(vol)
	c.done(err, "path", path)
	return path, err
}

func (t *tracingAPI) StorageVolCreateXML(pool libvirt.StoragePool, xml string, flags libvirt.StorageVolCreateFlags) (libvirt.StorageVol, error) {
	c := t.begin("StorageVolCreateXML", append([]any{"pool", pool.Name, "xmlBytes", len(xml)}, flagKV(int64(flags))...)...).detail("xml", xml)
	vol, err := t.inner.StorageVolCreateXML(pool, xml, flags)
	c.done(err, "volume", vol.Name)
	return vol, err
}

func (t *tracingAPI) StorageVolUpload(vol libvirt.StorageVol, r io.Reader, offset, length uint64, flags libvirt.StorageVolUploadFlags) error {
	c := t.begin("StorageVolUpload", append([]any{"pool", vol.Pool, "volume", vol.Name, "offset", offset, "length", length}, flagKV(int64(flags))...)...)
	err := t.inner.StorageVolUpload(vol, r, offset, length, flags)
	c.done(err)
	return err
}

func (t *tracingAPI) StorageVolDownload(vol libvirt.StorageVol, w io.Writer, offset, length uint64, flags libvirt.StorageVolDownloadFlags) error {
	c := t.begin("StorageVolDownload", append([]any{"pool", vol.Pool, "volume", vol.Name, "offset", offset, "length", length}, flagKV(int64(flags))...)...)
	err := t.inner.StorageVolDownload(vol, w, offset, length, flags)
	c.done(err)
	return err
}

func (t *tracingAPI) StorageVolDelete(vol libvirt.StorageVol, flags libvirt.StorageVolDeleteFlags) error {
	c := t.begin("StorageVolDelete", append([]any{"pool", vol.Pool, "volume", vol.Name}, flagKV(int64(flags))...)...)
	err := t.inner.StorageVolDelete(vol, flags)
	c.done(err)
	return err
}