pkg/log/utils.go

/*
 * Copyright 2018-present Open Networking Foundation

 * 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.
 */

// File contains utility functions to support Open Tracing in conjunction with
// Enhanced Logging based on context propagation

package log

import (
	"context"
	"errors"
	"fmt"
	"github.com/opentracing/opentracing-go"
	jtracing "github.com/uber/jaeger-client-go"
	jcfg "github.com/uber/jaeger-client-go/config"
	"io"
	"os"
	"strings"
	"sync"
)

const (
	RootSpanNameKey = "op-name"
)

// Global Settings governing the Log Correlation and Tracing features. Should only
// be updated through the exposed public methods
type LogFeaturesManager struct {
	isTracePublishingEnabled bool
	isLogCorrelationEnabled  bool
	componentName            string // Name of component extracted from ENV variable
	activeTraceAgentAddress  string
	lock                     sync.Mutex
}

var globalLFM *LogFeaturesManager = &LogFeaturesManager{}

func GetGlobalLFM() *LogFeaturesManager {
	return globalLFM
}

// A Wrapper to utilize currently Active Tracer instance. The middleware library being used for generating
// Spans for GRPC API calls does not support dynamically setting the Active Tracer similar to the SetGlobalTracer method
// provided by OpenTracing API
type ActiveTracerProxy struct {
}

func (atw ActiveTracerProxy) StartSpan(operationName string, opts ...opentracing.StartSpanOption) opentracing.Span {
	return opentracing.GlobalTracer().StartSpan(operationName, opts...)
}

func (atw ActiveTracerProxy) Inject(sm opentracing.SpanContext, format interface{}, carrier interface{}) error {
	return opentracing.GlobalTracer().Inject(sm, format, carrier)
}

func (atw ActiveTracerProxy) Extract(format interface{}, carrier interface{}) (opentracing.SpanContext, error) {
	return opentracing.GlobalTracer().Extract(format, carrier)
}

// Jaeger complaint Logger instance to redirect logs to Default Logger
type traceLogger struct {
	logger *clogger
}

func (tl traceLogger) Error(msg string) {
	tl.logger.Error(context.Background(), msg)
}

func (tl traceLogger) Infof(msg string, args ...interface{}) {
	// Tracing logs should be performed only at Debug Verbosity
	tl.logger.Debugf(context.Background(), msg, args...)
}

// Wrapper to handle correct Closer call at the time of Process Termination
type traceCloser struct {
}

func (c traceCloser) Close() error {
	currentActiveTracer := opentracing.GlobalTracer()
	if currentActiveTracer != nil {
		if jTracer, ok := currentActiveTracer.(*jtracing.Tracer); ok {
			jTracer.Close()
		}
	}

	return nil
}

// Method to Initialize Jaeger based Tracing client based on initial status of Tracing Publish and Log Correlation
func (lfm *LogFeaturesManager) InitTracingAndLogCorrelation(tracePublishEnabled bool, traceAgentAddress string, logCorrelationEnabled bool) (io.Closer, error) {
	lfm.componentName = os.Getenv("COMPONENT_NAME")
	if lfm.componentName == "" {
		return nil, errors.New("Unable to retrieve PoD Component Name from Runtime env")
	}

	lfm.lock.Lock()
	defer lfm.lock.Unlock()

	// Use NoopTracer when both Tracing Publishing and Log Correlation are disabled
	if !tracePublishEnabled && !logCorrelationEnabled {
		logger.Info(context.Background(), "Skipping Global Tracer initialization as both Trace publish and Log correlation are configured as disabled")
		lfm.isTracePublishingEnabled = false
		lfm.isLogCorrelationEnabled = false
		opentracing.SetGlobalTracer(opentracing.NoopTracer{})
		return traceCloser{}, nil
	}

	tracer, _, err := lfm.constructJaegerTracer(tracePublishEnabled, traceAgentAddress, true)
	if err != nil {
		return nil, err
	}

	// Initialize variables representing Active Status
	opentracing.SetGlobalTracer(tracer)
	lfm.isTracePublishingEnabled = tracePublishEnabled
	lfm.activeTraceAgentAddress = traceAgentAddress
	lfm.isLogCorrelationEnabled = logCorrelationEnabled
	return traceCloser{}, nil
}

// Method to replace Active Tracer along with graceful closer of previous tracer
func (lfm *LogFeaturesManager) replaceActiveTracer(tracer opentracing.Tracer) {
	currentActiveTracer := opentracing.GlobalTracer()
	opentracing.SetGlobalTracer(tracer)

	if currentActiveTracer != nil {
		if jTracer, ok := currentActiveTracer.(*jtracing.Tracer); ok {
			jTracer.Close()
		}
	}
}

func (lfm *LogFeaturesManager) GetLogCorrelationStatus() bool {
	lfm.lock.Lock()
	defer lfm.lock.Unlock()

	return lfm.isLogCorrelationEnabled
}

func (lfm *LogFeaturesManager) SetLogCorrelationStatus(isEnabled bool) {
	lfm.lock.Lock()
	defer lfm.lock.Unlock()

	if isEnabled == lfm.isLogCorrelationEnabled {
		logger.Debugf(context.Background(), "Ignoring Log Correlation Set operation with value %t; current Status same as desired", isEnabled)
		return
	}

	if isEnabled {
		// Construct new Tracer instance if Log Correlation has been enabled and current active tracer is a NoopTracer instance.
		// Continue using the earlier tracer instance in case of any error
		if _, ok := opentracing.GlobalTracer().(opentracing.NoopTracer); ok {
			tracer, _, err := lfm.constructJaegerTracer(lfm.isTracePublishingEnabled, lfm.activeTraceAgentAddress, false)
			if err != nil {
				logger.Warnf(context.Background(), "Log Correlation Enable operation failed with error: %s", err.Error())
				return
			}

			lfm.replaceActiveTracer(tracer)
		}

		lfm.isLogCorrelationEnabled = true
		logger.Info(context.Background(), "Log Correlation has been enabled")

	} else {
		// Switch to NoopTracer when Log Correlation has been disabled and Tracing Publish is already disabled
		if _, ok := opentracing.GlobalTracer().(opentracing.NoopTracer); !ok && !lfm.isTracePublishingEnabled {
			lfm.replaceActiveTracer(opentracing.NoopTracer{})
		}

		lfm.isLogCorrelationEnabled = false
		logger.Info(context.Background(), "Log Correlation has been disabled")
	}
}

func (lfm *LogFeaturesManager) GetTracePublishingStatus() bool {
	lfm.lock.Lock()
	defer lfm.lock.Unlock()

	return lfm.isTracePublishingEnabled
}

func (lfm *LogFeaturesManager) SetTracePublishingStatus(isEnabled bool) {
	lfm.lock.Lock()
	defer lfm.lock.Unlock()

	if isEnabled == lfm.isTracePublishingEnabled {
		logger.Debugf(context.Background(), "Ignoring Trace Publishing Set operation with value %t; current Status same as desired", isEnabled)
		return
	}

	if isEnabled {
		// Construct new Tracer instance if Tracing Publish has been enabled (even if a Jaeger instance is already active)
		// This is needed to ensure that a fresh lookup of Jaeger Agent address is performed again while performing
		// Disable-Enable of Tracing
		tracer, _, err := lfm.constructJaegerTracer(isEnabled, lfm.activeTraceAgentAddress, false)
		if err != nil {
			logger.Warnf(context.Background(), "Trace Publishing Enable operation failed with error: %s", err.Error())
			return
		}
		lfm.replaceActiveTracer(tracer)

		lfm.isTracePublishingEnabled = true
		logger.Info(context.Background(), "Tracing Publishing has been enabled")
	} else {
		// Switch to NoopTracer when Tracing Publish has been disabled and Log Correlation is already disabled
		if !lfm.isLogCorrelationEnabled {
			lfm.replaceActiveTracer(opentracing.NoopTracer{})
		} else {
			// Else construct a new Jaeger Instance with publishing disabled
			tracer, _, err := lfm.constructJaegerTracer(isEnabled, lfm.activeTraceAgentAddress, false)
			if err != nil {
				logger.Warnf(context.Background(), "Trace Publishing Disable operation failed with error: %s", err.Error())
				return
			}
			lfm.replaceActiveTracer(tracer)
		}

		lfm.isTracePublishingEnabled = false
		logger.Info(context.Background(), "Tracing Publishing has been disabled")
	}
}

// Method to contruct a new Jaeger Tracer instance based on given Trace Agent address and Publish status.
// The last attribute indicates whether to use Loopback IP for creating Jaeger Client when the DNS lookup
// of supplied Trace Agent address has failed. It is fine to fallback during the initialization step, but
// not later (when enabling/disabling the status dynamically)
func (lfm *LogFeaturesManager) constructJaegerTracer(tracePublishEnabled bool, traceAgentAddress string, fallbackToLoopbackAllowed bool) (opentracing.Tracer, io.Closer, error) {
	cfg := jcfg.Configuration{ServiceName: lfm.componentName}

	var err error
	var jReporterConfig jcfg.ReporterConfig
	var jReporterCfgOption jtracing.Reporter

	logger.Info(context.Background(), "Constructing new Jaeger Tracer instance")

	// Attempt Trace Agent Address first; will fallback to Loopback IP if it fails
	jReporterConfig = jcfg.ReporterConfig{LocalAgentHostPort: traceAgentAddress, LogSpans: true}
	jReporterCfgOption, err = jReporterConfig.NewReporter(lfm.componentName, jtracing.NewNullMetrics(), traceLogger{logger: logger.(*clogger)})

	if err != nil {
		if !fallbackToLoopbackAllowed {
			return nil, nil, errors.New("Reporter Creation for given Trace Agent address " + traceAgentAddress + " failed with error : " + err.Error())
		}

		logger.Infow(context.Background(), "Unable to create Reporter with given Trace Agent address",
			Fields{"error": err, "address": traceAgentAddress})
		// The Reporter initialization may fail due to Invalid Agent address or non-existent Agent (DNS lookup failure).
		// It is essential for Tracer Instance to still start for correct Span propagation needed for log correlation.
		// Thus, falback to use loopback IP for Reporter initialization before throwing back any error
		tracePublishEnabled = false

		jReporterConfig.LocalAgentHostPort = "127.0.0.1:6831"
		jReporterCfgOption, err = jReporterConfig.NewReporter(lfm.componentName, jtracing.NewNullMetrics(), traceLogger{logger: logger.(*clogger)})
		if err != nil {
			return nil, nil, errors.New("Failed to initialize Jaeger Tracing due to Reporter creation error : " + err.Error())
		}
	}

	// To start with, we are using Constant Sampling type
	samplerParam := 0 // 0: Do not publish span, 1: Publish
	if tracePublishEnabled {
		samplerParam = 1
	}
	jSamplerConfig := jcfg.SamplerConfig{Type: "const", Param: float64(samplerParam)}
	jSamplerCfgOption, err := jSamplerConfig.NewSampler(lfm.componentName, jtracing.NewNullMetrics())
	if err != nil {
		return nil, nil, errors.New("Unable to create Sampler : " + err.Error())
	}

	return cfg.NewTracer(jcfg.Reporter(jReporterCfgOption), jcfg.Sampler(jSamplerCfgOption))
}

func TerminateTracing(c io.Closer) {
	err := c.Close()
	if err != nil {
		logger.Error(context.Background(), "error-while-closing-jaeger-tracer", Fields{"err": err})
	}
}

// Extracts details of Execution Context as log fields from the Tracing Span injected into the
// context instance. Following log fields are extracted:
// 1. Operation Name : key as 'op-name' and value as Span operation name
// 2. Operation Id : key as 'op-id' and value as 64 bit Span Id in hex digits string
//
// Additionally, any tags present in Span are also extracted to use as log fields e.g. device-id.
//
// If no Span is found associated with context, blank slice is returned without any log fields
func (lfm *LogFeaturesManager) ExtractContextAttributes(ctx context.Context) []interface{} {
	if !lfm.isLogCorrelationEnabled {
		return make([]interface{}, 0)
	}

	attrMap := make(map[string]interface{})

	if ctx != nil {
		if span := opentracing.SpanFromContext(ctx); span != nil {
			if jspan, ok := span.(*jtracing.Span); ok {
				// Add Log fields for operation identified by Root Level Span (Trace)
				opId := fmt.Sprintf("%016x", jspan.SpanContext().TraceID().Low) // Using Sprintf to avoid removal of leading 0s
				opName := jspan.BaggageItem(RootSpanNameKey)

				taskId := fmt.Sprintf("%016x", uint64(jspan.SpanContext().SpanID())) // Using Sprintf to avoid removal of leading 0s
				taskName := jspan.OperationName()

				if opName == "" {
					span.SetBaggageItem(RootSpanNameKey, taskName)
					opName = taskName
				}

				attrMap["op-id"] = opId
				attrMap["op-name"] = opName

				// Add Log fields for task identified by Current Span, if it is different
				// than operation
				if taskId != opId {
					attrMap["task-id"] = taskId
					attrMap["task-name"] = taskName
				}

				for k, v := range jspan.Tags() {
					// Ignore the special tags added by Jaeger, middleware (sampler.type, span.*) present in the span
					if strings.HasPrefix(k, "sampler.") || strings.HasPrefix(k, "span.") || k == "component" {
						continue
					}

					attrMap[k] = v
				}

				processBaggageItems := func(k, v string) bool {
					if k != "rpc-span-name" {
						attrMap[k] = v
					}
					return true
				}

				jspan.SpanContext().ForeachBaggageItem(processBaggageItems)
			}
		}
	}

	return serializeMap(attrMap)
}

// Method to inject additional log fields into Span e.g. device-id
func EnrichSpan(ctx context.Context, keyAndValues ...Fields) {
	span := opentracing.SpanFromContext(ctx)
	if span != nil {
		if jspan, ok := span.(*jtracing.Span); ok {
			// Inject as a BaggageItem when the Span is the Root Span so that it propagates
			// across the components along with Root Span (called as Trace)
			// Else, inject as a Tag so that it is attached to the Child Task
			isRootSpan := false
			if jspan.SpanContext().TraceID().String() == jspan.SpanContext().SpanID().String() {
				isRootSpan = true
			}

			for _, field := range keyAndValues {
				for k, v := range field {
					if isRootSpan {
						span.SetBaggageItem(k, v.(string))
					} else {
						span.SetTag(k, v)
					}
				}
			}
		}
	}
}

// Method to inject Error into the Span in event of any operation failure
func MarkSpanError(ctx context.Context, err error) {
	span := opentracing.SpanFromContext(ctx)
	if span != nil {
		span.SetTag("error", true)
		span.SetTag("err", err)
	}
}

// Creates a Child Span from Parent Span embedded in passed context. Should be used before starting a new major
// operation in Synchronous or Asynchronous mode (go routine), such as following:
// 1. Start of all implemented External API methods unless using a interceptor for auto-injection of Span (Server side impl)
// 2. Just before calling an Third-Party lib which is invoking a External API (etcd, kafka)
// 3. In start of a Go Routine responsible for performing a major task involving significant duration
// 4. Any method which is suspected to be time consuming...
func CreateChildSpan(ctx context.Context, taskName string, keyAndValues ...Fields) (opentracing.Span, context.Context) {
	if !GetGlobalLFM().GetLogCorrelationStatus() && !GetGlobalLFM().GetTracePublishingStatus() {
		return opentracing.NoopTracer{}.StartSpan(taskName), ctx
	}

	parentSpan := opentracing.SpanFromContext(ctx)
	childSpan, newCtx := opentracing.StartSpanFromContext(ctx, taskName)

	if parentSpan == nil || parentSpan.BaggageItem(RootSpanNameKey) == "" {
		childSpan.SetBaggageItem(RootSpanNameKey, taskName)
	}

	EnrichSpan(newCtx, keyAndValues...)
	return childSpan, newCtx
}

// Creates a Async Child Span with Follows-From relationship from Parent Span embedded in passed context.
// Should be used only in scenarios when
// a) There is dis-continuation in execution and thus result of Child span does not affect the Parent flow at all
// b) The execution of Child Span is guaranteed to start after the completion of Parent Span
// In case of any confusion, use CreateChildSpan method
// Some situations where this method would be suitable includes Kafka Async RPC call, Propagation of Event across
// a channel etc.
func CreateAsyncSpan(ctx context.Context, taskName string, keyAndValues ...Fields) (opentracing.Span, context.Context) {
	if !GetGlobalLFM().GetLogCorrelationStatus() && !GetGlobalLFM().GetTracePublishingStatus() {
		return opentracing.NoopTracer{}.StartSpan(taskName), ctx
	}

	var asyncSpan opentracing.Span
	var newCtx context.Context

	parentSpan := opentracing.SpanFromContext(ctx)

	// We should always be creating Aysnc span from a Valid parent span. If not, create a Child span instead
	if parentSpan == nil {
		logger.Warn(context.Background(), "Async span must be created with a Valid parent span only")
		asyncSpan, newCtx = opentracing.StartSpanFromContext(ctx, taskName)
	} else {
		// Use Background context as the base for Follows-from case; else new span is getting both Child and FollowsFrom relationship
		asyncSpan, newCtx = opentracing.StartSpanFromContext(context.Background(), taskName, opentracing.FollowsFrom(parentSpan.Context()))
	}

	if parentSpan == nil || parentSpan.BaggageItem(RootSpanNameKey) == "" {
		asyncSpan.SetBaggageItem(RootSpanNameKey, taskName)
	}

	EnrichSpan(newCtx, keyAndValues...)
	return asyncSpan, newCtx
}

// Extracts the span from Source context and injects into the supplied Target context.
// This should be used in situations wherein we are calling a time-sensitive operation (etcd update) and hence
// had a context.Background() used earlier to avoid any cancellation/timeout of operation by passed context.
// This will allow propagation of span with a different base context (and not the original context)
func WithSpanFromContext(targetCtx, sourceCtx context.Context) context.Context {
	span := opentracing.SpanFromContext(sourceCtx)
	return opentracing.ContextWithSpan(targetCtx, span)
}

// Utility method to convert log Fields into array of interfaces expected by zap logger methods
func serializeMap(fields Fields) []interface{} {
	data := make([]interface{}, len(fields)*2)
	i := 0
	for k, v := range fields {
		data[i] = k
		data[i+1] = v
		i = i + 2
	}
	return data
}