[v2] Add logging to read/write spans in e2e tests (#5456)

## Which problem is this PR solving?
- Helps to debug unstable e2e tests in
#5418
- Current logs are still hard to follow even it already dump storage's
docker and OTEL col binary logs because we can't see which part of the
test related to which storage docker/ OTEL col binary logs.

## Description of the changes
- Add more logging to e2e tests that capture the timestamp of each
read/write run.

## How was this change tested?
- Run `STORAGE=grpc SPAN_STORAGE_TYPE=memory make
jaeger-v2-storage-integration-test`

## Checklist
- [x] I have read
https://github.com/jaegertracing/jaeger/blob/master/CONTRIBUTING_GUIDELINES.md
- [x] I have signed all commits
- [ ] I have added unit tests for the new functionality
- [x] I have run lint and test steps successfully
  - for `jaeger`: `make lint test`
  - for `jaeger-ui`: `yarn lint` and `yarn test`

Signed-off-by: James Ryans <[email protected]>

cmd/jaeger/internal/integration/e2e_integration.go

@@ -113,7 +113,7 @@ func (s *E2EStorageIntegration) e2eInitialize(t *testing.T, storage string) {
 
 	s.SpanWriter, err = createSpanWriter(logger, otlpPort)
 	require.NoError(t, err)
-	s.SpanReader, err = createSpanReader(ports.QueryGRPC)
+	s.SpanReader, err = createSpanReader(logger, ports.QueryGRPC)
 	require.NoError(t, err)
 }
 

cmd/jaeger/internal/integration/span_reader.go

@@ -11,6 +11,7 @@ import (
 	"math"
 	"strings"
 
+	"go.uber.org/zap"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/credentials/insecure"
 	"google.golang.org/grpc/status"
@@ -28,11 +29,13 @@ var (
 
 // SpanReader retrieve span data from Jaeger-v2 query with api_v2.QueryServiceClient.
 type spanReader struct {
+	logger     *zap.Logger
 	clientConn *grpc.ClientConn
 	client     api_v2.QueryServiceClient
 }
 
-func createSpanReader(port int) (*spanReader, error) {
+func createSpanReader(logger *zap.Logger, port int) (*spanReader, error) {
+	logger.Info("Creating the span reader", zap.Int("port", port))
 	opts := []grpc.DialOption{
 		grpc.WithTransportCredentials(insecure.NewCredentials()),
 	}
@@ -43,12 +46,14 @@ func createSpanReader(port int) (*spanReader, error) {
 	}
 
 	return &spanReader{
+		logger:     logger,
 		clientConn: cc,
 		client:     api_v2.NewQueryServiceClient(cc),
 	}, nil
 }
 
 func (r *spanReader) Close() error {
+	r.logger.Info("Closing the span writer")
 	return r.clientConn.Close()
 }
 
@@ -77,7 +82,9 @@ func (r *spanReader) GetTrace(ctx context.Context, traceID model.TraceID) (*mode
 		for i := range received.Spans {
 			spans = append(spans, &received.Spans[i])
 		}
+		r.logger.Info(fmt.Sprintf("GetTrace received %d spans (total %d)", len(received.Spans), len(spans)))
 	}
+	r.logger.Info(fmt.Sprintf("GetTraces received a total of %d spans", len(spans)))
 
 	return &model.Trace{
 		Spans: spans,
@@ -89,6 +96,7 @@ func (r *spanReader) GetServices(ctx context.Context) ([]string, error) {
 	if err != nil {
 		return []string{}, err
 	}
+	r.logger.Info(fmt.Sprintf("Received %d services", len(res.Services)))
 	return res.Services, nil
 }
 
@@ -101,6 +109,7 @@ func (r *spanReader) GetOperations(ctx context.Context, query spanstore.Operatio
 	if err != nil {
 		return operations, err
 	}
+	r.logger.Info(fmt.Sprintf("Received %d operations", len(res.Operations)))
 
 	for _, operation := range res.Operations {
 		operations = append(operations, spanstore.Operation{
@@ -133,6 +142,7 @@ func (r *spanReader) FindTraces(ctx context.Context, query *spanstore.TraceQuery
 		return traces, err
 	}
 
+	totalSpans := 0
 	spanMaps := map[string][]*model.Span{}
 	for received, err := stream.Recv(); !errors.Is(err, io.EOF); received, err = stream.Recv() {
 		if err != nil {
@@ -145,7 +155,10 @@ func (r *spanReader) FindTraces(ctx context.Context, query *spanstore.TraceQuery
 			}
 			spanMaps[traceID] = append(spanMaps[traceID], &received.Spans[i])
 		}
+		totalSpans += len(received.Spans)
+		r.logger.Info(fmt.Sprintf("FindTraces received %d spans (total %d)", len(received.Spans), totalSpans))
 	}
+	r.logger.Info(fmt.Sprintf("FindTraces received a total of %d spans", totalSpans))
 
 	for _, spans := range spanMaps {
 		traces = append(traces, &model.Trace{

cmd/jaeger/internal/integration/span_writer.go

@@ -27,10 +27,13 @@ var (
 
 // SpanWriter utilizes the OTLP exporter to send span data to the Jaeger-v2 receiver
 type spanWriter struct {
+	logger   *zap.Logger
 	exporter exporter.Traces
 }
 
 func createSpanWriter(logger *zap.Logger, port int) (*spanWriter, error) {
+	logger.Info("Creating the span writer", zap.Int("port", port))
+
 	factory := otlpexporter.NewFactory()
 	cfg := factory.CreateDefaultConfig().(*otlpexporter.Config)
 	cfg.Endpoint = fmt.Sprintf("localhost:%d", port)
@@ -51,11 +54,13 @@ func createSpanWriter(logger *zap.Logger, port int) (*spanWriter, error) {
 	}
 
 	return &spanWriter{
+		logger:   logger,
 		exporter: exporter,
 	}, nil
 }
 
 func (w *spanWriter) Close() error {
+	w.logger.Info("Closing the span writer")
 	return w.exporter.Shutdown(context.Background())
 }
 

plugin/storage/integration/integration.go

@@ -334,6 +334,7 @@ func (s *StorageIntegration) findTracesByQuery(t *testing.T, query *spanstore.Tr
 }
 
 func (s *StorageIntegration) writeTrace(t *testing.T, trace *model.Trace) {
+	t.Logf("%-23s Writing trace with %d spans", time.Now().Format("2006-01-02 15:04:05.999"), len(trace.Spans))
 	for _, span := range trace.Spans {
 		err := s.SpanWriter.WriteSpan(context.Background(), span)
 		require.NoError(t, err, "Not expecting error when writing trace to storage")