Consolidate rootLogger and scopedLogger (getporter#1878)

* Consolidate rootLogger and scopedLogger By only allowing the porter application context to create a root span, we can consolidate rootlogger and scoped logger into a single TraceLogger, and simplify logic around setting attributes on the root span. Signed-off-by: Carolyn Van Slyck <[email protected]> * Allow for a variable stack size when finding the function name Sometimes the stack looks like this when we ask for the calling function name: InstallBundle -> tracing.TraceLogger.StartSpan -> tracing.callerFunc other times it looks like this ExecuteBundle -> tracing.StartSpan -> tracing.TraceLogger.StartSpan -> tracing.callerFunc So I have tweaked how we look up the stack to keep checking until we find a function that isn't in the tracing package Signed-off-by: Carolyn Van Slyck <[email protected]> * Document more of the tracing package Signed-off-by: Carolyn Van Slyck <[email protected]> Signed-off-by: joshuabezaleel <[email protected]>
joshuabezaleel · Feb 8, 2022 · 8060f2e · 8060f2e
1 parent d4bf6a0
commit 8060f2e
Show file tree

Hide file tree

Showing 16 changed files with 370 additions and 424 deletions.
diff --git a/cmd/porter/main.go b/cmd/porter/main.go
@@ -29,7 +29,7 @@ func main() {
 
 		// Trace the command that called porter, e.g. porter installation show
 		calledCommand, formattedCommand := getCalledCommand(rootCmd)
-		ctx, log := p.Log.StartSpanWithName(context.Background(), calledCommand, attribute.String("command", formattedCommand))
+		ctx, log := p.StartRootSpan(context.Background(), calledCommand, attribute.String("command", formattedCommand))
 		defer func() {
 			// Capture panics and trace them
 			if panicErr := recover(); panicErr != nil {

diff --git a/pkg/build/buildkit/buildx.go b/pkg/build/buildkit/buildx.go
@@ -45,7 +45,7 @@ var _ io.Writer = unstructuredLogger{}
 // take lines from the docker output, and write them as info messages
 // This allows the docker library to use our logger like an io.Writer
 type unstructuredLogger struct {
-	logger tracing.ScopedLogger
+	logger tracing.TraceLogger
 }
 
 var newline = []byte("\n")
@@ -61,8 +61,7 @@ func (l unstructuredLogger) Write(p []byte) (n int, err error) {
 }
 
 func (b *Builder) BuildInvocationImage(ctx context.Context, manifest *manifest.Manifest) error {
-	log := tracing.LoggerFromContext(ctx)
-	ctx, log = log.StartSpan(attribute.String("image", manifest.Image))
+	ctx, log := tracing.StartSpan(ctx, attribute.String("image", manifest.Image))
 	defer log.EndSpan()
 
 	log.Info("Building invocation image")
@@ -204,7 +203,9 @@ func (d dockerToBuildx) DockerAPI(_ string) (dockerclient.APIClient, error) {
 }
 
 func (b *Builder) TagInvocationImage(ctx context.Context, origTag, newTag string) error {
-	log := tracing.LoggerFromContext(ctx)
+	ctx, log := tracing.StartSpan(ctx, attribute.String("source-tag", origTag), attribute.String("destination-tag", newTag))
+	defer log.EndSpan()
+
 	cli, err := command.NewDockerCli()
 	if err != nil {
 		return log.Error(errors.Wrap(err, "could not create new docker client"))

diff --git a/pkg/cnab/provider/action.go b/pkg/cnab/provider/action.go
@@ -11,6 +11,7 @@ import (
 	"get.porter.sh/porter/pkg/cnab"
 	"get.porter.sh/porter/pkg/config"
 	"get.porter.sh/porter/pkg/secrets"
+	"get.porter.sh/porter/pkg/tracing"
 	"github.com/cnabio/cnab-go/action"
 	cnabaction "github.com/cnabio/cnab-go/action"
 	"github.com/cnabio/cnab-go/driver"
@@ -108,13 +109,11 @@ func (r *Runtime) AddRelocation(args ActionArguments) action.OperationConfigFunc
 }
 
 func (r *Runtime) Execute(ctx context.Context, args ActionArguments) error {
-	ctx, log := r.Log.StartSpan(ctx,
+	ctx, log := tracing.StartSpan(ctx,
 		attribute.String("action", args.Action),
 		attribute.Bool("allowDockerHostAccess", args.AllowDockerHostAccess),
 		attribute.String("driver", args.Driver))
-	defer func() {
-		log.EndSpan()
-	}()
+	defer log.EndSpan()
 	args.BundleReference.AddToTrace(ctx)
 	args.Installation.AddToTrace(ctx)
 

diff --git a/pkg/context/context.go b/pkg/context/context.go
@@ -44,16 +44,31 @@ type Context struct {
 	NewCommand         CommandBuilder
 	PlugInDebugContext *PluginDebugContext
 
+	//
 	// Logging and Tracing configuration
+	//
+
 	// a consistent id that is set on the context and emitted in the logs
 	// Helps correlate logs with a workflow.
-	correlationId    string
-	Log              tracing.RootLogger
-	logLevel         zapcore.Level
-	logFile          afero.File
-	timestampLogs    bool
-	tracer           trace.Tracer
-	traceCloser      *sdktrace.TracerProvider
+	correlationId string
+
+	// logLevel filters the messages written to the console and logfile
+	logLevel zapcore.Level
+	logFile  afero.File
+
+	// indicates if log timestamps should be printed to the console
+	timestampLogs bool
+
+	// handles sending tracing data to an otel collector
+	tracer trace.Tracer
+
+	// handles send log data to the console/logfile
+	logger *zap.Logger
+
+	// cleans up resources associated with the tracer when porter completes
+	traceCloser *sdktrace.TracerProvider
+
+	// the service name sent to the otel collector when we send tracing data
 	traceServiceName string
 }
 
@@ -82,6 +97,14 @@ func New() *Context {
 	return c
 }
 
+// StartRootSpan creates the root tracing span for the porter application.
+// This should only be done once.
+func (c *Context) StartRootSpan(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, tracing.TraceLogger) {
+	childCtx, span := c.tracer.Start(ctx, op)
+	span.SetAttributes(attrs...)
+	return tracing.NewRootLogger(childCtx, span, c.logger, c.tracer)
+}
+
 func (c *Context) makeLogEncoding() zapcore.EncoderConfig {
 	enc := zap.NewProductionEncoderConfig()
 	if c.timestampLogs {
@@ -144,7 +167,7 @@ func (c *Context) ConfigureLogging(cfg LogConfiguration) {
 		c.tracer = trace.NewNoopTracerProvider().Tracer("noop")
 	}
 
-	c.Log = tracing.NewLogger(tmpLog, c.tracer, attribute.String("correlationId", c.correlationId))
+	c.logger = tmpLog
 }
 
 func (c *Context) makeConsoleLogger(encoding zapcore.EncoderConfig, structuredLogs bool) zapcore.Core {

diff --git a/pkg/context/context_test.go b/pkg/context/context_test.go
@@ -35,7 +35,7 @@ func TestContext_LogToFile(t *testing.T) {
 	c.ConfigureLogging(LogConfiguration{LogLevel: zapcore.DebugLevel, LogToFile: true, LogDirectory: "/.porter/logs"})
 	c.timestampLogs = false // turn off timestamps so we can compare more easily
 	logfile := c.logFile.Name()
-	_, log := c.Log.StartSpan(context.Background())
+	_, log := c.StartRootSpan(context.Background(), t.Name())
 	log.Info("a thing happened")
 	log.Warn("a weird thing happened")
 	log.Error(errors.New("a bad thing happened"))

diff --git a/pkg/porter/apply.go b/pkg/porter/apply.go
@@ -9,6 +9,7 @@ import (
 	"get.porter.sh/porter/pkg/encoding"
 	"get.porter.sh/porter/pkg/printer"
 	"get.porter.sh/porter/pkg/storage"
+	"get.porter.sh/porter/pkg/tracing"
 	"github.com/pkg/errors"
 	"go.opentelemetry.io/otel/attribute"
 )
@@ -50,7 +51,7 @@ func (o *ApplyOptions) Validate(cxt *portercontext.Context, args []string) error
 }
 
 func (p *Porter) InstallationApply(ctx context.Context, opts ApplyOptions) error {
-	ctx, log := p.Log.StartSpan(ctx)
+	ctx, log := tracing.StartSpan(ctx)
 	defer log.EndSpan()
 
 	log.Debugf("Reading input file %s", opts.File)

diff --git a/pkg/porter/helpers.go b/pkg/porter/helpers.go
@@ -53,7 +53,7 @@ type TestPorter struct {
 	RootContext context.Context
 
 	// The root log span created by NewTestPorter
-	RootLog tracing.ScopedLogger
+	RootSpan tracing.TraceLogger
 }
 
 // NewTestPorter initializes a porter test client, with the output buffered, and an in-memory file system.
@@ -91,15 +91,15 @@ func NewTestPorter(t *testing.T) *TestPorter {
 	}
 
 	// Start a tracing span for the test, so that we can capture logs
-	tp.RootContext, tp.RootLog = p.Log.StartSpanWithName(context.Background(), t.Name())
+	tp.RootContext, tp.RootSpan = p.StartRootSpan(context.Background(), t.Name())
 
 	return &tp
 }
 
 func (p *TestPorter) Teardown() error {
 	err := p.TestStore.Teardown()
 	p.TestConfig.TestContext.Teardown()
-	p.RootLog.EndSpan()
+	p.RootSpan.EndSpan()
 	return err
 }
 

diff --git a/pkg/porter/install.go b/pkg/porter/install.go
@@ -6,6 +6,7 @@ import (
 	"get.porter.sh/porter/pkg/claims"
 	"get.porter.sh/porter/pkg/cnab"
 	"get.porter.sh/porter/pkg/storage"
+	"get.porter.sh/porter/pkg/tracing"
 	"github.com/pkg/errors"
 )
 
@@ -54,7 +55,7 @@ func NewInstallOptions() InstallOptions {
 // InstallBundle accepts a set of pre-validated InstallOptions and uses
 // them to install a bundle.
 func (p *Porter) InstallBundle(ctx context.Context, opts InstallOptions) error {
-	ctx, log := p.Log.StartSpan(ctx)
+	ctx, log := tracing.StartSpan(ctx)
 	defer log.EndSpan()
 
 	// Figure out which bundle/installation we are working with

diff --git a/pkg/porter/list.go b/pkg/porter/list.go
@@ -10,6 +10,7 @@ import (
 	"get.porter.sh/porter/pkg/claims"
 	"get.porter.sh/porter/pkg/cnab"
 	"get.porter.sh/porter/pkg/printer"
+	"get.porter.sh/porter/pkg/tracing"
 	dtprinter "github.com/carolynvs/datetime-printer"
 	"github.com/pkg/errors"
 )
@@ -124,7 +125,7 @@ func NewDisplayRun(run claims.Run) DisplayRun {
 
 // ListInstallations lists installed bundles.
 func (p *Porter) ListInstallations(ctx context.Context, opts ListOptions) ([]claims.Installation, error) {
-	_, log := p.Log.StartSpan(ctx)
+	ctx, log := tracing.StartSpan(ctx)
 	defer log.EndSpan()
 
 	installations, err := p.Claims.ListInstallations(opts.GetNamespace(), opts.Name, opts.ParseLabels())

diff --git a/pkg/porter/reconcile.go b/pkg/porter/reconcile.go
@@ -34,7 +34,7 @@ type ReconcileOptions struct {
 // This is only used for install/upgrade actions triggered by applying a file
 // to an installation. For uninstall or invoke, you should call those directly.
 func (p *Porter) ReconcileInstallation(ctx context.Context, opts ReconcileOptions) error {
-	log := tracing.LoggerFromContext(ctx)
+	ctx, log := tracing.StartSpan(ctx)
 	if p.Debug {
 		fmt.Fprintf(p.Err, "Reconciling %s/%s installation\n", opts.Namespace, opts.Name)
 	}
@@ -127,7 +127,8 @@ func (p *Porter) ReconcileInstallation(ctx context.Context, opts ReconcileOption
 // IsInstallationInSync determines if the desired state of the installation matches
 // the state of the installation the last time it was modified.
 func (p *Porter) IsInstallationInSync(ctx context.Context, i claims.Installation, lastRun *claims.Run, action BundleAction) (bool, error) {
-	log := tracing.LoggerFromContext(ctx)
+	ctx, log := tracing.StartSpan(ctx)
+	defer log.EndSpan()
 
 	// Only print out info messages if we are triggering a bundle run. Otherwise, keep the explanations in debug output.
 

diff --git a/pkg/porter/uninstall.go b/pkg/porter/uninstall.go
@@ -10,7 +10,6 @@ import (
 	"get.porter.sh/porter/pkg/tracing"
 	"github.com/hashicorp/go-multierror"
 	"github.com/pkg/errors"
-	"go.opentelemetry.io/otel/trace"
 )
 
 var _ BundleAction = NewUninstallOptions()
@@ -70,7 +69,8 @@ func (opts *UninstallDeleteOptions) handleUninstallErrs(out io.Writer, err error
 // UninstallBundle accepts a set of pre-validated UninstallOptions and uses
 // them to uninstall a bundle.
 func (p *Porter) UninstallBundle(ctx context.Context, opts UninstallOptions) error {
-	log := tracing.LoggerFromContext(ctx)
+	ctx, log := tracing.StartSpan(ctx)
+	defer log.EndSpan()
 
 	// Figure out which bundle/installation we are working with
 	_, err := p.resolveBundleReference(ctx, opts.BundleActionOptions)
@@ -99,7 +99,6 @@ func (p *Porter) UninstallBundle(ctx context.Context, opts UninstallOptions) err
 		return err
 	}
 
-	span := trace.SpanFromContext(ctx)
 	log.Infof("%s bundle", opts.GetActionVerb())
 	err = p.CNAB.Execute(ctx, actionArgs)
 
@@ -131,7 +130,7 @@ func (p *Porter) UninstallBundle(ctx context.Context, opts UninstallOptions) err
 	}
 
 	if opts.shouldDelete() {
-		p.Log.Info(span, "deleting installation records")
+		log.Info("deleting installation records")
 		return p.Claims.RemoveInstallation(opts.Namespace, opts.Name)
 	}
 	return nil