Fix trace diffs

Signed-off-by: Artem Glazychev <artem.glazychev@xored.com>
networkservicemesh · Feb 2, 2021 · 475b305 · 475b305
1 parent ed5476d
commit 475b305
Show file tree

Hide file tree

Showing 3 changed files with 160 additions and 9 deletions.
diff --git a/pkg/networkservice/core/trace/client.go b/pkg/networkservice/core/trace/client.go
@@ -27,21 +27,37 @@ import (
 
 	"github.com/networkservicemesh/api/pkg/api/networkservice"
 
+	"github.com/networkservicemesh/sdk/pkg/networkservice/core/next"
 	"github.com/networkservicemesh/sdk/pkg/tools/logger"
-
 	"github.com/networkservicemesh/sdk/pkg/tools/typeutils"
 )
 
 type traceClient struct {
 	traced networkservice.NetworkServiceClient
 }
 
+type printerClient struct{}
+
+func (t *printerClient) Request(ctx context.Context, request *networkservice.NetworkServiceRequest, opts ...grpc.CallOption) (*networkservice.Connection, error) {
+	logRequest(ctx, request)
+	conn, err := next.Client(ctx).Request(ctx, request, opts...)
+	logResponse(ctx, conn)
+	return conn, err
+}
+
+func (t *printerClient) Close(ctx context.Context, conn *networkservice.Connection, opts ...grpc.CallOption) (*empty.Empty, error) {
+	logRequest(ctx, conn)
+	r, err := next.Client(ctx).Close(ctx, conn, opts...)
+	logResponse(ctx, conn)
+	return r, err
+}
+
 // NewNetworkServiceClient - wraps tracing around the supplied networkservice.NetworkServiceClient
 func NewNetworkServiceClient(traced networkservice.NetworkServiceClient) networkservice.NetworkServiceClient {
-	if traced == nil {
-		return &traceClient{traced: traced}
-	}
-	return &traceClient{traced: traced}
+	return next.NewNetworkServiceClient(
+		&traceClient{traced: traced},
+		&printerClient{},
+	)
 }
 
 func (t *traceClient) Request(ctx context.Context, request *networkservice.NetworkServiceRequest, opts ...grpc.CallOption) (*networkservice.Connection, error) {
@@ -87,5 +103,7 @@ func (t *traceClient) Close(ctx context.Context, conn *networkservice.Connection
 		logger.Log(ctx).Errorf("%v", err)
 		return nil, err
 	}
+
+	logResponse(ctx, rv)
 	return rv, err
 }
diff --git a/pkg/networkservice/core/trace/common_test.go b/pkg/networkservice/core/trace/common_test.go
@@ -1,5 +1,7 @@
 // Copyright (c) 2020 Cisco Systems, Inc.
 //
+// Copyright (c) 2021 Doc.ai and/or its affiliates.
+//
 // SPDX-License-Identifier: Apache-2.0
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
@@ -18,14 +20,22 @@
 package trace_test
 
 import (
+	"bytes"
+	"context"
 	"encoding/json"
 	"testing"
 
+	"github.com/sirupsen/logrus"
+
+	"github.com/golang/protobuf/ptypes/empty"
 	"github.com/networkservicemesh/api/pkg/api/networkservice"
 	"github.com/networkservicemesh/api/pkg/api/networkservice/mechanisms/cls"
 	"github.com/stretchr/testify/require"
 
+	"github.com/networkservicemesh/sdk/pkg/networkservice/core/chain"
+	"github.com/networkservicemesh/sdk/pkg/networkservice/core/next"
 	"github.com/networkservicemesh/sdk/pkg/networkservice/core/trace"
+	"github.com/networkservicemesh/sdk/pkg/tools/logger"
 )
 
 func TestDiffMechanism(t *testing.T) {
@@ -91,6 +101,62 @@ func TestDiffPathAdd(t *testing.T) {
 	require.True(t, diff)
 }
 
+func TestTraceOutput(t *testing.T) {
+	// Configure logging
+	// Set output to buffer
+	var buff bytes.Buffer
+	logrus.SetOutput(&buff)
+	logrus.SetFormatter(&logrus.TextFormatter{
+		DisableTimestamp: true,
+	})
+	logger.EnableTracing(true)
+
+	// Create a chain with modifying elements
+	ch := chain.NewNamedNetworkServiceServer(
+		"TestTraceOutput",
+		&labelChangerFirstServer{},
+		&labelChangerSecondServer{},
+	)
+
+	request := newConnection()
+
+	conn, err := ch.Request(context.Background(), request)
+	require.NoError(t, err)
+	require.NotNil(t, conn)
+
+	e, err := ch.Close(context.Background(), conn)
+	require.NoError(t, err)
+	require.NotNil(t, e)
+
+	print(buff.String())
+
+	expectedOutput :=
+		"level=trace msg=\"[INFO] (1) ⎆ sdk/pkg/networkservice/core/trace_test/labelChangerFirstServer.Request()\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1.1)   request={\\\"connection\\\":{\\\"id\\\":\\\"conn-1\\\",\\\"context\\\":" +
+			"{\\\"ip_context\\\":{\\\"src_ip_required\\\":true}}},\\\"mechanism_preferences\\\":[{\\\"cls\\\":\\\"LOCAL\\\"," +
+			"\\\"type\\\":\\\"KERNEL\\\"},{\\\"cls\\\":\\\"LOCAL\\\",\\\"type\\\":\\\"KERNEL\\\",\\\"parameters\\\":{\\\"label\\\"" +
+			":\\\"v2\\\"}}]}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1.2)   request-diff={\\\"connection\\\":{\\\"labels\\\":{\\\"+Label\\\":\\\"A\\\"}}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2)  ⎆ sdk/pkg/networkservice/core/trace_test/labelChangerSecondServer.Request()\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.1)    request-diff={\\\"connection\\\":{\\\"labels\\\":{\\\"Label\\\":\\\"B\\\"}}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.2)    response={\\\"id\\\":\\\"conn-1\\\",\\\"context\\\":{\\\"ip_context\\\":{\\\"src_ip_required\\\":true}}," +
+			"\\\"labels\\\":{\\\"Label\\\":\\\"B\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.3)    response-diff={\\\"labels\\\":{\\\"Label\\\":\\\"C\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1.3)   response-diff={\\\"labels\\\":{\\\"Label\\\":\\\"D\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1) ⎆ sdk/pkg/networkservice/core/trace_test/labelChangerFirstServer.Close()\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1.1)   request={\\\"id\\\":\\\"conn-1\\\",\\\"context\\\":{\\\"ip_context\\\":{\\\"src_ip_required\\\":true}}," +
+			"\\\"labels\\\":{\\\"Label\\\":\\\"D\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1.2)   request-diff={\\\"labels\\\":{\\\"Label\\\":\\\"W\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2)  ⎆ sdk/pkg/networkservice/core/trace_test/labelChangerSecondServer.Close()\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.1)    request-diff={\\\"labels\\\":{\\\"Label\\\":\\\"X\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.2)    response={\\\"id\\\":\\\"conn-1\\\",\\\"context\\\":{\\\"ip_context\\\":{\\\"src_ip_required\\\"" +
+			":true}},\\\"labels\\\":{\\\"Label\\\":\\\"X\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.3)    response-diff={\\\"labels\\\":{\\\"Label\\\":\\\"Y\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1.3)   response-diff={\\\"labels\\\":{\\\"Label\\\":\\\"Z\\\"}}\" name=TestTraceOutput\n"
+
+	require.Equal(t, expectedOutput, buff.String())
+}
+
 func newConnection() *networkservice.NetworkServiceRequest {
 	return &networkservice.NetworkServiceRequest{
 		Connection: &networkservice.Connection{
@@ -116,3 +182,51 @@ func newConnection() *networkservice.NetworkServiceRequest {
 		},
 	}
 }
+
+type labelChangerFirstServer struct{}
+
+func (c *labelChangerFirstServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) {
+	request.Connection.Labels = map[string]string{
+		"Label": "A",
+	}
+	rv, err := next.Server(ctx).Request(ctx, request)
+	rv.Labels = map[string]string{
+		"Label": "D",
+	}
+	return rv, err
+}
+
+func (c *labelChangerFirstServer) Close(ctx context.Context, connection *networkservice.Connection) (*empty.Empty, error) {
+	connection.Labels = map[string]string{
+		"Label": "W",
+	}
+	r, err := next.Server(ctx).Close(ctx, connection)
+	connection.Labels = map[string]string{
+		"Label": "Z",
+	}
+	return r, err
+}
+
+type labelChangerSecondServer struct{}
+
+func (c *labelChangerSecondServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) {
+	request.Connection.Labels = map[string]string{
+		"Label": "B",
+	}
+	rv, err := next.Server(ctx).Request(ctx, request)
+	rv.Labels = map[string]string{
+		"Label": "C",
+	}
+	return rv, err
+}
+
+func (c *labelChangerSecondServer) Close(ctx context.Context, connection *networkservice.Connection) (*empty.Empty, error) {
+	connection.Labels = map[string]string{
+		"Label": "X",
+	}
+	r, err := next.Server(ctx).Close(ctx, connection)
+	connection.Labels = map[string]string{
+		"Label": "Y",
+	}
+	return r, err
+}
diff --git a/pkg/networkservice/core/trace/server.go b/pkg/networkservice/core/trace/server.go
@@ -22,22 +22,40 @@ import (
 	"context"
 
 	"github.com/golang/protobuf/ptypes/empty"
-	"github.com/pkg/errors"
-
 	"github.com/networkservicemesh/api/pkg/api/networkservice"
+	"github.com/pkg/errors"
 
+	"github.com/networkservicemesh/sdk/pkg/networkservice/core/next"
 	"github.com/networkservicemesh/sdk/pkg/tools/logger"
-
 	"github.com/networkservicemesh/sdk/pkg/tools/typeutils"
 )
 
 type traceServer struct {
 	traced networkservice.NetworkServiceServer
 }
 
+type printerServer struct{}
+
+func (t *printerServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) {
+	logRequest(ctx, request)
+	conn, err := next.Server(ctx).Request(ctx, request)
+	logResponse(ctx, conn)
+	return conn, err
+}
+
+func (t *printerServer) Close(ctx context.Context, conn *networkservice.Connection) (*empty.Empty, error) {
+	logRequest(ctx, conn)
+	r, err := next.Server(ctx).Close(ctx, conn)
+	logResponse(ctx, conn)
+	return r, err
+}
+
 // NewNetworkServiceServer - wraps tracing around the supplied traced
 func NewNetworkServiceServer(traced networkservice.NetworkServiceServer) networkservice.NetworkServiceServer {
-	return &traceServer{traced: traced}
+	return next.NewNetworkServiceServer(
+		&traceServer{traced: traced},
+		&printerServer{},
+	)
 }
 
 func (t *traceServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) {
@@ -83,5 +101,6 @@ func (t *traceServer) Close(ctx context.Context, conn *networkservice.Connection
 		logger.Log(ctx).Errorf("%v", err)
 		return nil, err
 	}
+	logResponse(ctx, conn)
 	return rv, err
 }