diff --git a/pkg/networkservice/core/trace/client.go b/pkg/networkservice/core/trace/client.go index 832bef89a5..7649a28dfb 100644 --- a/pkg/networkservice/core/trace/client.go +++ b/pkg/networkservice/core/trace/client.go @@ -27,8 +27,8 @@ 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" ) @@ -36,12 +36,28 @@ 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 index 47ccc1e4d7..335bc29e8c 100644 --- 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,60 @@ 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) + + 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 +180,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 index d8a1aaffae..20efbffb66 100644 --- a/pkg/networkservice/core/trace/server.go +++ b/pkg/networkservice/core/trace/server.go @@ -22,12 +22,11 @@ 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" ) @@ -35,9 +34,28 @@ 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 }