Add operation id to vSphere calls

Increase use of trace.Operation as well as pass the
operation.ID to vSphere for observability within the
vSphere logs.

Fixes vmware#2739

lib/apiservers/engine/backends/eventmonitor.go

@@ -39,6 +39,7 @@ import (
 	"github.com/vmware/vic/lib/apiservers/portlayer/client/events"
 	plevents "github.com/vmware/vic/lib/portlayer/event/events"
 	"github.com/vmware/vic/pkg/trace"
+	"github.com/vmware/vic/pkg/uid"
 )
 
 const (
@@ -211,19 +212,22 @@ func (m *PortlayerEventMonitor) monitor() error {
 	return nil
 }
 
-// publishEvent() translate a portlayer event into a Docker event if the event is for a
-// known container and publishes them to Docker event subscribers.
+// PublishEvent translates select portlayer container events into Docker events
+// and publishes to subscribers
 func (p DockerEventPublisher) PublishEvent(event plevents.BaseEvent) {
-	defer trace.End(trace.Begin(""))
+	// create a shortID for the container for logging purposes
+	containerShortID := uid.Parse(event.Ref).Truncate()
+	defer trace.End(trace.Begin(fmt.Sprintf("Event Monitor received eventID(%s) for container(%s) - %s", event.ID, containerShortID, event.Event)))
 
 	vc := cache.ContainerCache().GetContainer(event.Ref)
 	if vc == nil {
-		log.Warnf("Received portlayer event %s for container %s but not found in cache", event.Event, event.Ref)
+		log.Warnf("Event Monitor received eventID(%s) but container(%s) not in cache", event.ID, containerShortID)
 		return
 	}
 
+	// docker event attributes
 	var attrs map[string]string
-	// TODO: move to a container.OnEvent() so that container drives the necessary changes based on event activity
+
 	switch event.Event {
 	case plevents.ContainerStopped,
 		plevents.ContainerPoweredOff,
@@ -234,13 +238,13 @@ func (p DockerEventPublisher) PublishEvent(event plevents.BaseEvent) {
 			// get the containerEngine
 			code, _ := NewContainerBackend().containerProxy.exitCode(vc)
 
-			log.Infof("Sending die event for container %s - code: %s", vc.ContainerID, code)
+			log.Infof("Sending die event for container(%s) with exitCode[%s] - eventID(%s)", containerShortID, code, event.ID)
 			// if the docker client is unable to convert the code to an int the client will return 125
 			attrs["exitCode"] = code
 			actor := CreateContainerEventActorWithAttributes(vc, attrs)
 			EventService().Log(containerDieEvent, eventtypes.ContainerEventType, actor)
 			if err := UnmapPorts(vc.ContainerID, vc.HostConfig); err != nil {
-				log.Errorf("Failed to unmap ports for container %s: %s", vc.ContainerID, err)
+				log.Errorf("Event Monitor failed to unmap ports for container(%s): %s - eventID(%s)", containerShortID, err, event.ID)
 			}
 
 			// auto-remove if required
@@ -252,7 +256,7 @@ func (p DockerEventPublisher) PublishEvent(event plevents.BaseEvent) {
 
 				err := NewContainerBackend().ContainerRm(vc.Name, config)
 				if err != nil {
-					log.Errorf("Failed to remove container %s: %s", vc.ContainerID, err)
+					log.Errorf("Event Monitor failed to remove container(%s) - eventID(%s): %s", containerShortID, event.ID, err)
 				}
 			}
 		}()
@@ -262,7 +266,7 @@ func (p DockerEventPublisher) PublishEvent(event plevents.BaseEvent) {
 		actor := CreateContainerEventActorWithAttributes(vc, attrs)
 		EventService().Log(containerDestroyEvent, eventtypes.ContainerEventType, actor)
 		if err := UnmapPorts(vc.ContainerID, vc.HostConfig); err != nil {
-			log.Errorf("Failed to unmap ports for container %s: %s", vc.ContainerID, err)
+			log.Errorf("Event Monitor failed to unmap ports for container(%s): %s - eventID(%s)", containerShortID, err, event.ID)
 		}
 		// remove from the container cache...
 		cache.ContainerCache().DeleteContainer(vc.ContainerID)

lib/apiservers/portlayer/restapi/handlers/containers_handlers.go

@@ -217,15 +217,16 @@ func (handler *ContainersHandlersImpl) GetHandler(params containers.GetParams) m
 }
 
 func (handler *ContainersHandlersImpl) CommitHandler(params containers.CommitParams) middleware.Responder {
-	defer trace.End(trace.Begin(fmt.Sprintf("handle(%s)", params.Handle)))
+	op := trace.NewOperation(context.Background(), fmt.Sprintf("commit handle(%s)", params.Handle))
+	defer trace.End(trace.Begin(fmt.Sprintf("commit handle(%s)", params.Handle), op))
 
 	h := exec.GetHandle(params.Handle)
 	if h == nil {
 		return containers.NewCommitNotFound().WithPayload(&models.Error{Message: "container not found"})
 	}
 
-	if err := h.Commit(context.Background(), handler.handlerCtx.Session, params.WaitTime); err != nil {
-		log.Errorf("CommitHandler error on handle(%s) for %s: %s", h, h.ExecConfig.ID, err)
+	if err := h.Commit(op, handler.handlerCtx.Session, params.WaitTime); err != nil {
+		op.Errorf("CommitHandler error on handle(%s) for %s: %s", h, h.ExecConfig.ID, err)
 		switch err := err.(type) {
 		case exec.ConcurrentAccessError:
 			return containers.NewCommitConflict().WithPayload(&models.Error{Message: err.Error()})
@@ -240,7 +241,8 @@ func (handler *ContainersHandlersImpl) CommitHandler(params containers.CommitPar
 }
 
 func (handler *ContainersHandlersImpl) RemoveContainerHandler(params containers.ContainerRemoveParams) middleware.Responder {
-	defer trace.End(trace.Begin(params.ID))
+	op := trace.NewOperation(context.Background(), params.ID)
+	defer trace.End(trace.Begin(params.ID, op))
 
 	// get the indicated container for removal
 	container := exec.Containers.Container(params.ID)
@@ -249,7 +251,7 @@ func (handler *ContainersHandlersImpl) RemoveContainerHandler(params containers.
 	}
 
 	// NOTE: this should allowing batching of operations, as with Create, Start, Stop, et al
-	err := container.Remove(context.Background(), handler.handlerCtx.Session)
+	err := container.Remove(op, handler.handlerCtx.Session)
 	if err != nil {
 		switch err := err.(type) {
 		case exec.NotFoundError:
@@ -272,17 +274,18 @@ func (handler *ContainersHandlersImpl) RemoveContainerHandler(params containers.
 }
 
 func (handler *ContainersHandlersImpl) GetContainerInfoHandler(params containers.GetContainerInfoParams) middleware.Responder {
-	defer trace.End(trace.Begin(params.ID))
+	op := trace.NewOperation(context.Background(), params.ID)
+	defer trace.End(trace.Begin(params.ID, op))
 
 	container := exec.Containers.Container(params.ID)
 	if container == nil {
 		info := fmt.Sprintf("GetContainerInfoHandler ContainerCache miss for container(%s)", params.ID)
-		log.Error(info)
+		op.Errorf(info)
 		return containers.NewGetContainerInfoNotFound().WithPayload(&models.Error{Message: info})
 	}
 
 	// Refresh to get up to date network info
-	container.Refresh(context.Background())
+	container.Refresh(op)
 	containerInfo := convertContainerToContainerInfo(container)
 	return containers.NewGetContainerInfoOK().WithPayload(containerInfo)
 }
@@ -319,7 +322,8 @@ func (handler *ContainersHandlersImpl) GetContainerListHandler(params containers
 }
 
 func (handler *ContainersHandlersImpl) ContainerSignalHandler(params containers.ContainerSignalParams) middleware.Responder {
-	defer trace.End(trace.Begin(params.ID))
+	op := trace.NewOperation(context.Background(), params.ID)
+	defer trace.End(trace.Begin(params.ID, op))
 
 	// NOTE: I feel that this should be in a Commit path for consistency
 	// it would allow phrasings such as:
@@ -331,7 +335,7 @@ func (handler *ContainersHandlersImpl) ContainerSignalHandler(params containers.
 		return containers.NewContainerSignalNotFound().WithPayload(&models.Error{Message: fmt.Sprintf("container %s not found", params.ID)})
 	}
 
-	err := container.Signal(context.Background(), params.Signal)
+	err := container.Signal(op, params.Signal)
 	if err != nil {
 		return containers.NewContainerSignalInternalServerError().WithPayload(&models.Error{Message: err.Error()})
 	}
@@ -394,7 +398,8 @@ func (handler *ContainersHandlersImpl) GetContainerStatsHandler(params container
 }
 
 func (handler *ContainersHandlersImpl) GetContainerLogsHandler(params containers.GetContainerLogsParams) middleware.Responder {
-	defer trace.End(trace.Begin(params.ID))
+	op := trace.NewOperation(context.Background(), params.ID)
+	defer trace.End(trace.Begin(params.ID, op))
 
 	container := exec.Containers.Container(params.ID)
 	if container == nil {
@@ -417,7 +422,7 @@ func (handler *ContainersHandlersImpl) GetContainerLogsHandler(params containers
 		since = *params.Since
 	}
 
-	reader, err := container.LogReader(context.Background(), tail, follow, since)
+	reader, err := container.LogReader(op, tail, follow, since)
 	if err != nil {
 		// Do not return an error here.  It's a workaround for a panic similar to #2594
 		return containers.NewGetContainerLogsInternalServerError()

lib/apiservers/portlayer/restapi/handlers/scopes_handlers.go

@@ -301,7 +301,8 @@ func (handler *ScopesHandlersImpl) ScopesBindContainer(params scopes.BindContain
 }
 
 func (handler *ScopesHandlersImpl) ScopesUnbindContainer(params scopes.UnbindContainerParams) middleware.Responder {
-	defer trace.End(trace.Begin(fmt.Sprintf("handle(%s)", params.Handle)))
+	op := trace.NewOperation(context.Background(), params.Handle)
+	defer trace.End(trace.Begin(fmt.Sprintf("handle(%s)", params.Handle), op))
 
 	h := exec.GetHandle(params.Handle)
 	if h == nil {
@@ -310,7 +311,7 @@ func (handler *ScopesHandlersImpl) ScopesUnbindContainer(params scopes.UnbindCon
 
 	var endpoints []*network.Endpoint
 	var err error
-	if endpoints, err = handler.netCtx.UnbindContainer(h); err != nil {
+	if endpoints, err = handler.netCtx.UnbindContainer(op, h); err != nil {
 		switch err := err.(type) {
 		case network.ResourceNotFoundError:
 			return scopes.NewUnbindContainerNotFound().WithPayload(errorPayload(err))

lib/install/management/debug.go

@@ -29,12 +29,9 @@ import (
 func (d *Dispatcher) DebugVCH(vch *vm.VirtualMachine, conf *config.VirtualContainerHostConfigSpec, password, authorizedKey string) error {
 	defer trace.End(trace.Begin(conf.Name))
 
-	op, err := trace.FromContext(d.ctx)
-	if err != nil {
-		op = trace.NewOperation(d.ctx, "enable appliance debug")
-	}
+	op := trace.FromContext(d.ctx, "enable appliance debug")
 
-	err = d.enableSSH(op, vch, password, authorizedKey)
+	err := d.enableSSH(op, vch, password, authorizedKey)
 	if err != nil {
 		op.Errorf("Unable to enable ssh on the VCH appliance VM: %s", err)
 		return err
@@ -46,10 +43,7 @@ func (d *Dispatcher) DebugVCH(vch *vm.VirtualMachine, conf *config.VirtualContai
 }
 
 func (d *Dispatcher) enableSSH(ctx context.Context, vch *vm.VirtualMachine, password, authorizedKey string) error {
-	op, err := trace.FromContext(ctx)
-	if err != nil {
-		op = trace.NewOperation(ctx, "enable ssh in appliance")
-	}
+	op := trace.FromContext(ctx, "enable ssh in appliance")
 
 	state, err := vch.PowerState(op)
 	if err != nil {
@@ -68,7 +62,7 @@ func (d *Dispatcher) enableSSH(ctx context.Context, vch *vm.VirtualMachine, pass
 		return err
 	}
 
-	pm, err := d.opManager(ctx, vch)
+	pm, err := d.opManager(op, vch)
 	if err != nil {
 		err = errors.Errorf("Unable to manage processes in appliance VM: %s", err)
 		op.Errorf("%s", err)
@@ -89,7 +83,7 @@ func (d *Dispatcher) enableSSH(ctx context.Context, vch *vm.VirtualMachine, pass
 		return err
 	}
 
-	_, err = d.opManagerWait(ctx, pm, &auth, pid)
+	_, err = d.opManagerWait(op, pm, &auth, pid)
 	if err != nil {
 		err = errors.Errorf("Unable to check enable SSH status: %s", err)
 		op.Errorf("%s", err)
@@ -113,7 +107,7 @@ func (d *Dispatcher) enableSSH(ctx context.Context, vch *vm.VirtualMachine, pass
 		return err
 	}
 
-	_, err = d.opManagerWait(ctx, pm, &auth, pid)
+	_, err = d.opManagerWait(op, pm, &auth, pid)
 	if err != nil {
 		err = errors.Errorf("Unable to check enable passwd status: %s", err)
 		op.Errorf("%s", err)

lib/migration/migrator.go

@@ -16,15 +16,13 @@ package migration
 
 import (
 	"context"
-	"fmt"
 	"strconv"
 
 	"github.com/vmware/vic/lib/migration/errors"
 	"github.com/vmware/vic/lib/migration/feature"
 	"github.com/vmware/vic/lib/migration/manager"
 	// imported for the side effect
 	_ "github.com/vmware/vic/lib/migration/plugins"
-	"github.com/vmware/vic/pkg/trace"
 	"github.com/vmware/vic/pkg/vsphere/session"
 )
 
@@ -74,7 +72,6 @@ func dataIsOlder(data map[string]string, target string, verKey string) (bool, er
 }
 
 func migrateConfig(ctx context.Context, s *session.Session, data map[string]string, target string, verKey string) (map[string]string, bool, error) {
-	defer trace.End(trace.Begin(fmt.Sprintf("target: %s, version key: %s", target, verKey)))
 
 	dst := make(map[string]string)
 	for k, v := range data {

lib/portlayer/event/collector/vsphere/vm_event.go

@@ -15,9 +15,11 @@
 package vsphere
 
 import (
-	"github.com/vmware/vic/lib/portlayer/event/events"
+	"strconv"
 
 	"github.com/vmware/govmomi/vim25/types"
+
+	"github.com/vmware/vic/lib/portlayer/event/events"
 )
 
 type VMEvent struct {
@@ -52,7 +54,7 @@ func NewVMEvent(be types.BaseEvent) *VMEvent {
 	return &VMEvent{
 		&events.BaseEvent{
 			Event:       ee,
-			ID:          int(e.Key),
+			ID:          strconv.Itoa(int(e.Key)),
 			Detail:      e.FullFormattedMessage,
 			Ref:         e.Vm.Vm.String(),
 			CreatedTime: e.CreatedTime,

lib/portlayer/event/collector/vsphere/vm_event_test.go

@@ -15,6 +15,7 @@
 package vsphere
 
 import (
+	"strconv"
 	"testing"
 	"time"
 
@@ -34,7 +35,7 @@ func TestNewEvent(t *testing.T) {
 	assert.NotNil(t, vme)
 	assert.Equal(t, events.ContainerPoweredOn, vme.String())
 	assert.Equal(t, vm.String(), vme.Reference())
-	assert.Equal(t, k, vme.EventID())
+	assert.Equal(t, strconv.Itoa(k), vme.EventID())
 	assert.Equal(t, msg, vme.Message())
 	assert.Equal(t, "vsphere.VMEvent", vme.Topic())
 	assert.Equal(t, tt, vme.Created())

lib/portlayer/event/events/base_event.go

@@ -26,13 +26,13 @@ type EventType string
 type BaseEvent struct {
 	Type        EventType
 	Event       string
-	ID          int
+	ID          string
 	Detail      string
 	Ref         string
 	CreatedTime time.Time
 }
 
-func (be *BaseEvent) EventID() int {
+func (be *BaseEvent) EventID() string {
 	return be.ID
 }
 
@@ -48,6 +48,7 @@ func (be *BaseEvent) Message() string {
 func (be *BaseEvent) Reference() string {
 	return be.Ref
 }
+
 func (be *BaseEvent) Created() time.Time {
 	return be.CreatedTime
 }

lib/portlayer/event/events/base_event_test.go

@@ -30,13 +30,13 @@ func TestNewEventType(t *testing.T) {
 func TestBaseEvent(t *testing.T) {
 	be := &BaseEvent{
 		Event:  "PoweredOn",
-		ID:     12,
+		ID:     "12",
 		Detail: "VM 123 PoweredOn",
 		Ref:    "vm:12",
 	}
 
 	assert.Equal(t, "PoweredOn", be.String())
-	assert.Equal(t, 12, be.EventID())
+	assert.Equal(t, "12", be.EventID())
 	assert.Equal(t, "VM 123 PoweredOn", be.Message())
 	assert.Equal(t, "vm:12", be.Reference())
 

lib/portlayer/event/events/events.go

@@ -21,7 +21,7 @@ import (
 type Event interface {
 	EventTopic
 	// id of event
-	EventID() int
+	EventID() string
 	// event (PowerOn, PowerOff, etc)
 	String() string
 	// reference evented object

lib/portlayer/event/manager.go

@@ -18,11 +18,11 @@ import (
 	"fmt"
 	"sync"
 
-	log "github.com/Sirupsen/logrus"
-
 	"github.com/vmware/vic/lib/portlayer/event/collector"
 	"github.com/vmware/vic/lib/portlayer/event/events"
 	"github.com/vmware/vic/pkg/trace"
+
+	log "github.com/Sirupsen/logrus"
 )
 
 type Manager struct {
@@ -69,10 +69,10 @@ func NewEventManager(collectors ...collector.Collector) *Manager {
 			subs := mgr.subs.subscribers[e.Topic()]
 			mgr.subs.mu.RUnlock()
 
-			log.Debugf("Found %d subscribers to id: %d - %s: %s", len(subs), e.EventID(), e.Topic(), e.Message())
+			log.Debugf("Found %d subscribers to %s: %s - %s", len(subs), e.EventID(), e.Topic(), e.Message())
 
 			for sub, s := range subs {
-				log.Debugf("Event manager calling back to %s for %d - %s: %s", sub, e.EventID(), e.Topic(), e.Message())
+				log.Debugf("Event manager calling back to %s for Event(%s): %s", sub, e.EventID(), e.Topic())
 				s.onEvent(e)
 			}
 		}