Fix trace diffs

Signed-off-by: Artem Glazychev <artem.glazychev@xored.com>

pkg/networkservice/core/trace/client.go

@@ -27,21 +27,35 @@ 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)
+	return next.Client(ctx).Close(ctx, conn, opts...)
+}
+
 // 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) {
@@ -50,8 +64,6 @@ func (t *traceClient) Request(ctx context.Context, request *networkservice.Netwo
 	ctx, finish := withLog(ctx, operation)
 	defer finish()
 
-	logRequest(ctx, request)
-
 	// Actually call the next
 	rv, err := t.traced.Request(ctx, request, opts...)
 
@@ -65,7 +77,6 @@ func (t *traceClient) Request(ctx context.Context, request *networkservice.Netwo
 		return nil, err
 	}
 
-	logResponse(ctx, rv)
 	return rv, err
 }
 
@@ -75,7 +86,6 @@ func (t *traceClient) Close(ctx context.Context, conn *networkservice.Connection
 	ctx, finish := withLog(ctx, operation)
 	defer finish()
 
-	logRequest(ctx, conn)
 	rv, err := t.traced.Close(ctx, conn, opts...)
 
 	if err != nil {

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,23 @@
 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/common/null"
+	"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 +102,51 @@ 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 context that contains modifying and non-modifying elements
+	ch := chain.NewNamedNetworkServiceServer(
+		"TestTraceOutput",
+		null.NewServer(),
+		&labelChangerServer{},
+	)
+
+	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)
+
+	expectedOutput :=
+		"level=trace msg=\"[INFO] (1) ⎆ sdk/pkg/networkservice/common/null/nullServer.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] (2)  ⎆ sdk/pkg/networkservice/core/trace_test/labelChangerServer.Request()\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.1)    request-diff={\\\"connection\\\":{\\\"labels\\\":{\\\"+Label\\\":\\\"A\\\"}}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2.2)    response={\\\"id\\\":\\\"conn-1\\\",\\\"context\\\":" +
+			"{\\\"ip_context\\\":{\\\"src_ip_required\\\":true}},\\\"labels\\\":{\\\"Label\\\":\\\"A\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1) ⎆ sdk/pkg/networkservice/common/null/nullServer.Close()\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (1.1)   request={\\\"id\\\":\\\"conn-1\\\",\\\"context\\\":{\\\"ip_context\\\":" +
+			"{\\\"src_ip_required\\\":true}},\\\"labels\\\":{\\\"Label\\\":\\\"A\\\"}}\" name=TestTraceOutput\n" +
+			"level=trace msg=\"[INFO] (2)  ⎆ sdk/pkg/networkservice/core/trace_test/labelChangerServer.Close()\" name=TestTraceOutput\n"
+
+	require.Equal(t, expectedOutput, buff.String())
+}
+
 func newConnection() *networkservice.NetworkServiceRequest {
 	return &networkservice.NetworkServiceRequest{
 		Connection: &networkservice.Connection{
@@ -116,3 +172,16 @@ func newConnection() *networkservice.NetworkServiceRequest {
 		},
 	}
 }
+
+type labelChangerServer struct{}
+
+func (c *labelChangerServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) {
+	request.Connection.Labels = map[string]string{
+		"Label": "A",
+	}
+	return next.Server(ctx).Request(ctx, request)
+}
+
+func (c *labelChangerServer) Close(ctx context.Context, connection *networkservice.Connection) (*empty.Empty, error) {
+	return next.Server(ctx).Close(ctx, connection)
+}

pkg/networkservice/core/trace/server.go

@@ -26,18 +26,35 @@ 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 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)
+	return next.Server(ctx).Close(ctx, conn)
+}
+
 // 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) {
@@ -46,8 +63,6 @@ func (t *traceServer) Request(ctx context.Context, request *networkservice.Netwo
 	ctx, finish := withLog(ctx, operation)
 	defer finish()
 
-	logRequest(ctx, request)
-
 	// Actually call the next
 	rv, err := t.traced.Request(ctx, request)
 
@@ -60,8 +75,6 @@ func (t *traceServer) Request(ctx context.Context, request *networkservice.Netwo
 		logger.Log(ctx).Errorf("%v", err)
 		return nil, err
 	}
-
-	logResponse(ctx, rv)
 	return rv, err
 }
 
@@ -71,7 +84,6 @@ func (t *traceServer) Close(ctx context.Context, conn *networkservice.Connection
 	ctx, finish := withLog(ctx, operation)
 	defer finish()
 
-	logRequest(ctx, conn)
 	rv, err := t.traced.Close(ctx, conn)
 
 	if err != nil {