🌱 Include VM MoID in its logger

pkg/context/vc_context.go

@@ -0,0 +1,53 @@
+// © Broadcom. All Rights Reserved.
+// The term “Broadcom” refers to Broadcom Inc. and/or its subsidiaries.
+// SPDX-License-Identifier: Apache-2.0
+
+package context
+
+import (
+	"context"
+	"math/rand"
+	"strings"
+
+	"github.com/go-logr/logr"
+	vimtypes "github.com/vmware/govmomi/vim25/types"
+	"sigs.k8s.io/controller-runtime/pkg/client"
+	"sigs.k8s.io/controller-runtime/pkg/controller"
+
+	pkglog "github.com/vmware-tanzu/vm-operator/pkg/log"
+)
+
+func getOpID(ctx context.Context, obj client.Object, operation string) (string, string) {
+	opID := strings.Join([]string{"vmoperator", obj.GetName(), operation}, "-")
+
+	if recID := controller.ReconcileIDFromContext(ctx); len(recID) >= 8 {
+		id := string(recID[:8])
+		return opID + "-" + id, ""
+	}
+
+	// Generate our own internal ID.
+	const charset = "0123456789abcdef"
+	buf := make([]byte, 8)
+	for i := range buf {
+		idx := rand.Intn(len(charset)) //nolint:gosec
+		buf[i] = charset[idx]
+	}
+	id := string(buf)
+
+	return opID + "-" + id, id
+}
+
+// WithVCOpID sets the vimtypes.ID in the context so that it is passed along to VC
+// to correlate VMOP and VC logs.
+func WithVCOpID(ctx context.Context, obj client.Object, operation string) context.Context {
+	vcOpID, intRecID := getOpID(ctx, obj, operation)
+	if intRecID != "" {
+		// If the context did not have a controller-runtime reconcile ID, include the one
+		// that we generated in the context's logger. The underlying reconcile ID context
+		// value type is not exported by controller-runtime so we cannot set that specific
+		// reconcile type.
+		logger := pkglog.FromContextOrDefault(ctx).WithValues("recID", intRecID)
+		ctx = logr.NewContext(ctx, logger)
+	}
+	return context.WithValue(ctx, vimtypes.ID{}, vcOpID)
+}

pkg/context/virtualmachine_context.go

@@ -14,6 +14,7 @@ import (
 	vimtypes "github.com/vmware/govmomi/vim25/types"
 
 	vmopv1 "github.com/vmware-tanzu/vm-operator/api/v1alpha5"
+	pkglog "github.com/vmware-tanzu/vm-operator/pkg/log"
 )
 
 type vmContextKey uint8
@@ -33,6 +34,20 @@ type VirtualMachineContext struct {
 	MoVM   mo.VirtualMachine
 }
 
+func NewVirtualMachineContext(ctx context.Context, vm *vmopv1.VirtualMachine) VirtualMachineContext {
+	logger := pkglog.FromContextOrDefault(ctx)
+	if vm.Status.UniqueID != "" {
+		logger = logger.WithValues("moID", vm.Status.UniqueID)
+		ctx = logr.NewContext(ctx, logger)
+	}
+
+	return VirtualMachineContext{
+		Context: ctx,
+		Logger:  logger,
+		VM:      vm,
+	}
+}
+
 func (v VirtualMachineContext) String() string {
 	if v.VM == nil {
 		return ""

pkg/providers/vsphere/vmprovider.go

@@ -8,7 +8,6 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
-	"math/rand"
 	"strings"
 	"sync"
 	"sync/atomic"
@@ -24,7 +23,6 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	apierrorsutil "k8s.io/apimachinery/pkg/util/errors"
 	ctrlclient "sigs.k8s.io/controller-runtime/pkg/client"
-	"sigs.k8s.io/controller-runtime/pkg/controller"
 	"sigs.k8s.io/controller-runtime/pkg/controller/controllerutil"
 	"sigs.k8s.io/yaml"
 
@@ -509,25 +507,6 @@ func (vs *vSphereVMProvider) UpdateContentLibraryItem(ctx context.Context, itemI
 	return contentLibraryProvider.UpdateLibraryItem(ctx, itemID, newName, newDescription)
 }
 
-func (vs *vSphereVMProvider) getOpID(ctx context.Context, obj ctrlclient.Object, operation string) string {
-	var id string
-
-	if recID := controller.ReconcileIDFromContext(ctx); recID != "" {
-		id = string(recID[:8])
-	} else {
-		const charset = "0123456789abcdef"
-		buf := make([]byte, 8)
-		for i := range buf {
-			idx := rand.Intn(len(charset)) //nolint:gosec
-			buf[i] = charset[idx]
-		}
-		id = string(buf)
-		// TODO: Add this id as our own reconcile ID type?
-	}
-
-	return strings.Join([]string{"vmoperator", obj.GetName(), operation, id}, "-")
-}
-
 func (vs *vSphereVMProvider) getVM(
 	vmCtx pkgctx.VirtualMachineContext,
 	client *vcclient.Client,
@@ -627,15 +606,10 @@ func (vs *vSphereVMProvider) GetTasksByActID(ctx context.Context, vm *vmopv1.Vir
 	taskManager := task.NewManager(vcClient.VimClient())
 	filterSpec := vimtypes.TaskFilterSpec{}
 	if vm != nil {
-		vmCtx := pkgctx.VirtualMachineContext{
-			Context: context.WithValue(
-				ctx,
-				vimtypes.ID{},
-				vs.getOpID(ctx, vm, "GetCloneTasksForVM"),
-			),
-			Logger: logger,
-			VM:     vm,
-		}
+		vmCtx := pkgctx.NewVirtualMachineContext(
+			pkgctx.WithVCOpID(ctx, vm, "getCloneTasksForVM"),
+			vm,
+		)
 
 		vcVM, err := vs.getVM(vmCtx, vcClient, true)
 		if err != nil {

pkg/providers/vsphere/vmprovider_vm.go

@@ -183,15 +183,10 @@ func (vs *vSphereVMProvider) createOrUpdateVirtualMachine(
 		return nil, providers.ErrReconcileInProgress
 	}
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(
-			ctx,
-			vimtypes.ID{},
-			vs.getOpID(ctx, vm, "createOrUpdateVM"),
-		),
-		Logger: logger,
-		VM:     vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "createOrUpdateVM"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(vmCtx)
 	if err != nil {
@@ -329,11 +324,10 @@ func (vs *vSphereVMProvider) CleanupVirtualMachine(
 		return providers.ErrReconcileInProgress
 	}
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "cleanupVM")),
-		Logger:  pkglog.FromContextOrDefault(ctx),
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "cleanupVM"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(vmCtx)
 	if err != nil {
@@ -372,11 +366,10 @@ func (vs *vSphereVMProvider) DeleteVirtualMachine(
 		return providers.ErrReconcileInProgress
 	}
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "deleteVM")),
-		Logger:  pkglog.FromContextOrDefault(ctx),
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "deleteVM"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(vmCtx)
 	if err != nil {
@@ -464,11 +457,10 @@ func (vs *vSphereVMProvider) PublishVirtualMachine(
 		"vmName", vm.NamespacedName(), "clName", fmt.Sprintf("%s/%s", cl.Namespace, cl.Name))
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, fmt.Sprintf("%s-%s", vs.getOpID(ctx, vm, "publishVM"), actID)),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "publishVM-"+actID),
+		vm,
+	)
 
 	client, err := vs.getVcClient(ctx)
 	if err != nil {
@@ -521,11 +513,10 @@ func (vs *vSphereVMProvider) GetVirtualMachineGuestHeartbeat(
 	logger := pkglog.FromContextOrDefault(ctx).WithValues("vmName", vm.NamespacedName())
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "heartbeat")),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "heartbeat"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(vmCtx)
 	if err != nil {
@@ -553,11 +544,10 @@ func (vs *vSphereVMProvider) GetVirtualMachineProperties(
 	logger := pkglog.FromContextOrDefault(ctx).WithValues("vmName", vm.NamespacedName())
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "properties")),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "properties"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(vmCtx)
 	if err != nil {
@@ -616,11 +606,10 @@ func (vs *vSphereVMProvider) GetVirtualMachineWebMKSTicket(
 	logger := pkglog.FromContextOrDefault(ctx).WithValues("vmName", vm.NamespacedName())
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "webconsole")),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "webconsole"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(vmCtx)
 	if err != nil {
@@ -647,11 +636,10 @@ func (vs *vSphereVMProvider) GetVirtualMachineHardwareVersion(
 	logger := pkglog.FromContextOrDefault(ctx).WithValues("vmName", vm.NamespacedName())
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "hardware-version")),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "hardware-version"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(vmCtx)
 	if err != nil {

pkg/providers/vsphere/vmprovider_vm_group.go

@@ -45,7 +45,7 @@ func (vs *vSphereVMProvider) PlaceVirtualMachineGroup(
 	group *vmopv1.VirtualMachineGroup,
 	groupPlacements []providers.VMGroupPlacement) error {
 
-	ctx = context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, group, "groupPlacement"))
+	ctx = pkgctx.WithVCOpID(ctx, group, "groupPlacement")
 
 	vcClient, err := vs.getVcClient(ctx)
 	if err != nil {

pkg/providers/vsphere/vmprovider_vm_snapshot.go

@@ -49,11 +49,10 @@ func (vs *vSphereVMProvider) DeleteSnapshot(
 	logger := pkglog.FromContextOrDefault(ctx).WithValues("vmName", vm.NamespacedName())
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "deleteSnapshot")),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "deleteSnapshot"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(ctx)
 	if err != nil {
@@ -93,11 +92,10 @@ func (vs *vSphereVMProvider) GetSnapshotSize(
 	logger := pkglog.FromContextOrDefault(ctx).WithValues("vmName", vm.NamespacedName())
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "getSnapshotSize")),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "getSnapshotSize"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(ctx)
 	if err != nil {
@@ -131,11 +129,10 @@ func (vs *vSphereVMProvider) SyncVMSnapshotTreeStatus(ctx context.Context, vm *v
 	logger := pkglog.FromContextOrDefault(ctx).WithValues("vmName", vm.NamespacedName())
 	ctx = logr.NewContext(ctx, logger)
 
-	vmCtx := pkgctx.VirtualMachineContext{
-		Context: context.WithValue(ctx, vimtypes.ID{}, vs.getOpID(ctx, vm, "syncVMSnapshotTreeStatus")),
-		Logger:  logger,
-		VM:      vm,
-	}
+	vmCtx := pkgctx.NewVirtualMachineContext(
+		pkgctx.WithVCOpID(ctx, vm, "syncVMSnapshotTreeStatus"),
+		vm,
+	)
 
 	client, err := vs.getVcClient(ctx)
 	if err != nil {