tracing_test.go

Documentation: k8s.io/component-base/tracing

     1  /*
     2  Copyright 2022 The Kubernetes Authors.
     3  
     4  Licensed under the Apache License, Version 2.0 (the "License");
     5  you may not use this file except in compliance with the License.
     6  You may obtain a copy of the License at
     7  
     8      http://www.apache.org/licenses/LICENSE-2.0
     9  
    10  Unless required by applicable law or agreed to in writing, software
    11  distributed under the License is distributed on an "AS IS" BASIS,
    12  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    13  See the License for the specific language governing permissions and
    14  limitations under the License.
    15  */
    16  
    17  package tracing
    18  
    19  import (
    20  	"bytes"
    21  	"context"
    22  	"flag"
    23  	"fmt"
    24  	"strings"
    25  	"testing"
    26  	"time"
    27  
    28  	"go.opentelemetry.io/otel/attribute"
    29  	"go.opentelemetry.io/otel/sdk/trace"
    30  	"go.opentelemetry.io/otel/sdk/trace/tracetest"
    31  	"k8s.io/klog/v2"
    32  	utiltrace "k8s.io/utils/trace"
    33  )
    34  
    35  func init() {
    36  	klog.InitFlags(flag.CommandLine)
    37  	flag.CommandLine.Lookup("logtostderr").Value.Set("false")
    38  }
    39  
    40  func TestOpenTelemetryTracing(t *testing.T) {
    41  	// Setup OpenTelemetry for testing
    42  	fakeRecorder := tracetest.NewSpanRecorder()
    43  	otelTracer := trace.NewTracerProvider(trace.WithSpanProcessor(fakeRecorder)).Tracer(instrumentationScope)
    44  
    45  	func() {
    46  		ctx := context.Background()
    47  		// Create a parent OpenTelemetry span
    48  		ctx, span := otelTracer.Start(ctx, "parent otel span")
    49  		defer span.End()
    50  
    51  		// Creates a child span
    52  		_, tr := Start(ctx, "frobber", attribute.String("foo", "bar"))
    53  		defer tr.End(10 * time.Second)
    54  
    55  		time.Sleep(5 * time.Millisecond)
    56  		// Add one event to the frobber span
    57  		tr.AddEvent("reticulated splines", attribute.Bool("should I do it?", false)) // took 5ms
    58  		time.Sleep(10 * time.Millisecond)
    59  
    60  		// Add error event to the frobber span
    61  		tr.RecordError(fmt.Errorf("something went wrong"))
    62  
    63  		// Ensure setting context with span makes the next span a child
    64  		ctx = ContextWithSpan(context.Background(), tr)
    65  
    66  		// Add another event to the frobber span after getting the span from context
    67  		SpanFromContext(ctx).AddEvent("sequenced particles", attribute.Int("inches in foot", 12)) // took 10ms
    68  
    69  		// Creates a nested child span
    70  		_, tr = Start(ctx, "nested child span")
    71  		defer tr.End(10 * time.Second)
    72  	}()
    73  
    74  	output := fakeRecorder.Ended()
    75  	if len(output) != 3 {
    76  		t.Fatalf("got %d; expected len(output) == 3", len(output))
    77  	}
    78  	// Nested child span is ended first
    79  	nestedChild := output[0]
    80  	if nestedChild.Name() != "nested child span" {
    81  		t.Fatalf("got %s; expected nestedChild.Name() == nested child span", nestedChild.Name())
    82  	}
    83  	// Child span is ended second
    84  	child := output[1]
    85  	if !nestedChild.Parent().Equal(child.SpanContext()) {
    86  		t.Errorf("got child: %v, parent: %v; expected child.Parent() == parent.SpanContext()", nestedChild.Parent(), child.SpanContext())
    87  	}
    88  	if child.Name() != "frobber" {
    89  		t.Errorf("got %s; expected child.Name() == frobber", child.Name())
    90  	}
    91  	if len(child.Attributes()) != 1 {
    92  		t.Errorf("got attributes %v; expected one attribute in child.Attributes()", child.Attributes())
    93  	}
    94  	if len(child.Events()) != 3 {
    95  		t.Errorf("got events %v; expected 2 events in child.Events()", child.Events())
    96  	}
    97  	if child.Events()[0].Name != "reticulated splines" {
    98  		t.Errorf("got event %v; expected child.Events()[0].Name == reticulated splines", child.Events()[0])
    99  	}
   100  	if len(child.Events()[0].Attributes) != 1 {
   101  		t.Errorf("got event %v; expected 1 attribute in child.Events()[0].Attributes", child.Events()[0])
   102  	}
   103  	if child.Events()[1].Name != "exception" {
   104  		t.Errorf("got event %v; expected child.Events()[1].Name == something went wrong", child.Events()[1])
   105  	}
   106  	if len(child.Events()[1].Attributes) != 2 {
   107  		t.Errorf("got event %#v; expected 2 attribute in child.Events()[1].Attributes", child.Events()[1])
   108  	}
   109  	if child.Events()[2].Name != "sequenced particles" {
   110  		t.Errorf("got event %v; expected child.Events()[2].Name == sequenced particles", child.Events()[2])
   111  	}
   112  	if len(child.Events()[2].Attributes) != 1 {
   113  		t.Errorf("got event %v; expected 1 attribute in child.Events()[2].Attributes", child.Events()[2])
   114  	}
   115  	// Parent span is ended last
   116  	parent := output[2]
   117  	if !child.Parent().Equal(parent.SpanContext()) {
   118  		t.Fatalf("got child: %v, parent: %v; expected child.Parent() == parent.SpanContext()", child.Parent(), parent.SpanContext())
   119  	}
   120  	if parent.Name() != "parent otel span" {
   121  		t.Fatalf("got %s; expected parent.Name() == parent otel span", parent.Name())
   122  	}
   123  	if len(parent.Attributes()) != 0 {
   124  		t.Fatalf("got attributes %v; expected empty parent.Attributes()", parent.Attributes())
   125  	}
   126  }
   127  
   128  func TestUtilTracing(t *testing.T) {
   129  	var buf bytes.Buffer
   130  	klog.SetOutput(&buf)
   131  
   132  	ctx := context.Background()
   133  	// Create a utiltracing span
   134  	tr0 := utiltrace.New("parent utiltrace span")
   135  	ctx = utiltrace.ContextWithTrace(ctx, tr0)
   136  
   137  	// Creates a child span
   138  	_, tr1 := Start(ctx, "frobber", attribute.String("foo", "bar"))
   139  
   140  	time.Sleep(5 * time.Millisecond)
   141  	// Add one event to the frobber span
   142  	tr1.AddEvent("reticulated splines", attribute.Bool("should I do it?", false)) // took 5ms
   143  
   144  	time.Sleep(10 * time.Millisecond)
   145  
   146  	// Ensure setting context with span makes the next span a child
   147  	ctx = ContextWithSpan(context.Background(), tr1)
   148  
   149  	// Add another event to the frobber span after getting the span from context
   150  	SpanFromContext(ctx).AddEvent("sequenced particles", attribute.Int("inches in foot", 12)) // took 10ms
   151  
   152  	// Creates a nested child span
   153  	_, tr2 := Start(ctx, "nested child span")
   154  	// always log
   155  	tr2.End(0 * time.Second)
   156  	tr1.End(0 * time.Second)
   157  
   158  	// Since all traces are nested, no logging should have occurred yet
   159  	if buf.String() != "" {
   160  		t.Errorf("child traces were printed out before the parent span completed: %v", buf.String())
   161  	}
   162  
   163  	// Now, end the parent span to cause logging to occur
   164  	tr0.Log()
   165  
   166  	expected := []string{
   167  		`"frobber" foo:bar`,
   168  		`---"reticulated splines" should I do it?:false`,
   169  		`---"sequenced particles" inches in foot:12`,
   170  		`"nested child span"`,
   171  		`"parent utiltrace span"`,
   172  	}
   173  	for _, msg := range expected {
   174  		if !strings.Contains(buf.String(), msg) {
   175  			t.Errorf("\nMsg %q not found in log: \n%v\n", msg, buf.String())
   176  		}
   177  	}
   178  }
   179  
   180  func TestContextNoPanic(t *testing.T) {
   181  	ctx := context.Background()
   182  	// Make sure calling functions on spans from context doesn't panic
   183  	SpanFromContext(ctx).AddEvent("foo")
   184  	SpanFromContext(ctx).End(time.Minute)
   185  }
   186
View as plain text