Repository: getporter/porter
Pull request #1864 (2022-01-19 14:56:30)

pkg/{porter,tracing}, cmd/porter: add tracing instrumentation for list
command

# What does this change

This PR adds instrumentation for list command. It also adds support for
automatically setting span name during creation by the caller function
name.
Some fixes for unclosed spans is included as well

# What issue does it fix
related to #1857 

# Notes for the reviewer
_Put any questions or notes for the reviewer here._

# Checklist
- [ ] Did you write tests?
- [ ] Did you write documentation?
- [ ] Did you change porter.yaml or a storage document record? Update the corresponding schema file.
- [ ] If this is your first pull request, please add your name to the bottom of our [Contributors][contributors] list. Thank you for making Porter better! 🙇‍♀️

# Reviewer Checklist
* Comment with /azp run test-porter-release if a magefile or build script was modified
* Comment with /azp run porter-integration if it's a non-trivial PR

[contributors]: https://porter.sh/src/CONTRIBUTORS.md


Patch:
diff --git a/cmd/porter/installations.go b/cmd/porter/installations.go
index a780c8a6..73072a76 100644
--- a/cmd/porter/installations.go
+++ b/cmd/porter/installations.go
@@ -49,7 +49,7 @@ Optional output formats include json and yaml.`,
 			return opts.Validate()
 		},
 		RunE: func(cmd *cobra.Command, args []string) error {
-			return p.PrintInstallations(opts)
+			return p.PrintInstallations(cmd.Context(), opts)
 		},
 	}
 
diff --git a/cmd/porter/main.go b/cmd/porter/main.go
index 2fc80a26..62f16ba5 100644
--- 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.StartSpan(context.Background(), calledCommand, attribute.String("command", formattedCommand))
+		ctx, log := p.Log.StartSpanWithName(context.Background(), calledCommand, attribute.String("command", formattedCommand))
 		defer func() {
 			// Capture panics and trace them
 			if panicErr := recover(); panicErr != nil {
@@ -45,7 +45,7 @@ func main() {
 
 		if err := rootCmd.ExecuteContext(ctx); err != nil {
 			// Ideally we log all errors in the span that generated it,
-			// but as a failsafe, always log the error a the root span as well
+			// but as a failsafe, always log the error at the root span as well
 			log.Error(err)
 			return 1
 		}
diff --git a/mage/docker/docker.go b/mage/docker/docker.go
index a494ba46..1aa0741f 100644
--- a/mage/docker/docker.go
+++ b/mage/docker/docker.go
@@ -19,6 +19,9 @@ import (
 const (
 	// Container name of the local registry
 	DefaultRegistryName = "registry"
+
+	// Name of the docker network shared by the local registry and KIND
+	DefaultNetworkName = "porter"
 )
 
 // Ensure the docker daemon is started and ready to accept connections.
@@ -75,6 +78,14 @@ func isDockerReady() (bool, error) {
 	return err == nil, nil
 }
 
+func EnsurePorterNetwork() error {
+	if NetworkExists(DefaultNetworkName) {
+		return nil
+	}
+
+	return shx.RunE("docker", "network", "create", DefaultNetworkName, "-d=bridge")
+}
+
 func NetworkExists(name string) bool {
 	err := shx.RunE("docker", "network", "inspect", name)
 	return err == nil
@@ -82,18 +93,21 @@ func NetworkExists(name string) bool {
 
 // Start a Docker registry to use with the tests.
 func StartDockerRegistry() error {
-	mg.SerialDeps(StartDocker)
-	if isContainerRunning(getRegistryName()) {
+	mg.SerialDeps(StartDocker, EnsurePorterNetwork)
+
+	// Check if we have the registry container on the proper network, if not recreate it
+	registryName := getRegistryName()
+	if isContainerRunning(registryName) && isOnDockerNetwork(registryName, DefaultNetworkName) {
 		return nil
 	}
 
-	err := RemoveContainer(getRegistryName())
+	err := RemoveContainer(registryName)
 	if err != nil {
 		return err
 	}
 
 	fmt.Println("Starting local docker registry")
-	return shx.RunE("docker", "run", "-d", "-p", "0.0.0.0:5000:5000", "--name", getRegistryName(), "registry:2")
+	return shx.RunE("docker", "run", "-d", "-p", "0.0.0.0:5000:5000", "--network="+DefaultNetworkName, "--name", registryName, "registry:2")
 }
 
 // Stop the Docker registry used by the tests.
@@ -140,3 +154,9 @@ func getRegistryName() string {
 	}
 	return DefaultRegistryName
 }
+
+func isOnDockerNetwork(container string, network string) bool {
+	networkId, _ := shx.OutputE("docker", "network", "inspect", network, "-f", "{{.Id}}")
+	networks, _ := shx.OutputE("docker", "inspect", container, "-f", "{{json .NetworkSettings.Networks}}")
+	return strings.Contains(networks, networkId)
+}
diff --git a/pkg/agent/agent.go b/pkg/agent/agent.go
index 10dba78c..9521df18 100644
--- a/pkg/agent/agent.go
+++ b/pkg/agent/agent.go
@@ -9,6 +9,7 @@ import (
 	"path/filepath"
 	"strings"
 
+	"github.com/pkg/errors"
 	"golang.org/x/sync/errgroup"
 )
 
@@ -63,9 +64,13 @@ func Execute(porterCommand []string, porterHome string, porterConfig string) (er
 	}
 
 	// Remind everyone the version of Porter we are using
+	fmt.Fprintf(stderr, "porter version\n")
 	cmd := exec.Command(porter, "version")
-	cmd.Stdout = stdout
+	cmd.Stdout = stderr // send all non-bundle output to stderr
 	cmd.Stderr = stderr
+	if err = cmd.Run(); err != nil {
+		return errors.Wrap(err, "porter version check failed"), false
+	}
 
 	// Run the specified porter command
 	fmt.Fprintf(stderr, "porter %s\n", strings.Join(porterCommand, " "))
diff --git a/pkg/build/buildkit/buildx.go b/pkg/build/buildkit/buildx.go
index 375f518d..76694f10 100644
--- a/pkg/build/buildkit/buildx.go
+++ b/pkg/build/buildkit/buildx.go
@@ -61,7 +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("BuildInvocationImage", attribute.String("image", manifest.Image))
+	ctx, log = log.StartSpan(attribute.String("image", manifest.Image))
 	defer log.EndSpan()
 
 	log.Info("Building invocation image")
@@ -103,7 +103,7 @@ func (b *Builder) BuildInvocationImage(ctx context.Context, manifest *manifest.M
 
 	out := ioutil.Discard
 	if b.IsVerbose() || b.Config.IsFeatureEnabled(experimental.FlagStructuredLogs) {
-		ctx, log = log.StartSpan("buildkit", attribute.String("source", "porter.build.buildkit"))
+		ctx, log = log.StartSpanWithName("buildkit", attribute.String("source", "porter.build.buildkit"))
 		defer log.EndSpan()
 		out = unstructuredLogger{log}
 	}
diff --git a/pkg/cnab/provider/action.go b/pkg/cnab/provider/action.go
index 9a532fa3..449dca1f 100644
--- a/pkg/cnab/provider/action.go
+++ b/pkg/cnab/provider/action.go
@@ -108,7 +108,7 @@ func (r *Runtime) AddRelocation(args ActionArguments) action.OperationConfigFunc
 }
 
 func (r *Runtime) Execute(ctx context.Context, args ActionArguments) error {
-	ctx, log := r.Log.StartSpan(ctx, "Execute Bundle",
+	ctx, log := r.Log.StartSpan(ctx,
 		attribute.String("action", args.Action),
 		attribute.Bool("allowDockerHostAccess", args.AllowDockerHostAccess),
 		attribute.String("driver", args.Driver))
diff --git a/pkg/porter/apply.go b/pkg/porter/apply.go
index 937b3290..ddba4e97 100644
--- a/pkg/porter/apply.go
+++ b/pkg/porter/apply.go
@@ -50,7 +50,9 @@ 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, "InstallationApply")
+	ctx, log := p.Log.StartSpan(ctx)
+	defer log.EndSpan()
+
 	log.Debugf("Reading input file %s", opts.File)
 
 	namespace, err := p.getNamespaceFromFile(opts)
diff --git a/pkg/porter/install.go b/pkg/porter/install.go
index 512cf06b..51bd7c6f 100644
--- a/pkg/porter/install.go
+++ b/pkg/porter/install.go
@@ -54,7 +54,8 @@ 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, "InstallBundle")
+	ctx, log := p.Log.StartSpan(ctx)
+	defer log.EndSpan()
 
 	// Figure out which bundle/installation we are working with
 	bundleRef, err := p.resolveBundleReference(ctx, opts.BundleActionOptions)
diff --git a/pkg/porter/list.go b/pkg/porter/list.go
index e15edd56..51815f84 100644
--- a/pkg/porter/list.go
+++ b/pkg/porter/list.go
@@ -1,6 +1,7 @@
 package porter
 
 import (
+	"context"
 	"fmt"
 	"sort"
 	"strings"
@@ -122,14 +123,17 @@ func NewDisplayRun(run claims.Run) DisplayRun {
 }
 
 // ListInstallations lists installed bundles.
-func (p *Porter) ListInstallations(opts ListOptions) ([]claims.Installation, error) {
+func (p *Porter) ListInstallations(ctx context.Context, opts ListOptions) ([]claims.Installation, error) {
+	_, log := p.Log.StartSpan(ctx)
+	defer log.EndSpan()
+
 	installations, err := p.Claims.ListInstallations(opts.GetNamespace(), opts.Name, opts.ParseLabels())
 	return installations, errors.Wrap(err, "could not list installations")
 }
 
 // PrintInstallations prints installed bundles.
-func (p *Porter) PrintInstallations(opts ListOptions) error {
-	installations, err := p.ListInstallations(opts)
+func (p *Porter) PrintInstallations(ctx context.Context, opts ListOptions) error {
+	installations, err := p.ListInstallations(ctx, opts)
 	if err != nil {
 		return err
 	}
diff --git a/pkg/tracing/logger.go b/pkg/tracing/logger.go
index 984b1b5d..78edd0d0 100644
--- a/pkg/tracing/logger.go
+++ b/pkg/tracing/logger.go
@@ -4,6 +4,8 @@ import (
 	"context"
 	"fmt"
 	"os"
+	"runtime"
+	"strings"
 
 	"github.com/pkg/errors"
 	"go.opentelemetry.io/otel/attribute"
@@ -14,7 +16,8 @@ import (
 )
 
 type RootLogger interface {
-	StartSpan(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger)
+	StartSpan(ctx context.Context, attrs ...attribute.KeyValue) (context.Context, ScopedLogger)
+	StartSpanWithName(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger)
 	Debug(span trace.Span, msg string, attrs ...attribute.KeyValue)
 	Debugf(span trace.Span, format string, args ...interface{})
 	Info(span trace.Span, msg string, attrs ...attribute.KeyValue)
@@ -49,17 +52,21 @@ func NewLogger(logger *zap.Logger, tracer trace.Tracer, attrs ...attribute.KeyVa
 	}
 }
 
-func (l traceLogger) StartSpan(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
+// StartSpanWithName creates a span with the name provided by the caller.
+func (l traceLogger) StartSpanWithName(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
 	type HasParentSpan interface {
 		ParentSpanID() trace.SpanID
 	}
+
 	childCtx, childSpan := l.Tracer.Start(ctx, op)
+
 	childSpan.SetAttributes(attrs...)
 
 	isRootSpan := true
 	if s, ok := childSpan.(HasParentSpan); ok {
 		isRootSpan = !s.ParentSpanID().IsValid()
 	}
+
 	if isRootSpan {
 		childSpan.SetAttributes(l.rootAttrs...)
 	}
@@ -67,6 +74,11 @@ func (l traceLogger) StartSpan(ctx context.Context, op string, attrs ...attribut
 	return NewScopedLogger(childCtx, childSpan, l)
 }
 
+// StartSpanWithName creates a span with the caller's function name.
+func (l traceLogger) StartSpan(ctx context.Context, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
+	return l.StartSpanWithName(ctx, callerFunc(0), attrs...)
+}
+
 func (l traceLogger) Debug(span trace.Span, msg string, attrs ...attribute.KeyValue) {
 	l.Logger.Debug(msg, ConvertAttributesToFields(attrs)...)
 
@@ -189,14 +201,18 @@ func newConsoleLogger() RootLogger {
 	}
 }
 
-func (n consoleLogger) StartSpan(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
+func (n consoleLogger) StartSpanWithName(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
 	childCtx, childSpan := n.tracer.Start(ctx, op)
 	childSpan.SetAttributes(attrs...)
 	return NewScopedLogger(childCtx, childSpan, n)
 }
 
-func (n consoleLogger) StartSpanInLog(ctx context.Context, op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
-	return n.StartSpan(ctx, op, attrs...)
+func (n consoleLogger) StartSpan(ctx context.Context, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
+	return n.StartSpanWithName(ctx, callerFunc(0), attrs...)
+}
+
+func (n consoleLogger) StartSpanInLog(ctx context.Context, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
+	return n.StartSpanWithName(ctx, callerFunc(0), attrs...)
 }
 
 func (n consoleLogger) Debug(span trace.Span, msg string, attrs ...attribute.KeyValue) {
@@ -231,3 +247,46 @@ func (n consoleLogger) Error(span trace.Span, err error, attrs ...attribute.KeyV
 func (n consoleLogger) Errorf(span trace.Span, msg string, args ...interface{}) error {
 	return n.Error(span, errors.Errorf(msg, args...))
 }
+
+func callerFunc(frames int) string {
+	var pc [1]uintptr
+	// we expect there're 3 functions(runtime.Callers, callerFunc,
+	// StartSpanNamedFromCaller) the stack before the actual caller functions
+	// we would like to find. If no function is found on the stack, return
+	// unknown
+	if runtime.Callers(frames+3, pc[:]) != 1 {
+		return "unknown"
+	}
+	// translate the PC into function information
+	frame, _ := runtime.CallersFrames(pc[:]).Next()
+	if frame.Function == "" {
+		return "unknown"
+	}
+
+	fnName, ok := extractFuncName(frame.Function)
+	if !ok {
+		return "unknown"
+	}
+
+	return fnName
+
+}
+
+// extractFuncName returns function names from a qualified full import path.
+// for example: "github.com/getporter/porter.ListInstallations", "main.Install"
+func extractFuncName(fn string) (string, bool) {
+	lastSlashIdx := strings.LastIndex(fn, "/")
+	if lastSlashIdx+1 >= len(fn) {
+		// a function name ended with a "/"
+		return "", false
+	}
+
+	qualifiedName := fn[lastSlashIdx+1:]
+	packageDotPos := strings.Index(qualifiedName, ".")
+	if packageDotPos < 0 || packageDotPos+1 >= len(qualifiedName) {
+		// qualifiedName ended with a "."
+		return "", false
+	}
+
+	return qualifiedName[packageDotPos+1:], true
+}
diff --git a/pkg/tracing/scopedLogger.go b/pkg/tracing/scopedLogger.go
index aa708fd4..f1bc350a 100644
--- a/pkg/tracing/scopedLogger.go
+++ b/pkg/tracing/scopedLogger.go
@@ -8,7 +8,8 @@ import (
 )
 
 type ScopedLogger interface {
-	StartSpan(op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger)
+	StartSpan(attrs ...attribute.KeyValue) (context.Context, ScopedLogger)
+	StartSpanWithName(ops string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger)
 	EndSpan(opts ...trace.SpanEndOption)
 	Debug(msg string, attrs ...attribute.KeyValue)
 	Debugf(format string, args ...interface{})
@@ -57,8 +58,12 @@ func (l scopedTraceLogger) EndSpan(opts ...trace.SpanEndOption) {
 	l.span.End(opts...)
 }
 
-func (l scopedTraceLogger) StartSpan(op string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
-	return l.rootLogger.StartSpan(l.ctx, op, attrs...)
+func (l scopedTraceLogger) StartSpan(attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
+	return l.rootLogger.StartSpanWithName(l.ctx, callerFunc(0), attrs...)
+}
+
+func (l scopedTraceLogger) StartSpanWithName(ops string, attrs ...attribute.KeyValue) (context.Context, ScopedLogger) {
+	return l.rootLogger.StartSpanWithName(l.ctx, ops, attrs...)
 }
 
 func (l scopedTraceLogger) Debug(msg string, attrs ...attribute.KeyValue) {


Test patch:
diff --git a/mage/tests/kind.go b/mage/tests/kind.go
index 0568867b..32a763d8 100644
--- a/mage/tests/kind.go
+++ b/mage/tests/kind.go
@@ -39,6 +39,7 @@ func EnsureTestCluster() {
 	if !useCluster() {
 		CreateTestCluster()
 	}
+
 	mgx.Must(docker.StartDockerRegistry())
 }
 
@@ -112,7 +113,8 @@ func CreateTestCluster() {
 	mgx.Must(errors.Wrap(err, "could not write kind config file"))
 	defer os.Remove("kind.config.yaml")
 
-	must.Run("kind", "create", "cluster", "--name", getKindClusterName(), "--config", "kind.config.yaml")
+	must.Command("kind", "create", "cluster", "--name", getKindClusterName(), "--config", "kind.config.yaml").
+		Env("KIND_EXPERIMENTAL_DOCKER_NETWORK=" + docker.DefaultNetworkName).Run()
 
 	// Document the local registry
 	kubectl("apply", "-f", "mage/tests/local-registry.yaml").Run()
diff --git a/pkg/agent/agent_test.go b/pkg/agent/agent_test.go
index 99c5d53a..98b8960a 100644
--- a/pkg/agent/agent_test.go
+++ b/pkg/agent/agent_test.go
@@ -28,6 +28,7 @@ func TestExecute(t *testing.T) {
 	require.NoError(t, err)
 	assert.True(t, run, "porter should have run")
 	gotStderr := stderrBuff.String()
+	assert.Contains(t, gotStderr, "porter version", "the agent should always print the porter CLI version")
 	assert.Contains(t, stdoutBuff.String(), "Usage:", "porter command output should be printed")
 
 	contents, err := os.ReadFile(filepath.Join(home, "config.toml"))
diff --git a/pkg/context/context_test.go b/pkg/context/context_test.go
index 45b26166..2e5759ca 100644
--- 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(), t.Name())
+	_, log := c.Log.StartSpan(context.Background())
 	log.Info("a thing happened")
 	log.Warn("a weird thing happened")
 	log.Error(errors.New("a bad thing happened"))
diff --git a/pkg/porter/list_test.go b/pkg/porter/list_test.go
index cdbf2987..cc80ccbf 100644
--- a/pkg/porter/list_test.go
+++ b/pkg/porter/list_test.go
@@ -1,6 +1,7 @@
 package porter
 
 import (
+	"context"
 	"testing"
 
 	"get.porter.sh/porter/pkg/claims"
@@ -63,26 +64,26 @@ func TestPorter_ListInstallations(t *testing.T) {
 
 	t.Run("all-namespaces", func(t *testing.T) {
 		opts := ListOptions{AllNamespaces: true}
-		results, err := p.ListInstallations(opts)
+		results, err := p.ListInstallations(context.Background(), opts)
 		require.NoError(t, err)
 		assert.Len(t, results, 6)
 	})
 
 	t.Run("local namespace", func(t *testing.T) {
 		opts := ListOptions{Namespace: "dev"}
-		results, err := p.ListInstallations(opts)
+		results, err := p.ListInstallations(context.Background(), opts)
 		require.NoError(t, err)
 		assert.Len(t, results, 2)
 
 		opts = ListOptions{Namespace: "test"}
-		results, err = p.ListInstallations(opts)
+		results, err = p.ListInstallations(context.Background(), opts)
 		require.NoError(t, err)
 		assert.Len(t, results, 3)
 	})
 
 	t.Run("global namespace", func(t *testing.T) {
 		opts := ListOptions{Namespace: ""}
-		results, err := p.ListInstallations(opts)
+		results, err := p.ListInstallations(context.Background(), opts)
 		require.NoError(t, err)
 		assert.Len(t, results, 1)
 	})
diff --git a/pkg/tracing/logger_test.go b/pkg/tracing/logger_test.go
new file mode 100644
index 00000000..09a712ca
--- /dev/null
+++ b/pkg/tracing/logger_test.go
@@ -0,0 +1,21 @@
+package tracing
+
+import "testing"
+
+func TestExtractFuncName(t *testing.T) {
+	for _, test := range []struct {
+		input    string
+		expected string
+		ok       bool
+	}{
+		{"", "", false},
+		{"porter/", "", false},
+		{"porter/v.", "", false},
+		{"github.com/getporter/porter/tracing.StartSpan", "StartSpan", true},
+	} {
+		fn, ok := extractFuncName(test.input)
+		if fn != test.expected || ok != test.ok {
+			t.Errorf("failed %q, got %q %v, expected %q %v", test.input, fn, ok, test.expected, test.ok)
+		}
+	}
+}
diff --git a/tests/integration/claim_migration_test.go b/tests/integration/claim_migration_test.go
index 78237081..635583f6 100644
--- a/tests/integration/claim_migration_test.go
+++ b/tests/integration/claim_migration_test.go
@@ -1,8 +1,10 @@
+//go:build integration
 // +build integration
 
 package integration
 
 import (
+	"context"
 	"testing"
 
 	"get.porter.sh/porter/pkg/porter"
@@ -29,7 +31,7 @@ func TestClaimMigration_List(t *testing.T) {
 	err := p.MigrateStorage()
 	require.NoError(t, err, "MigrateStorage failed")
 
-	installations, err := p.ListInstallations(porter.ListOptions{})
+	installations, err := p.ListInstallations(context.Background(), porter.ListOptions{})
 	require.NoError(t, err, "could not list installations")
 	require.Len(t, installations, 1, "expected one installation")
 	assert.Equal(t, "mybun", installations[0].Name, "unexpected list of installation names")