More details about trace data in logging exporter

exporter/README.md

@@ -239,17 +239,26 @@ The full list of settings exposed for this exporter are documented [here](fileex
 with detailed sample configurations [here](fileexporter/testdata/config.yaml).
 
 ## <a name="logging"></a>Logging Exporter
-Exports traces and/or metrics to the console via zap.Logger.
+Exports traces and/or metrics to the console via zap.Logger. This includes generic information
+about the package (with `info` loglevel) or details of the trace (when `debug` is set)
 
 The following settings can be configured:
 
-- `loglevel`: the log level of the logging export (debug|info|warn|error). Default is `info`.
+- `loglevel`: the log level of the logging export (debug|info|warn|error). Default is `info`. When it is set to `debug`, 
+the trace related data (e.g. node, attributes, spans, metadata) are verbosely logged.
+- `sampling_initial`: number of messages initially logged each second. Default is 2. 
+- `sampling_thereafter`: sampling rate after the initial messages are logged (every Mth message 
+is logged). Default is 500.  Refer to [Zap docs](https://godoc.org/go.uber.org/zap/zapcore#NewSampler) for 
+more details on how sampling parameters impact number of messages.
 
 Example:
 
 ```yaml
 exporters:
   logging:
+    loglevel: info
+    sampling_initial: 5
+    sampling_thereafter: 200
 ```
 
 The full list of settings exposed for this exporter are documented [here](loggingexporter/config.go)

exporter/loggingexporter/config.go

@@ -24,4 +24,10 @@ type Config struct {
 
 	// LogLevel defines log level of the logging exporter; options are debug, info, warn, error.
 	LogLevel string `mapstructure:"loglevel"`
+
+	// SamplingInitial defines how many samples are initially logged during each second.
+	SamplingInitial int `mapstructure:"sampling_initial"`
+
+	// SamplingThereafter defines the sampling rate after the initial samples are logged.
+	SamplingThereafter int `mapstructure:"sampling_thereafter"`
 }

exporter/loggingexporter/config_test.go

@@ -46,6 +46,8 @@ func TestLoadConfig(t *testing.T) {
 				NameVal: "logging/2",
 				TypeVal: "logging",
 			},
-			LogLevel: "debug",
+			LogLevel:           "debug",
+			SamplingInitial:    10,
+			SamplingThereafter: 50,
 		})
 }

exporter/loggingexporter/factory.go

@@ -24,7 +24,9 @@ import (
 
 const (
 	// The value of "type" key in configuration.
-	typeStr = "logging"
+	typeStr                   = "logging"
+	defaultSamplingInitial    = 2
+	defaultSamplingThereafter = 500
 )
 
 // Factory is the factory for logging exporter.
@@ -43,34 +45,44 @@ func (f *Factory) CreateDefaultConfig() configmodels.Exporter {
 			TypeVal: typeStr,
 			NameVal: typeStr,
 		},
-		LogLevel: "info",
+		LogLevel:           "info",
+		SamplingInitial:    defaultSamplingInitial,
+		SamplingThereafter: defaultSamplingThereafter,
 	}
 }
 
 // CreateTraceExporter creates a trace exporter based on this config.
 func (f *Factory) CreateTraceExporter(logger *zap.Logger, config configmodels.Exporter) (exporter.TraceExporter, error) {
 	cfg := config.(*Config)
 
-	exporterLogger, err := f.createLogger(cfg.LogLevel)
+	exporterLogger, err := f.createLogger(cfg)
 	if err != nil {
 		return nil, err
 	}
 
-	lexp, err := NewTraceExporter(config, exporterLogger)
+	lexp, err := NewTraceExporter(config, cfg.LogLevel, exporterLogger)
 	if err != nil {
 		return nil, err
 	}
 	return lexp, nil
 }
 
-func (f *Factory) createLogger(logLevel string) (*zap.Logger, error) {
+func (f *Factory) createLogger(cfg *Config) (*zap.Logger, error) {
 	var level zapcore.Level
-	err := (&level).UnmarshalText([]byte(logLevel))
+	err := (&level).UnmarshalText([]byte(cfg.LogLevel))
 	if err != nil {
 		return nil, err
 	}
-	conf := zap.NewProductionConfig()
-	conf.Level.SetLevel(level)
+
+	// We take development config as the base since it matches the purpose
+	// of logging exporter being used for debugging reasons (so e.g. console encoder)
+	conf := zap.NewDevelopmentConfig()
+	conf.Level = zap.NewAtomicLevelAt(level)
+	conf.Sampling = &zap.SamplingConfig{
+		Initial:    cfg.SamplingInitial,
+		Thereafter: cfg.SamplingThereafter,
+	}
+
 	logginglogger, err := conf.Build()
 	if err != nil {
 		return nil, err
@@ -82,7 +94,7 @@ func (f *Factory) createLogger(logLevel string) (*zap.Logger, error) {
 func (f *Factory) CreateMetricsExporter(logger *zap.Logger, config configmodels.Exporter) (exporter.MetricsExporter, error) {
 	cfg := config.(*Config)
 
-	exporterLogger, err := f.createLogger(cfg.LogLevel)
+	exporterLogger, err := f.createLogger(cfg)
 	if err != nil {
 		return nil, err
 	}

exporter/loggingexporter/logging_exporter.go

@@ -16,6 +16,10 @@ package loggingexporter
 
 import (
 	"context"
+	"encoding/hex"
+	"fmt"
+	"strconv"
+	"strings"
 
 	"go.uber.org/zap"
 
@@ -25,18 +29,135 @@ import (
 	"github.com/open-telemetry/opentelemetry-collector/exporter/exporterhelper"
 )
 
+type traceDataBuffer struct {
+	str strings.Builder
+}
+
+func (b *traceDataBuffer) logEntry(format string, a ...interface{}) {
+	b.str.WriteString(fmt.Sprintf(format, a...))
+	b.str.WriteString("\n")
+}
+
+func (b *traceDataBuffer) logAttr(label string, value string) {
+	b.logEntry("    %-15s: %s", label, value)
+}
+
+func (b *traceDataBuffer) logMap(label string, data map[string]string) {
+	if len(data) == 0 {
+		return
+	}
+
+	b.logEntry("%s:", label)
+	for label, value := range data {
+		b.logEntry("     -> %s: %s", label, value)
+	}
+}
+
+type loggingExporter struct {
+	logger *zap.Logger
+	name   zap.Field
+	debug  bool
+}
+
+func (s *loggingExporter) pushTraceData(
+	ctx context.Context,
+	td consumerdata.TraceData,
+) (int, error) {
+	buf := traceDataBuffer{}
+
+	resourceInfo := ""
+	nodesInfo := ""
+
+	if td.Resource != nil {
+		resourceInfo = fmt.Sprintf(", resource \"%s\" (%d labels)", td.Resource.Type, len(td.Resource.Labels))
+	}
+
+	if td.Node != nil {
+		nodesInfo = fmt.Sprintf(", node service: %s", td.Node.ServiceInfo.Name)
+	}
+
+	buf.logEntry("TraceData with %d spans%s%s", len(td.Spans), nodesInfo, resourceInfo)
+
+	if s.debug {
+		if td.Resource != nil {
+			buf.logMap("Resource labels", td.Resource.Labels)
+		}
+
+		if td.Node != nil {
+			id := td.Node.Identifier
+			if id != nil {
+				buf.logEntry("%20s: %s", "HostName", id.HostName)
+				buf.logEntry("%20s: %d", "PID", id.Pid)
+			}
+			li := td.Node.LibraryInfo
+			if li != nil {
+				buf.logEntry("%20s: %s", "Library language", li.Language.String())
+				buf.logEntry("%20s: %s", "Core library version", li.CoreLibraryVersion)
+				buf.logEntry("%20s: %s", "Exporter version", li.ExporterVersion)
+			}
+			buf.logMap("Node attributes", td.Node.Attributes)
+		}
+	}
+
+	s.logger.Info(buf.str.String(), s.name)
+
+	if s.debug {
+		for i, span := range td.Spans {
+			buf = traceDataBuffer{}
+			buf.logEntry("Span #%d", i)
+			if span == nil {
+				buf.logEntry("* Empty span")
+				continue
+			}
+
+			buf.logAttr("Trace ID", hex.EncodeToString(span.TraceId))
+			buf.logAttr("Parent ID", hex.EncodeToString(span.ParentSpanId))
+			buf.logAttr("ID", hex.EncodeToString(span.SpanId))
+			buf.logAttr("Name", span.Name.Value)
+			buf.logAttr("Kind", span.Kind.String())
+			buf.logAttr("Start time", span.StartTime.String())
+			buf.logAttr("End time", span.EndTime.String())
+			if span.Status != nil {
+				buf.logAttr("Status code", strconv.Itoa(int(span.Status.Code)))
+				buf.logAttr("Status message", span.Status.Message)
+			}
+
+			if span.Attributes != nil {
+				buf.logAttr("Span attributes", "")
+				for attr, value := range span.Attributes.AttributeMap {
+					v := ""
+					ts := value.GetStringValue()
+
+					if ts != nil {
+						v = ts.Value
+					} else {
+						// For other types, just use the proto compact form rather than digging into series of checks
+						v = value.String()
+					}
+
+					buf.logEntry("         -> %s: %s", attr, v)
+				}
+			}
+
+			s.logger.Debug(buf.str.String(), s.name)
+		}
+	}
+
+	return 0, nil
+}
+
 // NewTraceExporter creates an exporter.TraceExporter that just drops the
 // received data and logs debugging messages.
-func NewTraceExporter(config configmodels.Exporter, logger *zap.Logger) (exporter.TraceExporter, error) {
-	typeLog := zap.String("type", config.Type())
-	nameLog := zap.String("name", config.Name())
+func NewTraceExporter(config configmodels.Exporter, level string, logger *zap.Logger) (exporter.TraceExporter, error) {
+	s := &loggingExporter{
+		debug:  level == "debug",
+		name:   zap.String("exporter", config.Name()),
+		logger: logger,
+	}
+
 	return exporterhelper.NewTraceExporter(
 		config,
-		func(ctx context.Context, td consumerdata.TraceData) (int, error) {
-			logger.Info("TraceExporter", typeLog, nameLog, zap.Int("#spans", len(td.Spans)))
-			// TODO: Add ability to record the received data
-			return 0, nil
-		},
+		s.pushTraceData,
 		exporterhelper.WithShutdown(logger.Sync),
 	)
 }

exporter/loggingexporter/logging_exporter_test.go

@@ -17,7 +17,9 @@ import (
 	"context"
 	"testing"
 
+	commonpb "github.com/census-instrumentation/opencensus-proto/gen-go/agent/common/v1"
 	metricspb "github.com/census-instrumentation/opencensus-proto/gen-go/metrics/v1"
+	resourcepb "github.com/census-instrumentation/opencensus-proto/gen-go/resource/v1"
 	tracepb "github.com/census-instrumentation/opencensus-proto/gen-go/trace/v1"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -28,13 +30,43 @@ import (
 )
 
 func TestLoggingTraceExporterNoErrors(t *testing.T) {
-	lte, err := NewTraceExporter(&configmodels.ExporterSettings{}, zap.NewNop())
+	lte, err := NewTraceExporter(&configmodels.ExporterSettings{}, "debug", zap.NewNop())
 	require.NotNil(t, lte)
 	assert.NoError(t, err)
 
 	td := consumerdata.TraceData{
-		Spans: make([]*tracepb.Span, 7),
+		Node: &commonpb.Node{
+			ServiceInfo: &commonpb.ServiceInfo{
+				Name: "some-service",
+			},
+		},
+		Resource: &resourcepb.Resource{
+			Type:   "ServiceA",
+			Labels: map[string]string{"attr1": "value1"},
+		},
+		Spans: []*tracepb.Span{
+			{
+				TraceId: []byte("123"),
+				SpanId:  []byte("456"),
+				Name:    &tracepb.TruncatableString{Value: "Checkout"},
+				Kind:    tracepb.Span_CLIENT,
+			},
+			{
+				TraceId: []byte("123"),
+				SpanId:  []byte("457"),
+				Name:    &tracepb.TruncatableString{Value: "Frontend"},
+				Kind:    tracepb.Span_SERVER,
+				Attributes: &tracepb.Span_Attributes{
+					AttributeMap: map[string]*tracepb.AttributeValue{
+						"foo": {
+							Value: &tracepb.AttributeValue_StringValue{StringValue: &tracepb.TruncatableString{Value: "bar"}},
+						},
+					},
+				},
+			},
+		},
 	}
+
 	assert.NoError(t, lte.ConsumeTraceData(context.Background(), td))
 	assert.NoError(t, lte.Shutdown())
 }

exporter/loggingexporter/testdata/config.yaml

@@ -8,6 +8,8 @@ exporters:
   logging:
   logging/2:
     loglevel: debug
+    sampling_initial: 10
+    sampling_thereafter: 50
 
 service:
   pipelines:

receiver/end_to_end_test.go

@@ -33,7 +33,7 @@ func Example_endToEnd() {
 	// This is what the cmd/ocagent code would look like this.
 	// A trace receiver as per the trace receiver
 	// configs that have been parsed.
-	lte, err := loggingexporter.NewTraceExporter(&configmodels.ExporterSettings{}, zap.NewNop())
+	lte, err := loggingexporter.NewTraceExporter(&configmodels.ExporterSettings{}, "debug", zap.NewNop())
 	if err != nil {
 		log.Fatalf("Failed to create logging exporter: %v", err)
 	}

testbed/tests/testdata/agent-config.yaml

@@ -10,7 +10,7 @@ exporters:
   opencensus:
     endpoint: "localhost:56565"
   logging:
-    loglevel: debug
+    loglevel: info
 
 processors:
   queued_retry:

testbed/tests/testdata/memory-limiter.yaml

@@ -10,7 +10,7 @@ exporters:
   opencensus:
     endpoint: "localhost:56565"
   logging:
-    loglevel: debug
+    loglevel: info
 
 processors:
   queued_retry: