xref: /dports/security/vault/vault-1.8.2/vendor/github.com/hashicorp/vic/pkg/trace/operation.go

// Copyright 2016 VMware, Inc. All Rights Reserved.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//    http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

package trace

import (
	"bytes"
	"context"
	"fmt"
	"os"
	"sync/atomic"
	"time"

	"github.com/sirupsen/logrus"

	"github.com/vmware/govmomi/vim25/types"
)

type OperationKey string

const OpTraceKey OperationKey = "traceKey"

var opIDPrefix = os.Getpid()

// opCount is a monotonic counter which increments on Start()
var opCount uint64

type Operation struct {
	context.Context
	operation

	// Logger is used to configure an Operation-specific destination for log messages, in addition
	// to the global logger. This logger is passed to any children which are created.
	Logger *logrus.Logger
}

type operation struct {
	t  []Message
	id string
	// TODO: might want to do this via a Formatter, but just testing here
	indent string
}

func newOperation(ctx context.Context, id string, skip int, msg string) *Operation {
	op := operation{

		// Can be used to trace based on this number which is unique per chain
		// of operations
		id: id,
	}

	o := &Operation{
		Context:   ctx,
		operation: op,
	}

	// Start the trace.
	o.operation.t = []Message{*newTrace(msg, skip, o)}

	// We need to be able to identify this operation across API (and process)
	// boundaries.  So add the trace as a value to the embedded context.  We
	// stash the values individually in the context because we can't assign
	// the operation itself as a value to the embedded context (it's circular)
	ctx = context.WithValue(ctx, OpTraceKey, op)

	// By adding the op.id any operations passed to govmomi will result
	// in the op.id being logged in vSphere (vpxa / hostd) as the prefix to opID
	// For example if the op.id was 299.16 hostd would show
	// verbose hostd[12281B70] [Originator@6876 sub=PropertyProvider opID=299.16-5b05 user=root]
	ctx = context.WithValue(ctx, types.ID{}, op.id)

	return o
}

// Creates a header string to be printed.
func (o *Operation) header() string {
	return fmt.Sprintf("op=%s", o.id)
}

// Err returns a non-nil error value after Done is closed.  Err returns
// Canceled if the context was canceled or DeadlineExceeded if the
// context's deadline passed.  No other values for Err are defined.
// After Done is closed, successive calls to Err return the same value.
func (o Operation) Err() error {

	// Walk up the contexts from which this context was created and get their errors
	if err := o.Context.Err(); err != nil {
		buf := &bytes.Buffer{}

		// Add a frame for this Err call, then walk the stack
		currFrame := newTrace("Err", 2, &o)
		fmt.Fprintf(buf, "%s: %s error: %s\n", currFrame.funcName, o.t[0].msg, err)

		// handle the carriage return
		numFrames := len(o.t)

		for i, t := range o.t {
			fmt.Fprintf(buf, "%-15s:%d %s", t.funcName, t.lineNo, t.msg)

			// don't add a cr on the last frame
			if i != numFrames-1 {
				buf.WriteByte('\n')
			}
		}

		// Print the error
		o.Errorf(buf.String())

		return err
	}

	return nil
}

func (o Operation) String() string {
	return o.header()
}

func (o *Operation) ID() string {
	return o.id
}

func (o *Operation) Auditf(format string, args ...interface{}) {
	o.Infof(format, args...)
}

func (o *Operation) Infof(format string, args ...interface{}) {
	o.Info(fmt.Sprintf(format, args...))
}

func (o *Operation) Info(args ...interface{}) {
	msg := fmt.Sprint(args...)

	Logger.Infof("%s: %s%s", o.header(), o.indent, msg)

	if o.Logger != nil {
		o.Logger.Info(msg)
	}
}

func (o *Operation) Debugf(format string, args ...interface{}) {
	o.Debug(fmt.Sprintf(format, args...))
}

func (o *Operation) Debug(args ...interface{}) {
	msg := fmt.Sprint(args...)

	Logger.Debugf("%s: %s%s", o.header(), o.indent, msg)

	if o.Logger != nil {
		o.Logger.Debug(msg)
	}
}

func (o *Operation) Warnf(format string, args ...interface{}) {
	o.Warn(fmt.Sprintf(format, args...))
}

func (o *Operation) Warn(args ...interface{}) {
	msg := fmt.Sprint(args...)

	Logger.Warnf("%s: %s%s", o.header(), o.indent, msg)

	if o.Logger != nil {
		o.Logger.Warn(msg)
	}
}

func (o *Operation) Errorf(format string, args ...interface{}) {
	o.Error(fmt.Sprintf(format, args...))
}

func (o *Operation) Error(args ...interface{}) {
	msg := fmt.Sprint(args...)

	Logger.Errorf("%s: %s%s", o.header(), o.indent, msg)

	if o.Logger != nil {
		o.Logger.Error(msg)
	}
}

func (o *Operation) Panicf(format string, args ...interface{}) {
	o.Panic(fmt.Sprintf(format, args...))
}

func (o *Operation) Panic(args ...interface{}) {
	msg := fmt.Sprint(args...)

	Logger.Panicf("%s: %s%s", o.header(), o.indent, msg)

	if o.Logger != nil {
		o.Logger.Panic(msg)
	}
}

func (o *Operation) Fatalf(format string, args ...interface{}) {
	o.Fatal(fmt.Sprintf(format, args...))
}

func (o *Operation) Fatal(args ...interface{}) {
	msg := fmt.Sprint(args...)

	Logger.Fatalf("%s: %s%s", o.header(), o.indent, msg)

	if o.Logger != nil {
		o.Logger.Fatal(msg)
	}
}

func (o *Operation) newChildCommon(ctx context.Context, opID string, msg string) *Operation {
	child := newOperation(ctx, opID, 5, msg)
	child.t = append(child.t, o.t...)
	child.Logger = o.Logger
	// increase the indent
	child.indent = o.indent + "  "

	o.Debugf("[ChildOperation: %s] %s", child.id, msg)
	return child
}

func (o *Operation) newChild(ctx context.Context, msg string) *Operation {
	return o.newChildCommon(ctx, opID(atomic.AddUint64(&opCount, 1)), msg)
}

func (o *Operation) newChildWithChainedID(ctx context.Context, msg string) *Operation {
	childOpID := fmt.Sprintf("%s.%d", o.id, atomic.AddUint64(&opCount, 1))
	return o.newChildCommon(ctx, childOpID, msg)
}

func opID(opNum uint64) string {
	return fmt.Sprintf("%d.%d", opIDPrefix, opNum)
}

// NewOperation will return a new operation with operationID added as a value to the context
func NewOperation(ctx context.Context, format string, args ...interface{}) Operation {
	return *decoratedNewOperation(ctx, "NewOperation", format, args...)
}

func decoratedNewOperation(ctx context.Context, decoration, format string, args ...interface{}) *Operation {
	detail := fmt.Sprintf(format, args...)
	o := newOperation(ctx, opID(atomic.AddUint64(&opCount, 1)), 4, detail)

	frame := o.t[0]
	o.Debugf("[%s][%s:%d] %s", decoration, frame.funcName, frame.lineNo, detail)
	return o
}

// NewOperationFromID returns a an Operation with the incoming ID if valid
// It creates a parent operation with the incoming ID and a child with
// the parent operation ID as a prefix and a monotonically incremented
// integer as the suffix
func NewOperationFromID(ctx context.Context, ID *string, format string, args ...interface{}) Operation {
	var o Operation
	if ID == nil || *ID == "" {
		o = *newOperation(ctx, opID(atomic.AddUint64(&opCount, 1)), 3, fmt.Sprintf(format, args...))
	} else {
		msg := fmt.Sprintf(format, args...)
		o = *newOperation(ctx, *ID, 3, msg).newChildWithChainedID(ctx, msg)
	}

	frame := o.t[0]
	o.Debugf("[NewOperationFromID] %s [%s:%d]", o.header(), frame.funcName, frame.lineNo)
	return o
}

// NewOperationWithLoggerFrom will return a new operation with operationID added as a value to the
// context and logging settings copied from the supplied operation.
//
// Deprecated: This method was added to aid in converting old code to use operation-based logging.
//             Its use almost always indicates a broken context/operation model (e.g., a context
//             being improperly stored in a struct instead of being passed between functions).
func NewOperationWithLoggerFrom(ctx context.Context, oldOp Operation, format string, args ...interface{}) Operation {
	op := NewOperation(ctx, format, args...)
	op.Logger = oldOp.Logger
	return op
}

// WithTimeout creates a new operation from parent with context.WithTimeout
func WithTimeout(parent *Operation, timeout time.Duration, format string, args ...interface{}) (Operation, context.CancelFunc) {
	ctx, cancelFunc := context.WithTimeout(parent.Context, timeout)
	op := parent.newChild(ctx, fmt.Sprintf(format, args...))

	return *op, cancelFunc
}

// WithDeadline creates a new operation from parent with context.WithDeadline
func WithDeadline(parent *Operation, expiration time.Time, format string, args ...interface{}) (Operation, context.CancelFunc) {
	ctx, cancelFunc := context.WithDeadline(parent.Context, expiration)
	op := parent.newChild(ctx, fmt.Sprintf(format, args...))

	return *op, cancelFunc
}

// WithCancel creates a new operation from parent with context.WithCancel
func WithCancel(parent *Operation, format string, args ...interface{}) (Operation, context.CancelFunc) {
	ctx, cancelFunc := context.WithCancel(parent.Context)
	op := parent.newChild(ctx, fmt.Sprintf(format, args...))

	return *op, cancelFunc
}

// WithValue creates a new operation from parent with context.WithValue
func WithValue(parent *Operation, key, val interface{}, format string, args ...interface{}) Operation {
	ctx := context.WithValue(parent.Context, key, val)
	op := parent.newChild(ctx, fmt.Sprintf(format, args...))

	return *op
}

// FromOperation creates a child operation from the one supplied
// uses the same context as the parent
func FromOperation(parent Operation, format string, args ...interface{}) Operation {
	return *parent.newChild(parent.Context, fmt.Sprintf(format, args...))
}

// fromContext will return an Operation
//
// The Operation returned will be one of the following:
//   The operation in the context value
//   The operation passed as the context param
//   nil if neither of the above are true
func fromContext(ctx context.Context) *Operation {

	// do we have an operation - if we do we're creating a new child from the one in the context
	// While we could just use it directly we'd be losing the presumably valuable message
	if op, ok := ctx.(Operation); ok {
		return &op
	}

	// do we have a context w/the op added as a value
	op, ok := ctx.Value(OpTraceKey).(operation)
	if !ok || op.id == "" {
		return nil
	}

	// return an operation based off the context value
	return &Operation{
		Context:   ctx,
		operation: op,
	}
}

// FromContext will return an Operation. The message will only be used in the case of
// a new Operation being created, i.e. there was no operation found in the context
//
// The Operation returned will be one of the following:
//   The operation in the context value
//   The operation passed as the context param
//   A new operation
func FromContext(ctx context.Context, message string, args ...interface{}) Operation {
	cop := fromContext(ctx)
	if cop != nil {
		return *cop
	}

	return *decoratedNewOperation(ctx, "NewOperationFromContext", message, args...)
}

// ChildFromContext will return an Operation
//
// The Operation returned will be one of the following:
//   A child of the operation in the context value
//   A child of the operation passed as the context param
//   A new operation
func ChildFromContext(ctx context.Context, message string, args ...interface{}) Operation {

	// do we have an operation - if we do we're creating a new child from the one in the context
	// While we could just use it directly we'd be losing the presumably valuable message
	parent := fromContext(ctx)
	if parent != nil {
		return *parent.newChild(parent.Context, fmt.Sprintf(message, args...))
	}

	return *decoratedNewOperation(ctx, "NewChildFromContext", message, args...)
}