[VOL-3142] Enabled tracing for openolt-adapter and added config parameters
Change-Id: Ia451b39b84fe4f4906aa5f7fef679354cc9a4294
diff --git a/VERSION b/VERSION
index 69fa968..437459c 100644
--- a/VERSION
+++ b/VERSION
@@ -1 +1 @@
-2.5.0-dev
+2.5.0
diff --git a/cmd/openolt-adapter/main.go b/cmd/openolt-adapter/main.go
index 29b715f..1da44c4 100644
--- a/cmd/openolt-adapter/main.go
+++ b/cmd/openolt-adapter/main.go
@@ -516,6 +516,13 @@
probeCtx := context.WithValue(ctx, probe.ProbeContextKey, p)
+ closer, err := log.InitTracingAndLogCorrelation(cf.TraceEnabled, cf.TraceAgentAddress, cf.LogCorrelationEnabled)
+ if err != nil {
+ logger.Warnw(ctx, "unable-to-initialize-tracing-and-log-correlation-module", log.Fields{"error": err})
+ } else {
+ defer log.TerminateTracing(closer)
+ }
+
go ad.start(probeCtx)
code := waitForExit(ctx)
diff --git a/go.mod b/go.mod
index 6bc1ce5..632206d 100644
--- a/go.mod
+++ b/go.mod
@@ -7,7 +7,7 @@
github.com/cenkalti/backoff/v3 v3.1.1
github.com/gogo/protobuf v1.3.1
github.com/golang/protobuf v1.3.2
- github.com/opencord/voltha-lib-go/v3 v3.2.1
+ github.com/opencord/voltha-lib-go/v3 v3.2.3
github.com/opencord/voltha-protos/v3 v3.4.1
go.etcd.io/etcd v0.0.0-20190930204107-236ac2a90522
google.golang.org/grpc v1.25.1
diff --git a/go.sum b/go.sum
index 62a75be..0c98513 100644
--- a/go.sum
+++ b/go.sum
@@ -204,8 +204,8 @@
github.com/onsi/ginkgo v1.6.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE=
github.com/onsi/gomega v1.4.2 h1:3mYCb7aPxS/RU7TI1y4rkEn1oKmPRjNJLNEXgw7MH2I=
github.com/onsi/gomega v1.4.2/go.mod h1:ex+gbHU/CVuBBDIJjb2X0qEXbFg53c61hWP/1CpauHY=
-github.com/opencord/voltha-lib-go/v3 v3.2.1 h1:s6thA7jLGkrx6S3fzyCBYkXS4c0lIlPgmI0nYCme6NA=
-github.com/opencord/voltha-lib-go/v3 v3.2.1/go.mod h1:RPWJ4EY9Q758uwYAAb2WqZYDSI2M0FCQqjIHJxxDiHY=
+github.com/opencord/voltha-lib-go/v3 v3.2.3 h1:VN+PywEuABvSucQd2PS5828m/bqmQnTD/UNl9wR+pFs=
+github.com/opencord/voltha-lib-go/v3 v3.2.3/go.mod h1:7CnNtVE/O8y80Xw7JXtaWQ61HxL7yWXlB0/uH5R/X/Y=
github.com/opencord/voltha-protos/v3 v3.4.1 h1:Nrr0jKy7WiMiFlXYiK8z73RvI4K4L5b/top7d3htQQI=
github.com/opencord/voltha-protos/v3 v3.4.1/go.mod h1:nl1ETp5Iw3avxOaKD8BJlYY5wYI4KeV95aT1pL63nto=
github.com/opentracing/opentracing-go v1.1.0 h1:pWlfV3Bxv7k65HYwkikxat0+s3pV4bsqf19k25Ur8rU=
diff --git a/internal/pkg/config/config.go b/internal/pkg/config/config.go
index 3a8d157..541f4a6 100644
--- a/internal/pkg/config/config.go
+++ b/internal/pkg/config/config.go
@@ -48,9 +48,12 @@
// defaultHearbeatFailReportInterval is the time adapter will wait before updating the state to the core.
defaultHearbeatFailReportInterval = 0 * time.Second
//defaultGrpcTimeoutInterval is the time in seconds a grpc call will wait before returning error.
- defaultGrpcTimeoutInterval = 2 * time.Second
- defaultCurrentReplica = 1
- defaultTotalReplicas = 1
+ defaultGrpcTimeoutInterval = 2 * time.Second
+ defaultCurrentReplica = 1
+ defaultTotalReplicas = 1
+ defaultTraceEnabled = false
+ defaultTraceAgentAddress = "127.0.0.1:6831"
+ defaultLogCorrelationEnabled = true
)
// AdapterFlags represents the set of configurations used by the read-write adaptercore service
@@ -77,6 +80,9 @@
GrpcTimeoutInterval time.Duration
CurrentReplica int
TotalReplicas int
+ TraceEnabled bool
+ TraceAgentAddress string
+ LogCorrelationEnabled bool
}
// NewAdapterFlags returns a new RWCore config
@@ -101,6 +107,9 @@
HeartbeatCheckInterval: defaultHearbeatCheckInterval,
HeartbeatFailReportInterval: defaultHearbeatFailReportInterval,
GrpcTimeoutInterval: defaultGrpcTimeoutInterval,
+ TraceEnabled: defaultTraceEnabled,
+ TraceAgentAddress: defaultTraceAgentAddress,
+ LogCorrelationEnabled: defaultLogCorrelationEnabled,
}
return &adapterFlags
}
@@ -168,6 +177,15 @@
help = "Total number of instances for this adapter"
flag.IntVar(&(so.TotalReplicas), "total_replica", defaultTotalReplicas, help)
+ help = fmt.Sprintf("Whether to send logs to tracing agent?")
+ flag.BoolVar(&(so.TraceEnabled), "trace_enabled", defaultTraceEnabled, help)
+
+ help = fmt.Sprintf("The address of tracing agent to which span info should be sent.")
+ flag.StringVar(&(so.TraceAgentAddress), "trace_agent_address", defaultTraceAgentAddress, help)
+
+ help = fmt.Sprintf("Whether to enrich log statements with fields denoting operation being executed for achieving correlation?")
+ flag.BoolVar(&(so.LogCorrelationEnabled), "log_correlation_enabled", defaultLogCorrelationEnabled, help)
+
flag.Parse()
containerName := getContainerInfo()
if len(containerName) > 0 {
diff --git a/vendor/github.com/opencord/voltha-lib-go/v3/pkg/log/utils.go b/vendor/github.com/opencord/voltha-lib-go/v3/pkg/log/utils.go
index 1869b1a..cdd0a4e 100644
--- a/vendor/github.com/opencord/voltha-lib-go/v3/pkg/log/utils.go
+++ b/vendor/github.com/opencord/voltha-lib-go/v3/pkg/log/utils.go
@@ -25,15 +25,52 @@
"github.com/opentracing/opentracing-go"
jtracing "github.com/uber/jaeger-client-go"
jcfg "github.com/uber/jaeger-client-go/config"
- jmetrics "github.com/uber/jaeger-lib/metrics"
"io"
+ "io/ioutil"
"os"
+ "strings"
)
+const (
+ RootSpanNameKey = "op-name"
+)
+
+// Flag indicating whether to extract Log Fields from Span embedded in the received Context
+var extractLogFieldsFromContext bool = true
+
+// Flag indicating whether to process Span related operations; to save CPU cycles when disabled
+var processSpanOperations bool = true
+
+// 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...)
+}
+
// This method will start the Tracing for a component using Component name injected from the Chart
// The close() method on returned Closer instance should be called in defer mode to gracefully
// terminate tracing on component shutdown
-func StartTracing() (io.Closer, error) {
+func InitTracingAndLogCorrelation(tracePublishEnabled bool, traceAgentAddress string, logCorrelationEnabled bool) (io.Closer, error) {
+ if !tracePublishEnabled && !logCorrelationEnabled {
+ defaultLogger.Info(context.Background(), "Skipping Global Tracer initialization as both Trace publish and Log correlation are configured as disabled")
+ extractLogFieldsFromContext = false
+ processSpanOperations = false
+ return ioutil.NopCloser(strings.NewReader("")), nil
+ }
+
+ if !logCorrelationEnabled {
+ defaultLogger.Info(context.Background(), "Disabling Log Fields extraction from context as configured")
+ extractLogFieldsFromContext = false
+ }
+
componentName := os.Getenv("COMPONENT_NAME")
if componentName == "" {
return nil, errors.New("Unable to retrieve PoD Component Name from Runtime env")
@@ -42,10 +79,52 @@
// Use basic configuration to start with; will extend later to support dynamic config updates
cfg := jcfg.Configuration{}
- jLoggerCfgOption := jcfg.Logger(jtracing.StdLogger)
- jMetricsFactoryCfgOption := jcfg.Metrics(jmetrics.NullFactory)
+ var err error
+ var jReporterConfig jcfg.ReporterConfig
+ var jReporterCfgOption jtracing.Reporter
- return cfg.InitGlobalTracer(componentName, jLoggerCfgOption, jMetricsFactoryCfgOption)
+ // Attempt Trace Agent Address only if Trace Publishing is enabled; else directly use Loopback IP
+ if tracePublishEnabled {
+ jReporterConfig = jcfg.ReporterConfig{LocalAgentHostPort: traceAgentAddress, LogSpans: true}
+ jReporterCfgOption, err = jReporterConfig.NewReporter(componentName, jtracing.NewNullMetrics(), traceLogger{logger: defaultLogger})
+
+ if err != nil {
+ defaultLogger.Errorw(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
+ }
+ }
+
+ if !tracePublishEnabled {
+ jReporterConfig.LocalAgentHostPort = "127.0.0.1:6831"
+ jReporterCfgOption, err = jReporterConfig.NewReporter(componentName, jtracing.NewNullMetrics(), traceLogger{logger: defaultLogger})
+ if err != nil {
+ return 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(componentName, jtracing.NewNullMetrics())
+ if err != nil {
+ return nil, errors.New("Unable to create Sampler : " + err.Error())
+ }
+
+ return cfg.InitGlobalTracer(componentName, jcfg.Reporter(jReporterCfgOption), jcfg.Sampler(jSamplerCfgOption))
+}
+
+func TerminateTracing(c io.Closer) {
+ err := c.Close()
+ if err != nil {
+ defaultLogger.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
@@ -57,18 +136,43 @@
//
// If no Span is found associated with context, blank slice is returned without any log fields
func ExtractContextAttributes(ctx context.Context) []interface{} {
+ if !extractLogFieldsFromContext {
+ 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 {
- opname := jspan.OperationName()
- spanid := jspan.SpanContext().SpanID().String()
+ // Add Log fields for operation identified by Root Level Span (Trace)
+ opId := jspan.SpanContext().TraceID().String()
+ opName := jspan.BaggageItem(RootSpanNameKey)
- attrMap["op-id"] = spanid
- attrMap["op-name"] = opname
+ taskId := jspan.SpanContext().SpanID().String()
+ 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
}
}
@@ -78,6 +182,90 @@
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 {
+ for _, field := range keyAndValues {
+ for k, v := range field {
+ 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)
+ 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 !processSpanOperations {
+ 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 !processSpanOperations {
+ 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 {
+ defaultLogger.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)
diff --git a/vendor/modules.txt b/vendor/modules.txt
index 80f241f..9d67a93 100644
--- a/vendor/modules.txt
+++ b/vendor/modules.txt
@@ -67,7 +67,7 @@
github.com/mitchellh/go-homedir
# github.com/mitchellh/mapstructure v1.1.2
github.com/mitchellh/mapstructure
-# github.com/opencord/voltha-lib-go/v3 v3.2.1
+# github.com/opencord/voltha-lib-go/v3 v3.2.3
github.com/opencord/voltha-lib-go/v3/pkg/adapters
github.com/opencord/voltha-lib-go/v3/pkg/adapters/adapterif
github.com/opencord/voltha-lib-go/v3/pkg/adapters/common