From d61177fc5c768282eaa39ecc690db1dfc21017c2 Mon Sep 17 00:00:00 2001 From: Artem Glazychev Date: Tue, 19 Jan 2021 12:11:34 +0700 Subject: [PATCH] Fix trace diffs Signed-off-by: Artem Glazychev --- pkg/networkservice/core/trace/client.go | 34 ++++-- pkg/networkservice/core/trace/common_test.go | 112 +++++++++++++++++++ pkg/networkservice/core/trace/server.go | 33 ++++-- 3 files changed, 164 insertions(+), 15 deletions(-) diff --git a/pkg/networkservice/core/trace/client.go b/pkg/networkservice/core/trace/client.go index 832bef89a..152c7fe17 100644 --- a/pkg/networkservice/core/trace/client.go +++ b/pkg/networkservice/core/trace/client.go @@ -27,24 +27,26 @@ 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 { +type beginTraceClient struct { traced networkservice.NetworkServiceClient } +type endTraceClient struct{} + // 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( + &beginTraceClient{traced: traced}, + &endTraceClient{}, + ) } -func (t *traceClient) Request(ctx context.Context, request *networkservice.NetworkServiceRequest, opts ...grpc.CallOption) (*networkservice.Connection, error) { +func (t *beginTraceClient) Request(ctx context.Context, request *networkservice.NetworkServiceRequest, opts ...grpc.CallOption) (*networkservice.Connection, error) { // Create a new logger operation := typeutils.GetFuncName(t.traced, "Request") ctx, finish := withLog(ctx, operation) @@ -69,7 +71,7 @@ func (t *traceClient) Request(ctx context.Context, request *networkservice.Netwo return rv, err } -func (t *traceClient) Close(ctx context.Context, conn *networkservice.Connection, opts ...grpc.CallOption) (*empty.Empty, error) { +func (t *beginTraceClient) Close(ctx context.Context, conn *networkservice.Connection, opts ...grpc.CallOption) (*empty.Empty, error) { // Create a new logger operation := typeutils.GetFuncName(t.traced, "Close") ctx, finish := withLog(ctx, operation) @@ -87,5 +89,21 @@ func (t *traceClient) Close(ctx context.Context, conn *networkservice.Connection logger.Log(ctx).Errorf("%v", err) return nil, err } + + logResponse(ctx, conn) return rv, err } + +func (t *endTraceClient) 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 *endTraceClient) 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 +} diff --git a/pkg/networkservice/core/trace/common_test.go b/pkg/networkservice/core/trace/common_test.go index 47ccc1e4d..335bc29e8 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 d8a1aaffa..10e3913cb 100644 --- a/pkg/networkservice/core/trace/server.go +++ b/pkg/networkservice/core/trace/server.go @@ -22,25 +22,29 @@ 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 { +type beginTraceServer struct { traced networkservice.NetworkServiceServer } +type endTraceServer struct{} + // NewNetworkServiceServer - wraps tracing around the supplied traced func NewNetworkServiceServer(traced networkservice.NetworkServiceServer) networkservice.NetworkServiceServer { - return &traceServer{traced: traced} + return next.NewNetworkServiceServer( + &beginTraceServer{traced: traced}, + &endTraceServer{}, + ) } -func (t *traceServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) { +func (t *beginTraceServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) { // Create a new logger operation := typeutils.GetFuncName(t.traced, "Request") ctx, finish := withLog(ctx, operation) @@ -65,7 +69,7 @@ func (t *traceServer) Request(ctx context.Context, request *networkservice.Netwo return rv, err } -func (t *traceServer) Close(ctx context.Context, conn *networkservice.Connection) (*empty.Empty, error) { +func (t *beginTraceServer) Close(ctx context.Context, conn *networkservice.Connection) (*empty.Empty, error) { // Create a new logger operation := typeutils.GetFuncName(t.traced, "Close") ctx, finish := withLog(ctx, operation) @@ -83,5 +87,20 @@ 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 } + +func (t *endTraceServer) 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 *endTraceServer) 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 +}