Add more Opentracing detail to the app (#3383)

* Pass Go context down to Renderers

This is useful for cancellation or tracing.

* Add tracing spans to app

Also log things like number of nodes in Map, total number of reports.

app/api_topologies.go

@@ -1,6 +1,7 @@
 package app
 
 import (
+	"context"
 	"fmt"
 	"net/http"
 	"net/url"
@@ -9,9 +10,8 @@ import (
 	"sync"
 	"time"
 
-	"context"
-
 	"github.com/gorilla/mux"
+	opentracing "github.com/opentracing/opentracing-go"
 	log "github.com/sirupsen/logrus"
 
 	"github.com/weaveworks/scope/probe/docker"
@@ -479,32 +479,36 @@ func (r *Registry) makeTopologyList(rep Reporter) CtxHandlerFunc {
 			respondWith(w, http.StatusInternalServerError, err)
 			return
 		}
-		respondWith(w, http.StatusOK, r.renderTopologies(report, req))
+		respondWith(w, http.StatusOK, r.renderTopologies(ctx, report, req))
 	}
 }
 
-func (r *Registry) renderTopologies(rpt report.Report, req *http.Request) []APITopologyDesc {
+func (r *Registry) renderTopologies(ctx context.Context, rpt report.Report, req *http.Request) []APITopologyDesc {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "app.renderTopologies")
+	defer span.Finish()
 	topologies := []APITopologyDesc{}
 	req.ParseForm()
 	r.walk(func(desc APITopologyDesc) {
 		renderer, filter, _ := r.RendererForTopology(desc.id, req.Form, rpt)
-		desc.Stats = computeStats(rpt, renderer, filter)
+		desc.Stats = computeStats(ctx, rpt, renderer, filter)
 		for i, sub := range desc.SubTopologies {
 			renderer, filter, _ := r.RendererForTopology(sub.id, req.Form, rpt)
-			desc.SubTopologies[i].Stats = computeStats(rpt, renderer, filter)
+			desc.SubTopologies[i].Stats = computeStats(ctx, rpt, renderer, filter)
 		}
 		topologies = append(topologies, desc)
 	})
 	return updateFilters(rpt, topologies)
 }
 
-func computeStats(rpt report.Report, renderer render.Renderer, transformer render.Transformer) topologyStats {
+func computeStats(ctx context.Context, rpt report.Report, renderer render.Renderer, transformer render.Transformer) topologyStats {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "app.computeStats")
+	defer span.Finish()
 	var (
 		nodes     int
 		realNodes int
 		edges     int
 	)
-	r := render.Render(rpt, renderer, transformer)
+	r := render.Render(ctx, rpt, renderer, transformer)
 	for _, n := range r.Nodes {
 		nodes++
 		if n.Topology != render.Pseudo {

app/api_topologies_test.go

@@ -2,6 +2,7 @@ package app_test
 
 import (
 	"bytes"
+	"context"
 	"net/http/httptest"
 	"net/url"
 	"testing"
@@ -118,7 +119,7 @@ func TestRendererForTopologyWithFiltering(t *testing.T) {
 	input.Container.Nodes[fixture.ClientContainerNodeID] = input.Container.Nodes[fixture.ClientContainerNodeID].WithLatests(map[string]string{
 		docker.LabelPrefix + "works.weave.role": "system",
 	})
-	have := utils.Prune(render.Render(input, renderer, filter).Nodes)
+	have := utils.Prune(render.Render(context.Background(), input, renderer, filter).Nodes)
 	want := utils.Prune(expected.RenderedContainers.Copy())
 	delete(want, fixture.ClientContainerNodeID)
 	delete(want, render.MakePseudoNodeID(render.UncontainedID, fixture.ServerHostID))
@@ -149,7 +150,7 @@ func TestRendererForTopologyNoFiltering(t *testing.T) {
 	input.Container.Nodes[fixture.ClientContainerNodeID] = input.Container.Nodes[fixture.ClientContainerNodeID].WithLatests(map[string]string{
 		docker.LabelPrefix + "works.weave.role": "system",
 	})
-	have := utils.Prune(render.Render(input, renderer, filter).Nodes)
+	have := utils.Prune(render.Render(context.Background(), input, renderer, filter).Nodes)
 	want := utils.Prune(expected.RenderedContainers.Copy())
 	delete(want, render.MakePseudoNodeID(render.UncontainedID, fixture.ServerHostID))
 	delete(want, render.OutgoingInternetID)
@@ -183,7 +184,8 @@ func getTestContainerLabelFilterTopologySummary(t *testing.T, exclude bool) (det
 		return nil, err
 	}
 
-	return detailed.Summaries(detailed.RenderContext{Report: fixture.Report}, render.Render(fixture.Report, renderer, filter).Nodes), nil
+	ctx := context.Background()
+	return detailed.Summaries(ctx, detailed.RenderContext{Report: fixture.Report}, render.Render(ctx, fixture.Report, renderer, filter).Nodes), nil
 }
 
 func TestAPITopologyAddsKubernetes(t *testing.T) {

app/api_topology.go

@@ -42,7 +42,7 @@ type rendererHandler func(context.Context, render.Renderer, render.Transformer,
 // Full topology.
 func handleTopology(ctx context.Context, renderer render.Renderer, transformer render.Transformer, rc detailed.RenderContext, w http.ResponseWriter, r *http.Request) {
 	respondWith(w, http.StatusOK, APITopology{
-		Nodes: detailed.Summaries(rc, render.Render(rc.Report, renderer, transformer).Nodes),
+		Nodes: detailed.Summaries(ctx, rc, render.Render(ctx, rc.Report, renderer, transformer).Nodes),
 	})
 }
 
@@ -58,7 +58,7 @@ func handleNode(ctx context.Context, renderer render.Renderer, transformer rende
 	// filtering, which gives us the node (if it exists at all), and
 	// then (2) applying the filter separately to that result.  If the
 	// node is lost in the second step, we simply put it back.
-	nodes := renderer.Render(rc.Report)
+	nodes := renderer.Render(ctx, rc.Report)
 	node, ok := nodes.Nodes[nodeID]
 	if !ok {
 		http.NotFound(w, r)
@@ -145,7 +145,7 @@ func handleWebsocket(
 			log.Errorf("Error generating report: %v", err)
 			return
 		}
-		newTopo := detailed.Summaries(RenderContextForReporter(rep, re), render.Render(re, renderer, filter).Nodes)
+		newTopo := detailed.Summaries(ctx, RenderContextForReporter(rep, re), render.Render(ctx, re, renderer, filter).Nodes)
 		diff := detailed.TopoDiff(previousTopo, newTopo)
 		previousTopo = newTopo
 

app/benchmark_internal_test.go

@@ -1,6 +1,7 @@
 package app
 
 import (
+	"context"
 	"flag"
 	"math/rand"
 	"net/http"
@@ -100,7 +101,7 @@ func renderForTopology(b *testing.B, topologyID string, report report.Report) re
 	if err != nil {
 		b.Fatal(err)
 	}
-	return render.Render(report, renderer, filter).Nodes
+	return render.Render(context.Background(), report, renderer, filter).Nodes
 }
 
 func benchmarkRenderTopology(b *testing.B, topologyID string) {
@@ -111,7 +112,7 @@ func benchmarkRenderTopology(b *testing.B, topologyID string) {
 
 func BenchmarkRenderList(b *testing.B) {
 	benchmarkRender(b, func(report report.Report) {
-		topologyRegistry.renderTopologies(report, &http.Request{Form: url.Values{}})
+		topologyRegistry.renderTopologies(context.Background(), report, &http.Request{Form: url.Values{}})
 	})
 }
 
@@ -140,12 +141,13 @@ func BenchmarkRenderProcessNames(b *testing.B) {
 }
 
 func benchmarkSummarizeTopology(b *testing.B, topologyID string) {
+	ctx := context.Background()
 	r := getReport(b)
 	rc := detailed.RenderContext{Report: r}
 	nodes := renderForTopology(b, topologyID, r)
 	b.ResetTimer()
 	for i := 0; i < b.N; i++ {
-		detailed.Summaries(rc, nodes)
+		detailed.Summaries(ctx, rc, nodes)
 	}
 }
 

app/multitenant/aws_collector.go

@@ -15,6 +15,8 @@ import (
 	"github.com/aws/aws-sdk-go/service/dynamodb"
 	"github.com/bluele/gcache"
 	"github.com/nats-io/nats"
+	opentracing "github.com/opentracing/opentracing-go"
+	otlog "github.com/opentracing/opentracing-go/log"
 	"github.com/prometheus/client_golang/prometheus"
 	log "github.com/sirupsen/logrus"
 
@@ -336,10 +338,13 @@ func (c *awsCollector) getReports(ctx context.Context, reportKeys []string) ([]r
 }
 
 func (c *awsCollector) Report(ctx context.Context, timestamp time.Time) (report.Report, error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "awsCollector.Report")
+	defer span.Finish()
 	reportKeys, err := c.getReportKeys(ctx, timestamp)
 	if err != nil {
 		return report.MakeReport(), err
 	}
+	span.LogFields(otlog.Int("keys", len(reportKeys)), otlog.String("timestamp", timestamp.String()))
 	log.Debugf("Fetching %d reports to %v", len(reportKeys), timestamp)
 	reports, err := c.getReports(ctx, reportKeys)
 	if err != nil {

app/multitenant/memcache_client.go

@@ -9,6 +9,8 @@ import (
 
 	"context"
 	"github.com/bradfitz/gomemcache/memcache"
+	opentracing "github.com/opentracing/opentracing-go"
+	otlog "github.com/opentracing/opentracing-go/log"
 	"github.com/prometheus/client_golang/prometheus"
 	log "github.com/sirupsen/logrus"
 
@@ -150,13 +152,16 @@ func memcacheStatusCode(err error) string {
 
 // FetchReports gets reports from memcache.
 func (c *MemcacheClient) FetchReports(ctx context.Context, keys []string) (map[string]report.Report, []string, error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "Memcache.FetchReports")
+	defer span.Finish()
 	defer memcacheRequests.Add(float64(len(keys)))
 	var found map[string]*memcache.Item
 	err := instrument.TimeRequestHistogramStatus(ctx, "Memcache.GetMulti", memcacheRequestDuration, memcacheStatusCode, func(_ context.Context) error {
 		var err error
 		found, err = c.client.GetMulti(keys)
 		return err
 	})
+	span.LogFields(otlog.Int("keys", len(keys)), otlog.Int("hits", len(found)))
 	if err != nil {
 		return nil, keys, err
 	}

render/benchmark_test.go

@@ -1,6 +1,7 @@
 package render_test
 
 import (
+	"context"
 	"flag"
 	"io/ioutil"
 	"testing"
@@ -51,7 +52,7 @@ func benchmarkRender(b *testing.B, r render.Renderer) {
 		b.StopTimer()
 		render.ResetCache()
 		b.StartTimer()
-		benchmarkRenderResult = r.Render(report)
+		benchmarkRenderResult = r.Render(context.Background(), report)
 		if len(benchmarkRenderResult.Nodes) == 0 {
 			b.Errorf("Rendered topology contained no nodes")
 		}

render/container.go

@@ -1,6 +1,7 @@
 package render
 
 import (
+	"context"
 	"regexp"
 
 	"github.com/weaveworks/scope/probe/docker"
@@ -53,8 +54,8 @@ type connectionJoin struct {
 	topology string
 }
 
-func (c connectionJoin) Render(rpt report.Report) Nodes {
-	inputNodes := TopologySelector(c.topology).Render(rpt).Nodes
+func (c connectionJoin) Render(ctx context.Context, rpt report.Report) Nodes {
+	inputNodes := TopologySelector(c.topology).Render(ctx, rpt).Nodes
 	// Collect all the IPs we are trying to map to, and which ID they map from
 	var ipNodes = map[string]string{}
 	for _, n := range inputNodes {
@@ -92,7 +93,7 @@ func (c connectionJoin) Render(rpt report.Report) Nodes {
 			// from ipNodes, which is populated from c.topology, which
 			// is where MapEndpoints will look.
 			return id
-		}, c.topology).Render(rpt)
+		}, c.topology).Render(ctx, rpt)
 }
 
 // FilterEmpty is a Renderer which filters out nodes which have no children
@@ -121,9 +122,9 @@ type containerWithImageNameRenderer struct {
 
 // Render produces a container graph where the the latest metadata contains the
 // container image name, if found.
-func (r containerWithImageNameRenderer) Render(rpt report.Report) Nodes {
-	containers := r.Renderer.Render(rpt)
-	images := SelectContainerImage.Render(rpt)
+func (r containerWithImageNameRenderer) Render(ctx context.Context, rpt report.Report) Nodes {
+	containers := r.Renderer.Render(ctx, rpt)
+	images := SelectContainerImage.Render(ctx, rpt)
 
 	outputs := make(report.Nodes, len(containers.Nodes))
 	for id, c := range containers.Nodes {

render/container_test.go

@@ -1,6 +1,7 @@
 package render_test
 
 import (
+	"context"
 	"fmt"
 	"testing"
 
@@ -53,7 +54,7 @@ func testMap(t *testing.T, f render.MapFunc, input testcase) {
 }
 
 func TestContainerRenderer(t *testing.T) {
-	have := utils.Prune(render.ContainerWithImageNameRenderer.Render(fixture.Report).Nodes)
+	have := utils.Prune(render.ContainerWithImageNameRenderer.Render(context.Background(), fixture.Report).Nodes)
 	want := utils.Prune(expected.RenderedContainers)
 	if !reflect.DeepEqual(want, have) {
 		t.Error(test.Diff(want, have))
@@ -67,7 +68,7 @@ func TestContainerFilterRenderer(t *testing.T) {
 	input.Container.Nodes[fixture.ClientContainerNodeID] = input.Container.Nodes[fixture.ClientContainerNodeID].WithLatests(map[string]string{
 		docker.LabelPrefix + "works.weave.role": "system",
 	})
-	have := utils.Prune(render.Render(input, render.ContainerWithImageNameRenderer, filterApplication).Nodes)
+	have := utils.Prune(render.Render(context.Background(), input, render.ContainerWithImageNameRenderer, filterApplication).Nodes)
 	want := utils.Prune(expected.RenderedContainers.Copy())
 	delete(want, fixture.ClientContainerNodeID)
 	if !reflect.DeepEqual(want, have) {
@@ -76,15 +77,15 @@ func TestContainerFilterRenderer(t *testing.T) {
 }
 
 func TestContainerHostnameRenderer(t *testing.T) {
-	have := utils.Prune(render.Render(fixture.Report, render.ContainerHostnameRenderer, render.Transformers(nil)).Nodes)
+	have := utils.Prune(render.Render(context.Background(), fixture.Report, render.ContainerHostnameRenderer, render.Transformers(nil)).Nodes)
 	want := utils.Prune(expected.RenderedContainerHostnames)
 	if !reflect.DeepEqual(want, have) {
 		t.Error(test.Diff(want, have))
 	}
 }
 
 func TestContainerHostnameFilterRenderer(t *testing.T) {
-	have := utils.Prune(render.Render(fixture.Report, render.ContainerHostnameRenderer, filterSystem).Nodes)
+	have := utils.Prune(render.Render(context.Background(), fixture.Report, render.ContainerHostnameRenderer, filterSystem).Nodes)
 	want := utils.Prune(expected.RenderedContainerHostnames.Copy())
 	delete(want, fixture.ClientContainerHostname)
 	delete(want, fixture.ServerContainerHostname)
@@ -95,15 +96,15 @@ func TestContainerHostnameFilterRenderer(t *testing.T) {
 }
 
 func TestContainerImageRenderer(t *testing.T) {
-	have := utils.Prune(render.Render(fixture.Report, render.ContainerImageRenderer, render.Transformers(nil)).Nodes)
+	have := utils.Prune(render.Render(context.Background(), fixture.Report, render.ContainerImageRenderer, render.Transformers(nil)).Nodes)
 	want := utils.Prune(expected.RenderedContainerImages)
 	if !reflect.DeepEqual(want, have) {
 		t.Error(test.Diff(want, have))
 	}
 }
 
 func TestContainerImageFilterRenderer(t *testing.T) {
-	have := utils.Prune(render.Render(fixture.Report, render.ContainerImageRenderer, filterSystem).Nodes)
+	have := utils.Prune(render.Render(context.Background(), fixture.Report, render.ContainerImageRenderer, filterSystem).Nodes)
 	want := utils.Prune(expected.RenderedContainerHostnames.Copy())
 	delete(want, fixture.ClientContainerHostname)
 	delete(want, fixture.ServerContainerHostname)

render/detailed/node_test.go

@@ -1,6 +1,7 @@
 package detailed_test
 
 import (
+	"context"
 	"fmt"
 	"testing"
 
@@ -18,7 +19,7 @@ import (
 )
 
 func child(t *testing.T, r render.Renderer, id string) detailed.NodeSummary {
-	s, ok := detailed.MakeNodeSummary(detailed.RenderContext{Report: fixture.Report}, r.Render(fixture.Report).Nodes[id])
+	s, ok := detailed.MakeNodeSummary(detailed.RenderContext{Report: fixture.Report}, r.Render(context.Background(), fixture.Report).Nodes[id])
 	if !ok {
 		t.Fatalf("Expected node %s to be summarizable, but wasn't", id)
 	}
@@ -30,7 +31,7 @@ func connectionID(nodeID string, addr string) string {
 }
 
 func TestMakeDetailedHostNode(t *testing.T) {
-	renderableNodes := render.HostRenderer.Render(fixture.Report).Nodes
+	renderableNodes := render.HostRenderer.Render(context.Background(), fixture.Report).Nodes
 	renderableNode := renderableNodes[fixture.ClientHostNodeID]
 	have := detailed.MakeNode("hosts", detailed.RenderContext{Report: fixture.Report}, renderableNodes, renderableNode)
 
@@ -177,7 +178,7 @@ func TestMakeDetailedHostNode(t *testing.T) {
 
 func TestMakeDetailedContainerNode(t *testing.T) {
 	id := fixture.ServerContainerNodeID
-	renderableNodes := render.ContainerWithImageNameRenderer.Render(fixture.Report).Nodes
+	renderableNodes := render.ContainerWithImageNameRenderer.Render(context.Background(), fixture.Report).Nodes
 	renderableNode, ok := renderableNodes[id]
 	if !ok {
 		t.Fatalf("Node not found: %s", id)
@@ -306,7 +307,7 @@ func TestMakeDetailedContainerNode(t *testing.T) {
 
 func TestMakeDetailedPodNode(t *testing.T) {
 	id := fixture.ServerPodNodeID
-	renderableNodes := render.PodRenderer.Render(fixture.Report).Nodes
+	renderableNodes := render.PodRenderer.Render(context.Background(), fixture.Report).Nodes
 	renderableNode, ok := renderableNodes[id]
 	if !ok {
 		t.Fatalf("Node not found: %s", id)