From 2dd20904274f317a55be678dfc218d506ac950fb Mon Sep 17 00:00:00 2001 From: denis-tingaikin Date: Mon, 9 Dec 2024 06:11:15 +0300 Subject: [PATCH 1/5] optimize trace chain elements Signed-off-by: denis-tingaikin --- pkg/networkservice/core/trace/README.md | 34 +++ pkg/networkservice/core/trace/client.go | 20 +- pkg/networkservice/core/trace/server.go | 19 +- .../core/trace/server_bench_test.go | 173 +++++++++++ pkg/networkservice/core/trace/server_test.go | 243 +++++++++++++++ .../core/trace/testutil/testutil.go | 7 +- .../core/trace/traceconcise/common.go | 12 +- .../core/trace/traceconcise/common_test.go | 124 -------- .../core/trace/traceverbose/README.md | 14 - .../core/trace/traceverbose/common.go | 53 ++-- .../core/trace/traceverbose/common_test.go | 110 +------ .../core/trace/traceverbose/context.go | 6 +- pkg/registry/core/trace/ns_server_test.go | 280 +++++++++++++++++ pkg/registry/core/trace/nse_server_test.go | 282 ++++++++++++++++++ pkg/registry/core/trace/testutil/testutil.go | 47 --- .../core/trace/traceconcise/common.go | 15 +- .../trace/traceconcise/traceconcise_test.go | 141 --------- .../core/trace/traceverbose/common.go | 18 +- .../core/trace/traceverbose/context.go | 13 +- .../core/trace/traceverbose/ns_registry.go | 4 +- .../core/trace/traceverbose/nse_registry.go | 4 +- pkg/tools/dnsutils/trace/common.go | 14 +- pkg/tools/log/defaultlogger.go | 6 +- pkg/tools/log/logruslogger/logruslogger.go | 5 +- pkg/tools/log/spanlogger/spanlogger.go | 5 +- pkg/tools/nanoid/generator.go | 9 + pkg/tools/stringutils/stringutils.go | 27 ++ pkg/tools/typeutils/typeutils.go | 19 +- 28 files changed, 1162 insertions(+), 542 deletions(-) create mode 100644 pkg/networkservice/core/trace/README.md create mode 100644 pkg/networkservice/core/trace/server_bench_test.go create mode 100644 pkg/networkservice/core/trace/server_test.go delete mode 100644 pkg/networkservice/core/trace/traceconcise/common_test.go create mode 100644 pkg/registry/core/trace/ns_server_test.go create mode 100644 pkg/registry/core/trace/nse_server_test.go delete mode 100644 pkg/registry/core/trace/testutil/testutil.go delete mode 100644 pkg/registry/core/trace/traceconcise/traceconcise_test.go create mode 100644 pkg/tools/stringutils/stringutils.go diff --git a/pkg/networkservice/core/trace/README.md b/pkg/networkservice/core/trace/README.md new file mode 100644 index 000000000..dfefaceba --- /dev/null +++ b/pkg/networkservice/core/trace/README.md @@ -0,0 +1,34 @@ +## Logging levels + +- TRACE, DEBUG: these levels print diff, since diff is expensive operation (see diff between Trace and Info tests) it's recommended to use only for debugging. +- INFO: prints short information about requests and connections. +- FATAL, ERROR, WARN: Print only logs from chain elements that are using these levels directly in the source code e.g., `log.FromContext(ctx).Warn("todo")` + +## Benchmarks + +**Release v1.14.1** +``` +Benchmark_ShortRequest_Info-8 3924 344671 ns/op 25641 B/op 178 allocs/op +Benchmark_LongRequest_Info-8 340 3765718 ns/op 273254 B/op 861 allocs/op + +Benchmark_ShortRequest_Trace-8 79 13600986 ns/op 344445 B/op 8475 allocs/op +Benchmark_LongRequest_Trace-8 2 916385562 ns/op 20998324 B/op 694678 allocs/op + +Benchmark_LongRequest_Trace_NoDiff-8 2 565520104 ns/op 12236116 B/op 585667 allocs/op +Benchmark_LongRequest_Diff_Warn-8 340 3765718 ns/op 273254 B/op 861 allocs/op + +``` + + +**Release v1.14.2** +``` +Benchmark_ShortRequest_Info-8 4090 350181 ns/op 24246 B/op 177 allocs/op +Benchmark_LongRequest_Info-8 373 3064039 ns/op 253359 B/op 857 allocs/op + +Benchmark_ShortRequest_Trace-8 543 2599280 ns/op 237262 B/op 1825 allocs/op +Benchmark_LongRequest_Trace-8 9 131145361 ns/op 22433480 B/op 20749 allocs/op + +Benchmark_LongRequest_Trace_NoDiff-8 18 72167456 ns/op 10900859 B/op 13685 allocs/op + +Benchmark_LongRequest_Diff_Warn-8 31128 36019 ns/op 9600 B/op 200 allocs/op +``` diff --git a/pkg/networkservice/core/trace/client.go b/pkg/networkservice/core/trace/client.go index 3a5a6446c..5c1cfadaf 100644 --- a/pkg/networkservice/core/trace/client.go +++ b/pkg/networkservice/core/trace/client.go @@ -32,27 +32,35 @@ import ( ) type traceClient struct { - verbose networkservice.NetworkServiceClient - concise networkservice.NetworkServiceClient + verbose networkservice.NetworkServiceClient + concise networkservice.NetworkServiceClient + original networkservice.NetworkServiceClient } // NewNetworkServiceClient - wraps tracing around the supplied networkservice.NetworkServiceClient func NewNetworkServiceClient(traced networkservice.NetworkServiceClient) networkservice.NetworkServiceClient { return &traceClient{ - verbose: traceverbose.NewNetworkServiceClient(traced), - concise: traceconcise.NewNetworkServiceClient(traced), + verbose: traceverbose.NewNetworkServiceClient(traced), + concise: traceconcise.NewNetworkServiceClient(traced), + original: traced, } } func (t *traceClient) Request(ctx context.Context, request *networkservice.NetworkServiceRequest, opts ...grpc.CallOption) (*networkservice.Connection, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() <= logrus.WarnLevel { + return t.original.Request(ctx, request) + } + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Request(ctx, request, opts...) } return t.concise.Request(ctx, request, opts...) } func (t *traceClient) Close(ctx context.Context, conn *networkservice.Connection, opts ...grpc.CallOption) (*empty.Empty, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() <= logrus.WarnLevel { + return t.original.Close(ctx, conn) + } + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Close(ctx, conn, opts...) } return t.concise.Close(ctx, conn, opts...) diff --git a/pkg/networkservice/core/trace/server.go b/pkg/networkservice/core/trace/server.go index 5c7fe0e9c..b861c754b 100644 --- a/pkg/networkservice/core/trace/server.go +++ b/pkg/networkservice/core/trace/server.go @@ -30,27 +30,34 @@ import ( ) type traceServer struct { - verbose networkservice.NetworkServiceServer - concise networkservice.NetworkServiceServer + verbose, concise, original networkservice.NetworkServiceServer } // NewNetworkServiceServer - wraps tracing around the supplied traced func NewNetworkServiceServer(traced networkservice.NetworkServiceServer) networkservice.NetworkServiceServer { return &traceServer{ - verbose: traceverbose.NewNetworkServiceServer(traced), - concise: traceconcise.NewNetworkServiceServer(traced), + verbose: traceverbose.NewNetworkServiceServer(traced), + concise: traceconcise.NewNetworkServiceServer(traced), + original: traced, } } func (t *traceServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() <= logrus.WarnLevel { + return t.original.Request(ctx, request) + } + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Request(ctx, request) } + return t.concise.Request(ctx, request) } func (t *traceServer) Close(ctx context.Context, conn *networkservice.Connection) (*empty.Empty, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() <= logrus.WarnLevel { + return t.original.Close(ctx, conn) + } + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Close(ctx, conn) } return t.concise.Close(ctx, conn) diff --git a/pkg/networkservice/core/trace/server_bench_test.go b/pkg/networkservice/core/trace/server_bench_test.go new file mode 100644 index 000000000..5548feed9 --- /dev/null +++ b/pkg/networkservice/core/trace/server_bench_test.go @@ -0,0 +1,173 @@ +// Copyright (c) 2024 Cisco Systems, Inc. +// +// SPDX-License-Identifier: Apache-2.0 +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at: +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package trace_test + +import ( + "context" + "fmt" + "io" + "testing" + + "github.com/networkservicemesh/api/pkg/api/networkservice" + + "github.com/networkservicemesh/sdk/pkg/networkservice/common/null" + "github.com/networkservicemesh/sdk/pkg/networkservice/core/chain" + "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil" + "github.com/networkservicemesh/sdk/pkg/networkservice/utils/checks/checkrequest" + "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/nanoid" + + "github.com/sirupsen/logrus" +) + +func newTestRequest(size int) *networkservice.NetworkServiceRequest { + res := testutil.NewConnection() + + res.GetConnection().Path = &networkservice.Path{} + res.GetConnection().Labels = make(map[string]string) + + for i := 0; i < size; i++ { + res.GetConnection().GetPath().PathSegments = append(res.GetConnection().GetPath().PathSegments, + &networkservice.PathSegment{ + Name: nanoid.MustGenerateString(15), + Token: nanoid.MustGenerateString(25), + Id: nanoid.MustGenerateString(20), + }) + } + + res.GetConnection().Id = res.GetConnection().GetPath().GetPathSegments()[0].Id + + return res +} + +func newTestServerChain(size int) networkservice.NetworkServiceServer { + var servers []networkservice.NetworkServiceServer + + for i := 0; i < size; i++ { + id := i + servers = append(servers, checkrequest.NewServer(nil, func(_ *testing.T, nsr *networkservice.NetworkServiceRequest) { + nsr.GetConnection().GetLabels()["common-label"] = fmt.Sprint(id) + })) + } + + return chain.NewNetworkServiceServer(servers...) +} + +func newTestStaticServerChain(size int) networkservice.NetworkServiceServer { + var servers []networkservice.NetworkServiceServer + + for i := 0; i < size; i++ { + servers = append(servers, null.NewServer()) + } + + return chain.NewNetworkServiceServer(servers...) +} + +func Benchmark_ShortRequest_Info(b *testing.B) { + var s = newTestServerChain(10) + var request = newTestRequest(5) + var ctx = context.Background() + + logrus.SetLevel(logrus.InfoLevel) + logrus.SetOutput(io.Discard) + log.EnableTracing(true) + + b.ResetTimer() + + for range b.N { + _, _ = s.Request(ctx, request) + } +} + +func Benchmark_LongRequest_Info(b *testing.B) { + var s = newTestServerChain(100) + var request = newTestRequest(100) + var ctx = context.Background() + + logrus.SetLevel(logrus.InfoLevel) + logrus.SetOutput(io.Discard) + log.EnableTracing(true) + + b.ResetTimer() + + for range b.N { + _, _ = s.Request(ctx, request) + } +} + +func Benchmark_ShortRequest_Trace(b *testing.B) { + var s = newTestServerChain(10) + var request = newTestRequest(5) + var ctx = context.Background() + + logrus.SetLevel(logrus.TraceLevel) + logrus.SetOutput(io.Discard) + log.EnableTracing(true) + + b.ResetTimer() + + for range b.N { + _, _ = s.Request(ctx, request) + } +} +func Benchmark_LongRequest_Trace(b *testing.B) { + var s = newTestServerChain(100) + var request = newTestRequest(100) + var ctx = context.Background() + + logrus.SetLevel(logrus.TraceLevel) + logrus.SetOutput(io.Discard) + log.EnableTracing(true) + + b.ResetTimer() + + for range b.N { + _, _ = s.Request(ctx, request) + } +} + +func Benchmark_LongRequest_Trace_NoDiff(b *testing.B) { + var s = newTestStaticServerChain(100) + var request = newTestRequest(100) + var ctx = context.Background() + + logrus.SetLevel(logrus.TraceLevel) + logrus.SetOutput(io.Discard) + log.EnableTracing(true) + + b.ResetTimer() + + for range b.N { + _, _ = s.Request(ctx, request) + } +} + +func Benchmark_LongRequest_Diff_Warn(b *testing.B) { + var s = newTestStaticServerChain(100) + var request = newTestRequest(100) + var ctx = context.Background() + + logrus.SetLevel(logrus.WarnLevel) + logrus.SetOutput(io.Discard) + log.EnableTracing(true) + + b.ResetTimer() + + for range b.N { + _, _ = s.Request(ctx, request) + } +} diff --git a/pkg/networkservice/core/trace/server_test.go b/pkg/networkservice/core/trace/server_test.go new file mode 100644 index 000000000..5ba8d1a48 --- /dev/null +++ b/pkg/networkservice/core/trace/server_test.go @@ -0,0 +1,243 @@ +// Copyright (c) 2020-2024 Cisco Systems, Inc. +// +// Copyright (c) 2021-2024 Doc.ai and/or its affiliates. +// +// Copyright (c) 2024 Nordix Foundation. +// +// SPDX-License-Identifier: Apache-2.0 +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at: +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Package trace_test has few tests for tracing diffs +package trace_test + +import ( + "bytes" + "context" + + "testing" + + "github.com/sirupsen/logrus" + + "github.com/stretchr/testify/require" + + "github.com/networkservicemesh/sdk/pkg/networkservice/core/chain" + "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil" + "github.com/networkservicemesh/sdk/pkg/tools/log" +) + +func TestTraceOutput_FATAL(t *testing.T) { + // Configure logging + // Set output to buffer + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetLevel(logrus.FatalLevel) + log.EnableTracing(true) + + // Create a chain with modifying elements + ch := chain.NewNetworkServiceServer( + &testutil.LabelChangerFirstServer{}, + &testutil.LabelChangerSecondServer{}, + ) + + request := testutil.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 := `` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestTraceOutput(t *testing.T) { + // Configure logging + // Set output to buffer + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + logrus.SetLevel(logrus.TraceLevel) + log.EnableTracing(true) + + // Create a chain with modifying elements + ch := chain.NewNetworkServiceServer( + &testutil.LabelChangerFirstServer{}, + &testutil.LabelChangerSecondServer{}, + ) + + request := testutil.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 := ` [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Request() + [INFO] [id:conn-1] [type:networkService] (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"}}]} + [INFO] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Request() + [INFO] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [INFO] [id:conn-1] [type:networkService] (2.2) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} + [INFO] [id:conn-1] [type:networkService] (2.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"C"}} + [INFO] [id:conn-1] [type:networkService] (1.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} + [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Close() + [INFO] [id:conn-1] [type:networkService] (1.1) close={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} + [INFO] [id:conn-1] [type:networkService] (1.2) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"W"}} + [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Close() + [INFO] [id:conn-1] [type:networkService] (2.1) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} + [INFO] [id:conn-1] [type:networkService] (2.2) close-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} + [INFO] [id:conn-1] [type:networkService] (2.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Y"}} + [INFO] [id:conn-1] [type:networkService] (1.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Z"}} +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestErrorOutput(t *testing.T) { + // Configure logging + // Set output to buffer + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + logrus.SetLevel(logrus.TraceLevel) + log.EnableTracing(true) + + // Create a chain with modifying elements + ch := chain.NewNetworkServiceServer( + &testutil.LabelChangerFirstServer{}, + &testutil.LabelChangerSecondServer{}, + &testutil.ErrorServer{}, + ) + + request := testutil.NewConnection() + + conn, err := ch.Request(context.Background(), request) + require.Error(t, err) + require.Nil(t, conn) + + expectedOutput := ` [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Request() + [INFO] [id:conn-1] [type:networkService] (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"}}]} + [INFO] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Request() + [INFO] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (3) ⎆ testutil/ErrorServer.Request() + [INFO] [id:conn-1] [type:networkService] (3.1) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} + [ERRO] [id:conn-1] [type:networkService] (3.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [INFO] [id:conn-1] [type:networkService] (2.2) request-response-diff=null + [ERRO] [id:conn-1] [type:networkService] (2.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [ERRO] [id:conn-1] [type:networkService] (1.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestOutput_Info(t *testing.T) { + // Configure logging + // Set output to buffer + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.InfoLevel) + + // Create a chain with modifying elements + ch := chain.NewNetworkServiceServer( + &testutil.LabelChangerFirstServer{}, + &testutil.LabelChangerSecondServer{}, + ) + + request := testutil.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 := ` [INFO] [id:conn-1] [type:networkService] server-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"}}]} + [INFO] [id:conn-1] [type:networkService] server-request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} + [INFO] [id:conn-1] [type:networkService] server-close={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} + [INFO] [id:conn-1] [type:networkService] server-close-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} +` + + result := testutil.TrimLogTime(&buff) + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestErrorOutput_Info(t *testing.T) { + // Configure logging + // Set output to buffer + var buff bytes.Buffer + logrus.SetOutput(&buff) + + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.InfoLevel) + + // Create a chain with modifying elements + ch := chain.NewNetworkServiceServer( + &testutil.LabelChangerFirstServer{}, + &testutil.LabelChangerSecondServer{}, + &testutil.ErrorServer{}, + ) + + request := testutil.NewConnection() + + conn, err := ch.Request(context.Background(), request) + require.Error(t, err) + require.Nil(t, conn) + + expectedOutput := `[INFO][id:conn-1][type:networkService]server-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"}}]} +[INFO][id:conn-1][type:networkService]server-request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} +[ERRO][id:conn-1][type:networkService]Errorreturnedfromtestutil/ErrorServer.Request:Errorreturnedfromapi/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} diff --git a/pkg/networkservice/core/trace/testutil/testutil.go b/pkg/networkservice/core/trace/testutil/testutil.go index 9ff72ac02..91cec59c3 100644 --- a/pkg/networkservice/core/trace/testutil/testutil.go +++ b/pkg/networkservice/core/trace/testutil/testutil.go @@ -1,4 +1,4 @@ -// Copyright (c) 2023 Doc.ai and/or its affiliates. +// Copyright (c) 2023-2024 Doc.ai and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -160,6 +160,11 @@ func (c *ErrorServer) Close(ctx context.Context, connection *networkservice.Conn return next.Server(ctx).Close(ctx, connection) } +// Normalize normalizes test input of logs to make it usable for equals operations +func Normalize(in string) string { + return strings.ReplaceAll(in, " ", "") +} + // TrimLogTime - to format logs func TrimLogTime(buff fmt.Stringer) string { // Logger created by the trace chain element uses custom formatter, which prints date and time info in each line diff --git a/pkg/networkservice/core/trace/traceconcise/common.go b/pkg/networkservice/core/trace/traceconcise/common.go index 0134f470e..6d9baa438 100644 --- a/pkg/networkservice/core/trace/traceconcise/common.go +++ b/pkg/networkservice/core/trace/traceconcise/common.go @@ -1,4 +1,4 @@ -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -25,6 +25,7 @@ import ( "github.com/pkg/errors" "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/stringutils" ) const ( @@ -45,21 +46,16 @@ func logResponse(ctx context.Context, response any, prefixes ...string) { } func logError(ctx context.Context, err error, operation string) error { - if trace(ctx) { - log.FromContext(ctx).Errorf("%v", errors.Wrapf(err, "Error returned from %s", operation)) - } + log.FromContext(ctx).Errorf("%v", errors.Wrapf(err, "Error returned from %s", operation)) return err } func logObject(ctx context.Context, k, v interface{}) { - if !trace(ctx) { - return - } s := log.FromContext(ctx) msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/networkservice/core/trace/traceconcise/common_test.go b/pkg/networkservice/core/trace/traceconcise/common_test.go deleted file mode 100644 index 8007d75c1..000000000 --- a/pkg/networkservice/core/trace/traceconcise/common_test.go +++ /dev/null @@ -1,124 +0,0 @@ -// Copyright (c) 2023-2024 Cisco and/or its affiliates. -// -// Copyright (c) 2024 Nordix Foundation. -// -// SPDX-License-Identifier: Apache-2.0 -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at: -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -// Package traceconcise_test has few tests for logs in concise mode -package traceconcise_test - -import ( - "bytes" - "context" - "testing" - - "github.com/sirupsen/logrus" - - "github.com/stretchr/testify/require" - - "github.com/networkservicemesh/sdk/pkg/networkservice/core/chain" - "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil" - "github.com/networkservicemesh/sdk/pkg/tools/log" -) - -func TestOutput(t *testing.T) { - // Configure logging - // Set output to buffer - var buff bytes.Buffer - logrus.SetOutput(&buff) - logrus.SetFormatter(&logrus.TextFormatter{ - DisableTimestamp: true, - }) - log.EnableTracing(true) - logrus.SetLevel(logrus.InfoLevel) - - // Create a chain with modifying elements - ch := chain.NewNetworkServiceServer( - &testutil.LabelChangerFirstServer{}, - &testutil.LabelChangerSecondServer{}, - ) - - request := testutil.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 := - " [INFO] [id:conn-1] [type:networkService] server-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\"}}]}" + - "\n [INFO] [id:conn-1] [type:networkService] server-request-response={\"id\":\"conn-1\",\"context\":" + - "{\"ip_context\":{\"src_ip_required\":true}},\"labels\":{\"Label\":\"B\"}}" + - "\n [INFO] [id:conn-1] [type:networkService] server-close={\"id\":\"conn-1\",\"context\":{\"ip_context\":" + - "{\"src_ip_required\":true}},\"labels\":{\"Label\":\"D\"}}" + - "\n [INFO] [id:conn-1] [type:networkService] server-close-response={\"id\":\"conn-1\",\"context\":" + - "{\"ip_context\":{\"src_ip_required\":true}},\"labels\":{\"Label\":\"X\"}}\n" - - result := testutil.TrimLogTime(&buff) - require.Equal(t, expectedOutput, result) -} - -func TestErrorOutput(t *testing.T) { - // Configure logging - // Set output to buffer - var buff bytes.Buffer - logrus.SetOutput(&buff) - - logrus.SetFormatter(&logrus.TextFormatter{ - DisableTimestamp: true, - }) - log.EnableTracing(true) - logrus.SetLevel(logrus.InfoLevel) - - // Create a chain with modifying elements - ch := chain.NewNetworkServiceServer( - &testutil.LabelChangerFirstServer{}, - &testutil.LabelChangerSecondServer{}, - &testutil.ErrorServer{}, - ) - - request := testutil.NewConnection() - - conn, err := ch.Request(context.Background(), request) - require.Error(t, err) - require.Nil(t, conn) - - expectedOutput := - " [INFO] [id:conn-1] [type:networkService] server-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\"}}]}\n" + - " [INFO] [id:conn-1] [type:networkService] server-request-response={\"id\":\"conn-1\",\"context\":" + - "{\"ip_context\":{\"src_ip_required\":true}},\"labels\":{\"Label\":\"B\"}}\n" + - " [ERRO] [id:conn-1] [type:networkService] Error returned from sdk/pkg/networkservice/core/trace/testutil/ErrorServer.Request:" + - " Error returned from api/pkg/api/networkservice/networkServiceClient.Close;" + - "\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close;" + - "\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85;" + - "\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;" + - "\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;" + - "\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;" + - "\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;" + - "\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close;" + - "\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106;" + - "\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;" + - "\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\t\n" - - result := testutil.TrimLogTime(&buff) - require.Equal(t, expectedOutput, result) -} diff --git a/pkg/networkservice/core/trace/traceverbose/README.md b/pkg/networkservice/core/trace/traceverbose/README.md index a708622be..f17583782 100644 --- a/pkg/networkservice/core/trace/traceverbose/README.md +++ b/pkg/networkservice/core/trace/traceverbose/README.md @@ -7,17 +7,3 @@ It creates a new span for every Request() or Close(). Instead of logging full request, trace element saves it in context, so that the trace element that wrapped the next client or server, compares the request in the context with its own, and if they do not match, calculates the diff and logs only it. The same with response. - -## Benchmarks -If we assume that -* logRequest() - logs full `proto.Message` -* logRequestIfDiffers() - Compares previous and current `proto.Message`. Logs the current message only if they differ. -* logRequestDiff() - Compares previous and current `proto.Message`. If they differ calculates the diff of them and logs only it. - -then we get the following results: - -| Type | Ops | ns/op | -| ------------- |:-----:| -----:| -| logRequest() | 32778 | 36565 | -| logRequestIfDiffers()| 33396 | 41140 | -| logRequestDiff() | 34741 | 42793 | diff --git a/pkg/networkservice/core/trace/traceverbose/common.go b/pkg/networkservice/core/trace/traceverbose/common.go index cd5fc66e3..941206c0f 100644 --- a/pkg/networkservice/core/trace/traceverbose/common.go +++ b/pkg/networkservice/core/trace/traceverbose/common.go @@ -1,7 +1,7 @@ -// Copyright (c) 2020-2023 Cisco Systems, Inc. -// // Copyright (c) 2021-2023 Doc.ai and/or its affiliates. // +// Copyright (c) 2020-2024 Cisco Systems, Inc. +// // SPDX-License-Identifier: Apache-2.0 // // Licensed under the Apache License, Version 2.0 (the "License"); @@ -26,11 +26,13 @@ import ( "strconv" "strings" + "github.com/OneOfOne/xxhash" "github.com/pkg/errors" "google.golang.org/protobuf/proto" "google.golang.org/protobuf/reflect/protoreflect" "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/stringutils" ) const ( @@ -39,39 +41,27 @@ const ( ) func logRequest(ctx context.Context, request proto.Message, prefixes ...string) { - msg := strings.Join(prefixes, "-") - diffMsg := strings.Join(append(prefixes, "diff"), "-") - - connInfo, ok := trace(ctx) - if ok && !proto.Equal(connInfo.Request, request) { - if connInfo.Request != nil && connInfo.Request.ProtoReflect().Descriptor().FullName() == request.ProtoReflect().Descriptor().FullName() { - requestDiff, hadChanges := Diff(connInfo.Request.ProtoReflect(), request.ProtoReflect()) - if hadChanges { - logObjectTrace(ctx, diffMsg, requestDiff) - } + connInfo, _ := trace(ctx) + + if v := hashCode(request); connInfo.Request != v { + if connInfo.Request != 0 { + logObjectTrace(ctx, strings.Join(append(prefixes, "diff"), "-"), request) } else { - logObjectTrace(ctx, msg, request) + logObjectTrace(ctx, strings.Join(prefixes, "-"), request) } - connInfo.Request = proto.Clone(request) + connInfo.Request = v } } func logResponse(ctx context.Context, response proto.Message, prefixes ...string) { - msg := strings.Join(append(prefixes, "response"), "-") - diffMsg := strings.Join(append(prefixes, "response", "diff"), "-") - - connInfo, ok := trace(ctx) - if ok && !proto.Equal(connInfo.Response, response) { - if connInfo.Response != nil { - responseDiff, changed := Diff(connInfo.Response.ProtoReflect(), response.ProtoReflect()) - if changed { - logObjectTrace(ctx, diffMsg, responseDiff) - } + connInfo, _ := trace(ctx) + if v := hashCode(response); connInfo.Response != v { + if connInfo.Response != 0 { + logObjectTrace(ctx, strings.Join(append(prefixes, "response", "diff"), "-"), response) } else { - logObjectTrace(ctx, msg, response) + logObjectTrace(ctx, strings.Join(append(prefixes, "response"), "-"), response) } - connInfo.Response = proto.Clone(response) - return + connInfo.Response = v } } @@ -216,14 +206,19 @@ func logError(ctx context.Context, err error, operation string) error { return err } +func hashCode(msg proto.Message) uint64 { + bytes, _ := proto.MarshalOptions{Deterministic: true, AllowPartial: true, UseCachedSize: true}.Marshal(msg) + return xxhash.Checksum64(bytes) +} + func logObjectTrace(ctx context.Context, k, v interface{}) { s := log.FromContext(ctx) msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } - s.Tracef("%v=%s", k, msg) + s.Infof("%v=%s", k, msg) } diff --git a/pkg/networkservice/core/trace/traceverbose/common_test.go b/pkg/networkservice/core/trace/traceverbose/common_test.go index f31404ea0..5948bb98e 100644 --- a/pkg/networkservice/core/trace/traceverbose/common_test.go +++ b/pkg/networkservice/core/trace/traceverbose/common_test.go @@ -18,25 +18,18 @@ // See the License for the specific language governing permissions and // limitations under the License. -// Package trace_test has few tests for tracing diffs package traceverbose_test import ( - "bytes" - "context" "encoding/json" - "testing" - "github.com/sirupsen/logrus" - "github.com/networkservicemesh/api/pkg/api/networkservice" - "github.com/stretchr/testify/require" - "github.com/networkservicemesh/sdk/pkg/networkservice/core/chain" "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil" "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/traceverbose" - "github.com/networkservicemesh/sdk/pkg/tools/log" + + "github.com/stretchr/testify/require" ) func TestDiffMechanism(t *testing.T) { @@ -102,102 +95,3 @@ func TestDiffPathAdd(t *testing.T) { require.Equal(t, `{"connection":{"path":{"path_segments":{"+1":{"id":"id2","token":"t2"}}}}}`, string(jsonOut)) 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, - }) - logrus.SetLevel(logrus.TraceLevel) - log.EnableTracing(true) - - // Create a chain with modifying elements - ch := chain.NewNetworkServiceServer( - &testutil.LabelChangerFirstServer{}, - &testutil.LabelChangerSecondServer{}, - ) - - request := testutil.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 := - " [TRAC] [id:conn-1] [type:networkService] (1) ⎆ sdk/pkg/networkservice/core/trace/testutil/LabelChangerFirstServer.Request()\n" + - " [TRAC] [id:conn-1] [type:networkService] (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\"}}]}\n" + - " [TRAC] [id:conn-1] [type:networkService] (1.2) request-diff={\"connection\":{\"labels\":{\"+Label\":\"A\"}}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (2) ⎆ sdk/pkg/networkservice/core/trace/testutil/LabelChangerSecondServer.Request()\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.1) request-diff={\"connection\":{\"labels\":{\"Label\":\"B\"}}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.2) request-response={\"id\":\"conn-1\",\"context\":{\"ip_context\":{\"src_ip_required\":true}}," + - "\"labels\":{\"Label\":\"B\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.3) request-response-diff={\"labels\":{\"Label\":\"C\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (1.3) request-response-diff={\"labels\":{\"Label\":\"D\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (1) ⎆ sdk/pkg/networkservice/core/trace/testutil/LabelChangerFirstServer.Close()\n" + - " [TRAC] [id:conn-1] [type:networkService] (1.1) close={\"id\":\"conn-1\",\"context\":{\"ip_context\":{\"src_ip_required\":true}}," + - "\"labels\":{\"Label\":\"D\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (1.2) close-diff={\"labels\":{\"Label\":\"W\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (2) ⎆ sdk/pkg/networkservice/core/trace/testutil/LabelChangerSecondServer.Close()\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.1) close-diff={\"labels\":{\"Label\":\"X\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.2) close-response={\"id\":\"conn-1\",\"context\":{\"ip_context\":{\"src_ip_required\"" + - ":true}},\"labels\":{\"Label\":\"X\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.3) close-response-diff={\"labels\":{\"Label\":\"Y\"}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (1.3) close-response-diff={\"labels\":{\"Label\":\"Z\"}}\n" - - result := testutil.TrimLogTime(&buff) - require.Equal(t, expectedOutput, result) -} - -func TestErrorOutput(t *testing.T) { - // Configure logging - // Set output to buffer - var buff bytes.Buffer - logrus.SetOutput(&buff) - logrus.SetFormatter(&logrus.TextFormatter{ - DisableTimestamp: true, - }) - logrus.SetLevel(logrus.TraceLevel) - log.EnableTracing(true) - - // Create a chain with modifying elements - ch := chain.NewNetworkServiceServer( - &testutil.LabelChangerFirstServer{}, - &testutil.LabelChangerSecondServer{}, - &testutil.ErrorServer{}, - ) - - request := testutil.NewConnection() - - conn, err := ch.Request(context.Background(), request) - require.Error(t, err) - require.Nil(t, conn) - - expectedOutput := - " [TRAC] [id:conn-1] [type:networkService] (1) ⎆ sdk/pkg/networkservice/core/trace/testutil/LabelChangerFirstServer.Request()\n" + - " [TRAC] [id:conn-1] [type:networkService] (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\"}}]}\n" + - " [TRAC] [id:conn-1] [type:networkService] (1.2) request-diff={\"connection\":{\"labels\":{\"+Label\":\"A\"}}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (2) ⎆ sdk/pkg/networkservice/core/trace/testutil/LabelChangerSecondServer.Request()\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.1) request-diff={\"connection\":{\"labels\":{\"Label\":\"B\"}}}\n" + - " [TRAC] [id:conn-1] [type:networkService] (3) ⎆ sdk/pkg/networkservice/core/trace/testutil/ErrorServer.Request()\n" + - " [TRAC] [id:conn-1] [type:networkService] (3.1) request-response={\"id\":\"conn-1\",\"context\":{\"ip_context\":{\"src_ip_required\":true}},\"labels\":{\"Label\":\"B\"}}\n" + - " [ERRO] [id:conn-1] [type:networkService] (3.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\t\n" + - " [TRAC] [id:conn-1] [type:networkService] (2.2) request-response-diff={\"context\":{\"ip_context\":{\"src_ip_required\":false}},\"id\":\"\",\"labels\":{\"-Label\":\"B\"}}\n" + - " [ERRO] [id:conn-1] [type:networkService] (2.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\t\n" + - " [ERRO] [id:conn-1] [type:networkService] (1.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106;\tgithub.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close;\t\t/root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65;\t\n" - - result := testutil.TrimLogTime(&buff) - require.Equal(t, expectedOutput, result) -} diff --git a/pkg/networkservice/core/trace/traceverbose/context.go b/pkg/networkservice/core/trace/traceverbose/context.go index 148f3a82d..aa1cb8791 100644 --- a/pkg/networkservice/core/trace/traceverbose/context.go +++ b/pkg/networkservice/core/trace/traceverbose/context.go @@ -22,8 +22,6 @@ package traceverbose import ( "context" - "google.golang.org/protobuf/proto" - "github.com/networkservicemesh/sdk/pkg/tools/grpcutils" "github.com/networkservicemesh/sdk/pkg/tools/log" "github.com/networkservicemesh/sdk/pkg/tools/log/logruslogger" @@ -40,9 +38,9 @@ const ( // ConnectionInfo - struct, containing string representations of request and response, used for tracing. type traceInfo struct { // Request is last request of NetworkService{Client, Server} - Request proto.Message + Request uint64 // Response is last response of NetworkService{Client, Server} - Response proto.Message + Response uint64 } // withLog - provides corresponding logger in context diff --git a/pkg/registry/core/trace/ns_server_test.go b/pkg/registry/core/trace/ns_server_test.go new file mode 100644 index 000000000..63bf41c9a --- /dev/null +++ b/pkg/registry/core/trace/ns_server_test.go @@ -0,0 +1,280 @@ +// Copyright (c) 2023-2024 Cisco and/or its affiliates. +// +// Copyright (c) 2024 Nordix Foundation. +// +// SPDX-License-Identifier: Apache-2.0 +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at: +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Package traceconcise_test has few tests for logs in concise mode +package trace_test + +import ( + "bytes" + "context" + "testing" + + "github.com/networkservicemesh/api/pkg/api/registry" + "github.com/pkg/errors" + "github.com/sirupsen/logrus" + "go.uber.org/goleak" + + "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil" + "github.com/networkservicemesh/sdk/pkg/registry/common/memory" + "github.com/networkservicemesh/sdk/pkg/registry/common/null" + "github.com/networkservicemesh/sdk/pkg/registry/core/chain" + "github.com/networkservicemesh/sdk/pkg/registry/core/streamchannel" + "github.com/networkservicemesh/sdk/pkg/registry/utils/inject/injecterror" + "github.com/networkservicemesh/sdk/pkg/tools/log" + + "github.com/stretchr/testify/require" +) + +func TestOutput_RegistryNetworkService(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.InfoLevel) + + s := chain.NewNetworkServiceRegistryServer( + memory.NewNetworkServiceRegistryServer(), + null.NewNetworkServiceRegistryServer(), + ) + + ns, err := s.Register(context.Background(), ®istry.NetworkService{ + Name: "a", + }) + require.NoError(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceResponse, 1) + defer close(ch) + _ = s.Find(®istry.NetworkServiceQuery{ + NetworkService: ®istry.NetworkService{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceFindServer(ctx, ch)) + + _, err = s.Unregister(context.Background(), ns) + require.NoError(t, err) + + expectedOutput := ` [INFO] [type:registry] ns-server-register=name:"a" + [INFO] [type:registry] ns-server-register-response=name:"a" + [INFO] [type:registry] ns-server-find=network_service:{name:"a"} + [INFO] [type:registry] ns-server-send=network_service:{name:"a"} + [INFO] [type:registry] ns-server-send-response=network_service:{name:"a"} + [INFO] [type:registry] ns-server-find-response=network_service:{name:"a"} + [INFO] [type:registry] ns-server-unregister=name:"a" + [INFO] [type:registry] ns-server-unregister-response=name:"a" +` + + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestOutput_Trace_RegistryNetworkService(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.TraceLevel) + + s := chain.NewNetworkServiceRegistryServer( + memory.NewNetworkServiceRegistryServer(), + null.NewNetworkServiceRegistryServer(), + ) + + ns, err := s.Register(context.Background(), ®istry.NetworkService{ + Name: "a", + }) + require.NoError(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceResponse, 1) + defer close(ch) + _ = s.Find(®istry.NetworkServiceQuery{ + NetworkService: ®istry.NetworkService{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceFindServer(ctx, ch)) + + _, err = s.Unregister(context.Background(), ns) + require.NoError(t, err) + + expectedOutput := ` [TRAC] [type:registry] (1) ⎆ memory/memoryNSServer.Register() + [TRAC] [type:registry] (1.1) register=name:"a" + [TRAC] [type:registry] (2) ⎆ null/nullNSServer.Register() + [TRAC] [type:registry] (2.1) register=name:"a" + [TRAC] [type:registry] (2.2) register-response=name:"a" + [TRAC] [type:registry] (1.2) register-response=name:"a" + [TRAC] [type:registry] (1) ⎆ memory/memoryNSServer.Find() + [TRAC] [type:registry] (1.1) find=network_service:{name:"a"} + [TRAC] [type:registry] (2) ⎆ memory/memoryNSServer.Send() + [TRAC] [type:registry] (2.1) network service=name:"a" + [TRAC] [type:registry] (2) ⎆ null/nullNSServer.Find() + [TRAC] [type:registry] (2.1) find=network_service:{name:"a"} + [TRAC] [type:registry] (1) ⎆ memory/memoryNSServer.Unregister() + [TRAC] [type:registry] (1.1) unregister=name:"a" + [TRAC] [type:registry] (2) ⎆ null/nullNSServer.Unregister() + [TRAC] [type:registry] (2.1) unregister=name:"a" + [TRAC] [type:registry] (2.2) unregister-response=name:"a" + [TRAC] [type:registry] (1.2) unregister-response=name:"a" +` + + result := testutil.TrimLogTime(&buff) + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestErrorOutput_RegistryNetworkService(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.InfoLevel) + + s := chain.NewNetworkServiceRegistryServer( + memory.NewNetworkServiceRegistryServer(), + injecterror.NewNetworkServiceRegistryServer( + injecterror.WithError(errors.New("test error")), + injecterror.WithRegisterErrorTimes(0), + injecterror.WithFindErrorTimes(0), + injecterror.WithUnregisterErrorTimes(0), + ), + ) + + ns, err := s.Register(context.Background(), ®istry.NetworkService{ + Name: "a", + }) + require.Error(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceResponse, 1) + defer close(ch) + err = s.Find(®istry.NetworkServiceQuery{ + NetworkService: ®istry.NetworkService{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceFindServer(ctx, ch)) + require.Error(t, err) + + _, err = s.Unregister(context.Background(), ns) + require.Error(t, err) + + expectedOutput := ` [INFO] [type:registry] ns-server-register=name:"a" + [ERRO] [type:registry] Error returned from injecterror/injectErrorNSServer.Register: test error + [INFO] [type:registry] ns-server-find=network_service:{name:"a"} + [ERRO] [type:registry] Error returned from injecterror/injectErrorNSServer.Find: test error + [INFO] [type:registry] ns-server-unregister= + [ERRO] [type:registry] Error returned from injecterror/injectErrorNSServer.Unregister: test error +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestErrorOutput_Trace_RegistryNetworkService(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.TraceLevel) + + s := chain.NewNetworkServiceRegistryServer( + memory.NewNetworkServiceRegistryServer(), + injecterror.NewNetworkServiceRegistryServer( + injecterror.WithError(&testutil.CustomError{}), + injecterror.WithRegisterErrorTimes(0), + injecterror.WithFindErrorTimes(0), + injecterror.WithUnregisterErrorTimes(0), + ), + ) + + ns, err := s.Register(context.Background(), ®istry.NetworkService{ + Name: "a", + }) + require.Error(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceResponse, 1) + defer close(ch) + err = s.Find(®istry.NetworkServiceQuery{ + NetworkService: ®istry.NetworkService{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceFindServer(ctx, ch)) + require.Error(t, err) + + _, err = s.Unregister(context.Background(), ns) + require.Error(t, err) + + expectedOutput := ` [TRAC] [type:registry] (1) ⎆ memory/memoryNSServer.Register() + [TRAC] [type:registry] (1.1) register=name:"a" + [TRAC] [type:registry] (2) ⎆ injecterror/injectErrorNSServer.Register() + [TRAC] [type:registry] (2.1) register=name:"a" + [ERRO] [type:registry] (2.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [ERRO] [type:registry] (1.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [TRAC] [type:registry] (1) ⎆ memory/memoryNSServer.Find() + [TRAC] [type:registry] (1.1) find=network_service:{name:"a"} + [TRAC] [type:registry] (2) ⎆ injecterror/injectErrorNSServer.Find() + [TRAC] [type:registry] (2.1) find=network_service:{name:"a"} + [ERRO] [type:registry] (2.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [ERRO] [type:registry] (1.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [TRAC] [type:registry] (1) ⎆ memory/memoryNSServer.Unregister() + [TRAC] [type:registry] (1.1) unregister= + [TRAC] [type:registry] (2) ⎆ injecterror/injectErrorNSServer.Unregister() + [TRAC] [type:registry] (2.1) unregister= + [ERRO] [type:registry] (2.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [ERRO] [type:registry] (1.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} diff --git a/pkg/registry/core/trace/nse_server_test.go b/pkg/registry/core/trace/nse_server_test.go new file mode 100644 index 000000000..c5bb9e9e6 --- /dev/null +++ b/pkg/registry/core/trace/nse_server_test.go @@ -0,0 +1,282 @@ +// Copyright (c) 2023-2024 Cisco and/or its affiliates. +// +// Copyright (c) 2024 Nordix Foundation. +// +// SPDX-License-Identifier: Apache-2.0 +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at: +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Package traceconcise_test has few tests for logs in concise mode +package trace_test + +import ( + "bytes" + "context" + "testing" + + "github.com/networkservicemesh/api/pkg/api/registry" + "github.com/pkg/errors" + "github.com/sirupsen/logrus" + "go.uber.org/goleak" + + "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil" + "github.com/networkservicemesh/sdk/pkg/registry/common/memory" + "github.com/networkservicemesh/sdk/pkg/registry/common/null" + "github.com/networkservicemesh/sdk/pkg/registry/core/chain" + "github.com/networkservicemesh/sdk/pkg/registry/core/streamchannel" + "github.com/networkservicemesh/sdk/pkg/registry/utils/inject/injecterror" + "github.com/networkservicemesh/sdk/pkg/tools/log" + + "github.com/stretchr/testify/require" +) + +func TestOutput(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.InfoLevel) + + s := chain.NewNetworkServiceEndpointRegistryServer( + memory.NewNetworkServiceEndpointRegistryServer(), + null.NewNetworkServiceEndpointRegistryServer(), + ) + + nse, err := s.Register(context.Background(), ®istry.NetworkServiceEndpoint{ + Name: "a", + }) + require.NoError(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceEndpointResponse, 1) + defer close(ch) + _ = s.Find(®istry.NetworkServiceEndpointQuery{ + NetworkServiceEndpoint: ®istry.NetworkServiceEndpoint{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceEndpointFindServer(ctx, ch)) + + _, err = s.Unregister(context.Background(), nse) + require.NoError(t, err) + + expectedOutput := ` [INFO] [type:registry] nse-server-register=name:"a" + [INFO] [type:registry] nse-server-register-response=name:"a" + [INFO] [type:registry] nse-server-find=network_service_endpoint:{name:"a"} + [INFO] [type:registry] nse-server-send=network_service_endpoint:{name:"a"} + [INFO] [type:registry] nse-server-send-response=network_service_endpoint:{name:"a"} + [INFO] [type:registry] nse-server-find-response=network_service_endpoint:{name:"a"} + [INFO] [type:registry] nse-server-unregister=name:"a" + [INFO] [type:registry] nse-server-unregister-response=name:"a" +` + + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestOutput_Trace(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.TraceLevel) + + s := chain.NewNetworkServiceEndpointRegistryServer( + memory.NewNetworkServiceEndpointRegistryServer(), + null.NewNetworkServiceEndpointRegistryServer(), + ) + + nse, err := s.Register(context.Background(), ®istry.NetworkServiceEndpoint{ + Name: "a", + }) + require.NoError(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceEndpointResponse, 1) + defer close(ch) + _ = s.Find(®istry.NetworkServiceEndpointQuery{ + NetworkServiceEndpoint: ®istry.NetworkServiceEndpoint{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceEndpointFindServer(ctx, ch)) + + _, err = s.Unregister(context.Background(), nse) + require.NoError(t, err) + + expectedOutput := ` [TRAC] [type:registry] (1) ⎆ memory/memoryNSEServer.Register() + [TRAC] [type:registry] (1.1) register=name:"a" + [TRAC] [type:registry] (2) ⎆ null/nullNSEServer.Register() + [TRAC] [type:registry] (2.1) register=name:"a" + [TRAC] [type:registry] (2.2) register-response=name:"a" + [TRAC] [type:registry] (1.2) register-response=name:"a" + [TRAC] [type:registry] (1) ⎆ memory/memoryNSEServer.Find() + [TRAC] [type:registry] (1.1) find=network_service_endpoint:{name:"a"} + [TRAC] [type:registry] (2) ⎆ memory/memoryNSEServer.Send() + [TRAC] [type:registry] (2.1) network service endpoint=name:"a" + [TRAC] [type:registry] (2) ⎆ null/nullNSEServer.Find() + [TRAC] [type:registry] (2.1) find=network_service_endpoint:{name:"a"} + [TRAC] [type:registry] (2.2) find-response=network_service_endpoint:{name:"a"} + [TRAC] [type:registry] (1.2) find-response=network_service_endpoint:{name:"a"} + [TRAC] [type:registry] (1) ⎆ memory/memoryNSEServer.Unregister() + [TRAC] [type:registry] (1.1) unregister=name:"a" + [TRAC] [type:registry] (2) ⎆ null/nullNSEServer.Unregister() + [TRAC] [type:registry] (2.1) unregister=name:"a" + [TRAC] [type:registry] (2.2) unregister-response=name:"a" + [TRAC] [type:registry] (1.2) unregister-response=name:"a" +` + + result := testutil.TrimLogTime(&buff) + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestErrorOutput(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.InfoLevel) + + s := chain.NewNetworkServiceEndpointRegistryServer( + memory.NewNetworkServiceEndpointRegistryServer(), + injecterror.NewNetworkServiceEndpointRegistryServer( + injecterror.WithError(errors.New("test error")), + injecterror.WithRegisterErrorTimes(0), + injecterror.WithFindErrorTimes(0), + injecterror.WithUnregisterErrorTimes(0), + ), + ) + + nse, err := s.Register(context.Background(), ®istry.NetworkServiceEndpoint{ + Name: "a", + }) + require.Error(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceEndpointResponse, 1) + defer close(ch) + err = s.Find(®istry.NetworkServiceEndpointQuery{ + NetworkServiceEndpoint: ®istry.NetworkServiceEndpoint{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceEndpointFindServer(ctx, ch)) + require.Error(t, err) + + _, err = s.Unregister(context.Background(), nse) + require.Error(t, err) + + expectedOutput := ` [INFO] [type:registry] nse-server-register=name:"a" + [ERRO] [type:registry] Error returned from injecterror/injectErrorNSEServer.Register: test error + [INFO] [type:registry] nse-server-find=network_service_endpoint:{name:"a"} + [ERRO] [type:registry] Error returned from injecterror/injectErrorNSEServer.Find: test error + [INFO] [type:registry] nse-server-unregister= + [ERRO] [type:registry] Error returned from injecterror/injectErrorNSEServer.Unregister: test error +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + +func TestErrorOutput_Trace(t *testing.T) { + t.Skip() + t.Cleanup(func() { goleak.VerifyNone(t) }) + + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + log.EnableTracing(true) + logrus.SetLevel(logrus.TraceLevel) + + s := chain.NewNetworkServiceEndpointRegistryServer( + memory.NewNetworkServiceEndpointRegistryServer(), + injecterror.NewNetworkServiceEndpointRegistryServer( + injecterror.WithError(&testutil.CustomError{}), + injecterror.WithRegisterErrorTimes(0), + injecterror.WithFindErrorTimes(0), + injecterror.WithUnregisterErrorTimes(0), + ), + ) + + nse, err := s.Register(context.Background(), ®istry.NetworkServiceEndpoint{ + Name: "a", + }) + require.Error(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ch := make(chan *registry.NetworkServiceEndpointResponse, 1) + defer close(ch) + err = s.Find(®istry.NetworkServiceEndpointQuery{ + NetworkServiceEndpoint: ®istry.NetworkServiceEndpoint{ + Name: "a", + }, + }, streamchannel.NewNetworkServiceEndpointFindServer(ctx, ch)) + require.Error(t, err) + + _, err = s.Unregister(context.Background(), nse) + require.Error(t, err) + + expectedOutput := ` [TRAC] [type:registry] (1) ⎆ memory/memoryNSEServer.Register() + [TRAC] [type:registry] (1.1) register=name:"a" + [TRAC] [type:registry] (2) ⎆ injecterror/injectErrorNSEServer.Register() + [TRAC] [type:registry] (2.1) register=name:"a" + [ERRO] [type:registry] (2.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [ERRO] [type:registry] (1.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [TRAC] [type:registry] (1) ⎆ memory/memoryNSEServer.Find() + [TRAC] [type:registry] (1.1) find=network_service_endpoint:{name:"a"} + [TRAC] [type:registry] (2) ⎆ injecterror/injectErrorNSEServer.Find() + [TRAC] [type:registry] (2.1) find=network_service_endpoint:{name:"a"} + [ERRO] [type:registry] (2.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [ERRO] [type:registry] (1.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [TRAC] [type:registry] (1) ⎆ memory/memoryNSEServer.Unregister() + [TRAC] [type:registry] (1.1) unregister= + [TRAC] [type:registry] (2) ⎆ injecterror/injectErrorNSEServer.Unregister() + [TRAC] [type:registry] (2.1) unregister= + [ERRO] [type:registry] (2.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; + [ERRO] [type:registry] (1.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} diff --git a/pkg/registry/core/trace/testutil/testutil.go b/pkg/registry/core/trace/testutil/testutil.go deleted file mode 100644 index 990834cd4..000000000 --- a/pkg/registry/core/trace/testutil/testutil.go +++ /dev/null @@ -1,47 +0,0 @@ -// Copyright (c) 2023 Doc.ai and/or its affiliates. -// -// SPDX-License-Identifier: Apache-2.0 -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at: -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -// Package testutil has few util functions for testing -package testutil - -import ( - "fmt" - "strings" -) - -// TrimLogTime - to format logs -func TrimLogTime(buff fmt.Stringer) string { - // Logger created by the trace chain element uses custom formatter, which prints date and time info in each line - // To check if output matches our expectations, we need to somehow get rid of this info. - // We have the following options: - // 1. Configure formatter options on logger creation in trace element - // 2. Use some global configuration (either set global default formatter - // instead of creating it in trace element or use global config for our formatter) - // 3. Remove datetime information from the output - // Since we are unlikely to need to remove date in any case except these tests, - // it seems like the third option would be the most convenient. - result := "" - datetimeLength := 19 - for _, line := range strings.Split(buff.String(), "\n") { - if len(line) > datetimeLength { - result += line[datetimeLength:] + "\n" - } else { - result += line - } - } - - return result -} diff --git a/pkg/registry/core/trace/traceconcise/common.go b/pkg/registry/core/trace/traceconcise/common.go index 945dfee65..058b13d0d 100644 --- a/pkg/registry/core/trace/traceconcise/common.go +++ b/pkg/registry/core/trace/traceconcise/common.go @@ -1,4 +1,4 @@ -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -24,6 +24,7 @@ import ( "github.com/pkg/errors" "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/stringutils" ) const ( @@ -35,23 +36,17 @@ const ( ) func logError(ctx context.Context, err error, operation string) error { - if trace(ctx) { - log.FromContext(ctx).Errorf("%v", errors.Wrapf(err, "Error returned from %s", operation)) - } + log.FromContext(ctx).Errorf("%v", errors.Wrapf(err, "Error returned from %s", operation)) return err } func logObject(ctx context.Context, k, v interface{}) { - if !trace(ctx) { - return - } - s := log.FromContext(ctx) msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } - s.Infof("%v=%s", k, msg) + log.FromContext(ctx).Infof("%v=%s", k, msg) } diff --git a/pkg/registry/core/trace/traceconcise/traceconcise_test.go b/pkg/registry/core/trace/traceconcise/traceconcise_test.go deleted file mode 100644 index 263198ef6..000000000 --- a/pkg/registry/core/trace/traceconcise/traceconcise_test.go +++ /dev/null @@ -1,141 +0,0 @@ -// Copyright (c) 2023-2024 Cisco and/or its affiliates. -// -// Copyright (c) 2024 Nordix Foundation. -// -// SPDX-License-Identifier: Apache-2.0 -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at: -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -// Package traceconcise_test has few tests for logs in concise mode -package traceconcise_test - -import ( - "bytes" - "context" - "testing" - - "github.com/networkservicemesh/api/pkg/api/registry" - "github.com/pkg/errors" - "github.com/sirupsen/logrus" - "go.uber.org/goleak" - - "github.com/networkservicemesh/sdk/pkg/registry/common/memory" - "github.com/networkservicemesh/sdk/pkg/registry/common/null" - "github.com/networkservicemesh/sdk/pkg/registry/core/chain" - "github.com/networkservicemesh/sdk/pkg/registry/core/streamchannel" - "github.com/networkservicemesh/sdk/pkg/registry/core/trace/testutil" - "github.com/networkservicemesh/sdk/pkg/registry/utils/inject/injecterror" - "github.com/networkservicemesh/sdk/pkg/tools/log" - - "github.com/stretchr/testify/require" -) - -func TestOutput(t *testing.T) { - t.Cleanup(func() { goleak.VerifyNone(t) }) - - var buff bytes.Buffer - logrus.SetOutput(&buff) - logrus.SetFormatter(&logrus.TextFormatter{ - DisableTimestamp: true, - }) - log.EnableTracing(true) - logrus.SetLevel(logrus.InfoLevel) - - s := chain.NewNetworkServiceEndpointRegistryServer( - memory.NewNetworkServiceEndpointRegistryServer(), - null.NewNetworkServiceEndpointRegistryServer(), - ) - - nse, err := s.Register(context.Background(), ®istry.NetworkServiceEndpoint{ - Name: "a", - }) - require.NoError(t, err) - - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - ch := make(chan *registry.NetworkServiceEndpointResponse, 1) - defer close(ch) - _ = s.Find(®istry.NetworkServiceEndpointQuery{ - NetworkServiceEndpoint: ®istry.NetworkServiceEndpoint{ - Name: "a", - }, - }, streamchannel.NewNetworkServiceEndpointFindServer(ctx, ch)) - - _, err = s.Unregister(context.Background(), nse) - require.NoError(t, err) - - expectedOutput := - " [INFO] [type:registry] nse-server-register={\"name\":\"a\"}\n" + - " [INFO] [type:registry] nse-server-register-response={\"name\":\"a\"}\n" + - " [INFO] [type:registry] nse-server-find={\"network_service_endpoint\":{\"name\":\"a\"}}\n" + - " [INFO] [type:registry] nse-server-send={\"network_service_endpoint\":{\"name\":\"a\"}}\n" + - " [INFO] [type:registry] nse-server-send-response={\"network_service_endpoint\":{\"name\":\"a\"}}\n" + - " [INFO] [type:registry] nse-server-find-response={\"network_service_endpoint\":{\"name\":\"a\"}}\n" + - " [INFO] [type:registry] nse-server-unregister={\"name\":\"a\"}\n" + - " [INFO] [type:registry] nse-server-unregister-response={\"name\":\"a\"}\n" - - result := testutil.TrimLogTime(&buff) - require.Equal(t, expectedOutput, result) -} - -func TestErrorOutput(t *testing.T) { - t.Cleanup(func() { goleak.VerifyNone(t) }) - - var buff bytes.Buffer - logrus.SetOutput(&buff) - logrus.SetFormatter(&logrus.TextFormatter{ - DisableTimestamp: true, - }) - log.EnableTracing(true) - logrus.SetLevel(logrus.InfoLevel) - - s := chain.NewNetworkServiceEndpointRegistryServer( - memory.NewNetworkServiceEndpointRegistryServer(), - injecterror.NewNetworkServiceEndpointRegistryServer( - injecterror.WithError(errors.New("test error")), - injecterror.WithRegisterErrorTimes(0), - injecterror.WithFindErrorTimes(0), - injecterror.WithUnregisterErrorTimes(0), - ), - ) - - nse, err := s.Register(context.Background(), ®istry.NetworkServiceEndpoint{ - Name: "a", - }) - require.Error(t, err) - - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - ch := make(chan *registry.NetworkServiceEndpointResponse, 1) - defer close(ch) - err = s.Find(®istry.NetworkServiceEndpointQuery{ - NetworkServiceEndpoint: ®istry.NetworkServiceEndpoint{ - Name: "a", - }, - }, streamchannel.NewNetworkServiceEndpointFindServer(ctx, ch)) - require.Error(t, err) - - _, err = s.Unregister(context.Background(), nse) - require.Error(t, err) - - expectedOutput := - " [INFO] [type:registry] nse-server-register={\"name\":\"a\"}\n" + - " [ERRO] [type:registry] Error returned from sdk/pkg/registry/utils/inject/injecterror/injectErrorNSEServer.Register: test error\n" + - " [INFO] [type:registry] nse-server-find={\"network_service_endpoint\":{\"name\":\"a\"}}\n" + - " [ERRO] [type:registry] Error returned from sdk/pkg/registry/utils/inject/injecterror/injectErrorNSEServer.Find: test error\n" + - " [INFO] [type:registry] nse-server-unregister=null\n" + - " [ERRO] [type:registry] Error returned from sdk/pkg/registry/utils/inject/injecterror/injectErrorNSEServer.Unregister: test error\n" - - result := testutil.TrimLogTime(&buff) - require.Equal(t, expectedOutput, result) -} diff --git a/pkg/registry/core/trace/traceverbose/common.go b/pkg/registry/core/trace/traceverbose/common.go index ee96d7c71..e17b4edb9 100644 --- a/pkg/registry/core/trace/traceverbose/common.go +++ b/pkg/registry/core/trace/traceverbose/common.go @@ -1,6 +1,6 @@ // Copyright (c) 2021 Doc.ai and/or its affiliates. // -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -26,6 +26,7 @@ import ( "github.com/pkg/errors" "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/stringutils" ) const ( @@ -41,10 +42,10 @@ type stackTracer interface { } func logError(ctx context.Context, err error, operation string) error { + if err == error(nil) { + return nil + } if _, ok := err.(stackTracer); !ok { - if err == error(nil) { - return nil - } err = errors.Wrapf(err, "Error returned from %s", operation) log.FromContext(ctx).Errorf("%+v", err) return err @@ -54,17 +55,12 @@ func logError(ctx context.Context, err error, operation string) error { } func logObjectTrace(ctx context.Context, k, v interface{}) { - if ok := trace(ctx); !ok { - return - } - - s := log.FromContext(ctx) msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } - s.Tracef("%v=%s", k, msg) + log.FromContext(ctx).Tracef("%v=%s", k, msg) } diff --git a/pkg/registry/core/trace/traceverbose/context.go b/pkg/registry/core/trace/traceverbose/context.go index fe6e6121a..47b9dfaa5 100644 --- a/pkg/registry/core/trace/traceverbose/context.go +++ b/pkg/registry/core/trace/traceverbose/context.go @@ -1,7 +1,7 @@ -// Copyright (c) 2020-2023 Cisco Systems, Inc. -// // Copyright (c) 2021-2023 Doc.ai and/or its affiliates. // +// Copyright (c) 2020-2024 Cisco Systems, Inc. +// // SPDX-License-Identifier: Apache-2.0 // // Licensed under the Apache License, Version 2.0 (the "License"); @@ -27,11 +27,10 @@ import ( "github.com/networkservicemesh/sdk/pkg/tools/log/spanlogger" ) -type contextKeyType string +type contextKeyType struct{} const ( - traceInfoKey contextKeyType = "ConnectionInfoRegistry" - loggedType string = "registry" + loggedType string = "registry" ) // ConnectionInfo - struct is used for tracing. @@ -73,11 +72,11 @@ func withTrace(parent context.Context) context.Context { return parent } - return context.WithValue(parent, traceInfoKey, &traceInfo{}) + return context.WithValue(parent, contextKeyType{}, &traceInfo{}) } // trace - return traceInfo from context func trace(ctx context.Context) bool { - _, ok := ctx.Value(traceInfoKey).(*traceInfo) + _, ok := ctx.Value(contextKeyType{}).(*traceInfo) return ok } diff --git a/pkg/registry/core/trace/traceverbose/ns_registry.go b/pkg/registry/core/trace/traceverbose/ns_registry.go index 232c13745..02c8638ca 100644 --- a/pkg/registry/core/trace/traceverbose/ns_registry.go +++ b/pkg/registry/core/trace/traceverbose/ns_registry.go @@ -1,6 +1,6 @@ // Copyright (c) 2020-2022 Doc.ai and/or its affiliates. // -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -166,7 +166,7 @@ func (t *traceNetworkServiceRegistryServer) Unregister(ctx context.Context, in * if err != nil { return nil, logError(ctx, err, operation) } - logObjectTrace(ctx, "unregister-response", rv) + logObjectTrace(ctx, "unregister-response", in) return rv, nil } diff --git a/pkg/registry/core/trace/traceverbose/nse_registry.go b/pkg/registry/core/trace/traceverbose/nse_registry.go index e44fa298a..9b34c0351 100644 --- a/pkg/registry/core/trace/traceverbose/nse_registry.go +++ b/pkg/registry/core/trace/traceverbose/nse_registry.go @@ -1,6 +1,6 @@ // Copyright (c) 2020-2022 Doc.ai and/or its affiliates. // -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -166,7 +166,7 @@ func (t *traceNetworkServiceEndpointRegistryServer) Unregister(ctx context.Conte if err != nil { return nil, logError(ctx, err, operation) } - logObjectTrace(ctx, "unregister-response", rv) + logObjectTrace(ctx, "unregister-response", in) return rv, nil } diff --git a/pkg/tools/dnsutils/trace/common.go b/pkg/tools/dnsutils/trace/common.go index 7255a1802..d1a1b60a6 100644 --- a/pkg/tools/dnsutils/trace/common.go +++ b/pkg/tools/dnsutils/trace/common.go @@ -1,4 +1,4 @@ -// Copyright (c) 2022 Cisco Systems, Inc. +// Copyright (c) 2022-2024 Cisco Systems, Inc. // // SPDX-License-Identifier: Apache-2.0 // @@ -18,8 +18,6 @@ package trace import ( "context" - "encoding/json" - "fmt" "strings" "github.com/google/go-cmp/cmp" @@ -68,13 +66,5 @@ func logResponse(ctx context.Context, message *dns.Msg, prefixes ...string) { } func logObjectTrace(ctx context.Context, k, v interface{}) { - s := log.FromContext(ctx) - msg := "" - cc, err := json.Marshal(v) - if err == nil { - msg = string(cc) - } else { - msg = fmt.Sprint(v) - } - s.Tracef("%v=%s", k, msg) + log.FromContext(ctx).Tracef("%v=%s", k, v) } diff --git a/pkg/tools/log/defaultlogger.go b/pkg/tools/log/defaultlogger.go index 42d1399aa..93e28503b 100644 --- a/pkg/tools/log/defaultlogger.go +++ b/pkg/tools/log/defaultlogger.go @@ -1,4 +1,4 @@ -// Copyright (c) 2021-2022 Doc.ai and/or its affiliates. +// Copyright (c) 2021-2024 Doc.ai and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -21,6 +21,8 @@ import ( "fmt" "log" "strings" + + "github.com/networkservicemesh/sdk/pkg/tools/stringutils" ) type defaultLogger struct { @@ -90,7 +92,7 @@ func (l *defaultLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/logruslogger/logruslogger.go b/pkg/tools/log/logruslogger/logruslogger.go index 41d9b3bc2..b6fb71da9 100644 --- a/pkg/tools/log/logruslogger/logruslogger.go +++ b/pkg/tools/log/logruslogger/logruslogger.go @@ -34,6 +34,7 @@ import ( "github.com/networkservicemesh/sdk/pkg/tools/log" "github.com/networkservicemesh/sdk/pkg/tools/log/spanlogger" + "github.com/networkservicemesh/sdk/pkg/tools/stringutils" ) type logrusLogger struct { @@ -92,7 +93,7 @@ func (s *logrusLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } @@ -196,7 +197,7 @@ func (s *traceLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/spanlogger/spanlogger.go b/pkg/tools/log/spanlogger/spanlogger.go index 64e3810f0..2f7249c6a 100644 --- a/pkg/tools/log/spanlogger/spanlogger.go +++ b/pkg/tools/log/spanlogger/spanlogger.go @@ -1,6 +1,6 @@ // Copyright (c) 2021-2022 Doc.ai and/or its affiliates. // -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -27,6 +27,7 @@ import ( "github.com/networkservicemesh/sdk/pkg/tools/log" "github.com/networkservicemesh/sdk/pkg/tools/opentelemetry" + "github.com/networkservicemesh/sdk/pkg/tools/stringutils" ) // spanlogger - provides a way to log via opentelemetry spans @@ -92,7 +93,7 @@ func (s *spanLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = string(cc) + msg = stringutils.CovertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/nanoid/generator.go b/pkg/tools/nanoid/generator.go index e02fd23ff..30b14e923 100644 --- a/pkg/tools/nanoid/generator.go +++ b/pkg/tools/nanoid/generator.go @@ -59,6 +59,15 @@ func generateRandomBuffer(generator io.Reader, step int) ([]byte, error) { return buffer, nil } +// MustGenerateString calls GenerateString and panics if it returns error +func MustGenerateString(size int, opts ...Option) string { + res, err := GenerateString(size, opts...) + if err != nil { + panic(err.Error()) + } + return res +} + // GenerateString generates a random string based on size. // Original JavaScript implementation: https://github.com/ai/nanoid/blob/main/README.md func GenerateString(size int, opt ...Option) (string, error) { diff --git a/pkg/tools/stringutils/stringutils.go b/pkg/tools/stringutils/stringutils.go new file mode 100644 index 000000000..9a3ac3fd5 --- /dev/null +++ b/pkg/tools/stringutils/stringutils.go @@ -0,0 +1,27 @@ +// Copyright (c) 2024 Cisco and/or its affiliates. +// +// SPDX-License-Identifier: Apache-2.0 +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at: +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Package stringutils provides helper functions related to strings. +package stringutils + +import "unsafe" + +// CovertBytesToString converts slice of bytes to string via unsafe package with zero allocations. +// Note: slice MUST NOT be modified after using this function. +func CovertBytesToString(slice []byte) string { + // nolint + return *(*string)(unsafe.Pointer(&slice)) +} diff --git a/pkg/tools/typeutils/typeutils.go b/pkg/tools/typeutils/typeutils.go index 2eed37378..80b6ba361 100644 --- a/pkg/tools/typeutils/typeutils.go +++ b/pkg/tools/typeutils/typeutils.go @@ -1,4 +1,4 @@ -// Copyright (c) 2020 Cisco Systems, Inc. +// Copyright (c) 2020-2024 Cisco Systems, Inc. // // SPDX-License-Identifier: Apache-2.0 // @@ -18,7 +18,6 @@ package typeutils import ( - "fmt" "reflect" "strings" ) @@ -29,6 +28,18 @@ func GetFuncName(value interface{}, methodName string) string { if v.Kind() == reflect.Ptr { v = v.Elem() } - pkgPath := strings.TrimPrefix(v.Type().PkgPath(), "github.com/networkservicemesh/") - return fmt.Sprintf("%s/%s.%s", pkgPath, v.Type().Name(), methodName) + + typeName := v.Type().Name() + pkgPath := v.Type().PkgPath() + pkgPath = pkgPath[strings.LastIndex(pkgPath, "/")+1:] + sb := strings.Builder{} + + sb.Grow(len(methodName) + len(pkgPath) + len(typeName) + 2) + _, _ = sb.WriteString(pkgPath) + _, _ = sb.WriteString("/") + _, _ = sb.WriteString(typeName) + _, _ = sb.WriteString(".") + _, _ = sb.WriteString(methodName) + + return sb.String() } From 5d6ccd07fb19e9b799de685f81876dad90caa22c Mon Sep 17 00:00:00 2001 From: denis-tingaikin Date: Mon, 9 Dec 2024 06:21:17 +0300 Subject: [PATCH 2/5] fix ci issues Signed-off-by: denis-tingaikin --- go.mod | 2 +- pkg/networkservice/core/trace/client.go | 2 +- pkg/networkservice/core/trace/server.go | 2 +- pkg/networkservice/core/trace/traceverbose/context.go | 4 ++-- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/go.mod b/go.mod index c8a6b66e1..a068c790b 100644 --- a/go.mod +++ b/go.mod @@ -3,6 +3,7 @@ module github.com/networkservicemesh/sdk go 1.23 require ( + github.com/OneOfOne/xxhash v1.2.8 github.com/RoaringBitmap/roaring v0.9.4 github.com/antonfisher/nested-logrus-formatter v1.3.1 github.com/benbjohnson/clock v1.3.0 @@ -50,7 +51,6 @@ require ( require ( cloud.google.com/go/compute v1.23.1 // indirect github.com/Microsoft/go-winio v0.6.1 // indirect - github.com/OneOfOne/xxhash v1.2.8 // indirect github.com/agnivade/levenshtein v1.1.1 // indirect github.com/armon/go-metrics v0.0.0-20190430140413-ec5e00d3c878 // indirect github.com/beorn7/perks v1.0.1 // indirect diff --git a/pkg/networkservice/core/trace/client.go b/pkg/networkservice/core/trace/client.go index 5c1cfadaf..93c7b3f3c 100644 --- a/pkg/networkservice/core/trace/client.go +++ b/pkg/networkservice/core/trace/client.go @@ -1,4 +1,4 @@ -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // diff --git a/pkg/networkservice/core/trace/server.go b/pkg/networkservice/core/trace/server.go index b861c754b..dc3d0e635 100644 --- a/pkg/networkservice/core/trace/server.go +++ b/pkg/networkservice/core/trace/server.go @@ -1,4 +1,4 @@ -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // diff --git a/pkg/networkservice/core/trace/traceverbose/context.go b/pkg/networkservice/core/trace/traceverbose/context.go index aa1cb8791..8c5c7770c 100644 --- a/pkg/networkservice/core/trace/traceverbose/context.go +++ b/pkg/networkservice/core/trace/traceverbose/context.go @@ -1,7 +1,7 @@ -// Copyright (c) 2020-2023 Cisco Systems, Inc. -// // Copyright (c) 2021-2023 Doc.ai and/or its affiliates. // +// Copyright (c) 2020-2024 Cisco Systems, Inc. +// // SPDX-License-Identifier: Apache-2.0 // // Licensed under the Apache License, Version 2.0 (the "License"); From bc378bf145cde7dffd81ec66b5006895a59e664b Mon Sep 17 00:00:00 2001 From: denis-tingaikin Date: Mon, 9 Dec 2024 13:17:20 +0300 Subject: [PATCH 3/5] apply self code review Signed-off-by: denis-tingaikin --- pkg/registry/core/trace/ns_registry.go | 60 +++++++++++++++--------- pkg/registry/core/trace/nse_registry.go | 61 ++++++++++++++++--------- 2 files changed, 79 insertions(+), 42 deletions(-) diff --git a/pkg/registry/core/trace/ns_registry.go b/pkg/registry/core/trace/ns_registry.go index 89307f79b..f6256b2cb 100644 --- a/pkg/registry/core/trace/ns_registry.go +++ b/pkg/registry/core/trace/ns_registry.go @@ -1,4 +1,4 @@ -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -31,68 +31,86 @@ import ( ) type traceNetworkServiceRegistryClient struct { - verbose registry.NetworkServiceRegistryClient - concise registry.NetworkServiceRegistryClient + verbose, concise, original registry.NetworkServiceRegistryClient } // NewNetworkServiceRegistryClient - wraps registry.NetworkServiceRegistryClient with tracing func NewNetworkServiceRegistryClient(traced registry.NetworkServiceRegistryClient) registry.NetworkServiceRegistryClient { return &traceNetworkServiceRegistryClient{ - verbose: traceverbose.NewNetworkServiceRegistryClient(traced), - concise: traceconcise.NewNetworkServiceRegistryClient(traced), + verbose: traceverbose.NewNetworkServiceRegistryClient(traced), + concise: traceconcise.NewNetworkServiceRegistryClient(traced), + original: traced, } } func (t *traceNetworkServiceRegistryClient) Register(ctx context.Context, in *registry.NetworkService, opts ...grpc.CallOption) (*registry.NetworkService, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Register(ctx, in, opts...) + } + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Register(ctx, in, opts...) } - return t.concise.Register(ctx, in, opts...) + return t.original.Register(ctx, in, opts...) } func (t *traceNetworkServiceRegistryClient) Find(ctx context.Context, in *registry.NetworkServiceQuery, opts ...grpc.CallOption) (registry.NetworkServiceRegistry_FindClient, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Find(ctx, in, opts...) } - return t.concise.Find(ctx, in, opts...) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Find(ctx, in, opts...) + } + return t.original.Find(ctx, in, opts...) } func (t *traceNetworkServiceRegistryClient) Unregister(ctx context.Context, in *registry.NetworkService, opts ...grpc.CallOption) (*empty.Empty, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Unregister(ctx, in, opts...) } - return t.concise.Unregister(ctx, in, opts...) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Unregister(ctx, in, opts...) + } + return t.original.Unregister(ctx, in, opts...) } type traceNetworkServiceRegistryServer struct { - verbose registry.NetworkServiceRegistryServer - concise registry.NetworkServiceRegistryServer + concise, verbose, original registry.NetworkServiceRegistryServer } // NewNetworkServiceRegistryServer - wraps registry.NetworkServiceRegistryServer with tracing func NewNetworkServiceRegistryServer(traced registry.NetworkServiceRegistryServer) registry.NetworkServiceRegistryServer { return &traceNetworkServiceRegistryServer{ - verbose: traceverbose.NewNetworkServiceRegistryServer(traced), - concise: traceconcise.NewNetworkServiceRegistryServer(traced), + verbose: traceverbose.NewNetworkServiceRegistryServer(traced), + concise: traceconcise.NewNetworkServiceRegistryServer(traced), + original: traced, } } func (t *traceNetworkServiceRegistryServer) Register(ctx context.Context, in *registry.NetworkService) (*registry.NetworkService, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Register(ctx, in) } - return t.concise.Register(ctx, in) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Register(ctx, in) + } + return t.original.Register(ctx, in) } func (t *traceNetworkServiceRegistryServer) Find(in *registry.NetworkServiceQuery, s registry.NetworkServiceRegistry_FindServer) error { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Find(in, s) } - return t.concise.Find(in, s) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Find(in, s) + } + return t.original.Find(in, s) } func (t *traceNetworkServiceRegistryServer) Unregister(ctx context.Context, in *registry.NetworkService) (*empty.Empty, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Unregister(ctx, in) } - return t.concise.Unregister(ctx, in) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Unregister(ctx, in) + } + return t.original.Unregister(ctx, in) } diff --git a/pkg/registry/core/trace/nse_registry.go b/pkg/registry/core/trace/nse_registry.go index 246124c2e..52564eba3 100644 --- a/pkg/registry/core/trace/nse_registry.go +++ b/pkg/registry/core/trace/nse_registry.go @@ -1,4 +1,4 @@ -// Copyright (c) 2023 Cisco and/or its affiliates. +// Copyright (c) 2023-2024 Cisco and/or its affiliates. // // SPDX-License-Identifier: Apache-2.0 // @@ -30,68 +30,87 @@ import ( ) type traceNetworkServiceEndpointRegistryClient struct { - verbose registry.NetworkServiceEndpointRegistryClient - concise registry.NetworkServiceEndpointRegistryClient + verbose, concise, original registry.NetworkServiceEndpointRegistryClient } // NewNetworkServiceEndpointRegistryClient - wraps registry.NetworkServiceEndpointRegistryClient with tracing func NewNetworkServiceEndpointRegistryClient(traced registry.NetworkServiceEndpointRegistryClient) registry.NetworkServiceEndpointRegistryClient { return &traceNetworkServiceEndpointRegistryClient{ - verbose: traceverbose.NewNetworkServiceEndpointRegistryClient(traced), - concise: traceconcise.NewNetworkServiceEndpointRegistryClient(traced), + verbose: traceverbose.NewNetworkServiceEndpointRegistryClient(traced), + concise: traceconcise.NewNetworkServiceEndpointRegistryClient(traced), + original: traced, } } func (t *traceNetworkServiceEndpointRegistryClient) Register(ctx context.Context, in *registry.NetworkServiceEndpoint, opts ...grpc.CallOption) (*registry.NetworkServiceEndpoint, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Register(ctx, in, opts...) } - return t.concise.Register(ctx, in, opts...) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Register(ctx, in, opts...) + } + return t.original.Register(ctx, in, opts...) } + func (t *traceNetworkServiceEndpointRegistryClient) Find(ctx context.Context, in *registry.NetworkServiceEndpointQuery, opts ...grpc.CallOption) (registry.NetworkServiceEndpointRegistry_FindClient, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Find(ctx, in, opts...) } - return t.concise.Find(ctx, in, opts...) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Find(ctx, in, opts...) + } + return t.original.Find(ctx, in, opts...) } func (t *traceNetworkServiceEndpointRegistryClient) Unregister(ctx context.Context, in *registry.NetworkServiceEndpoint, opts ...grpc.CallOption) (*empty.Empty, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Unregister(ctx, in, opts...) } - return t.concise.Unregister(ctx, in, opts...) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Unregister(ctx, in, opts...) + } + return t.original.Unregister(ctx, in, opts...) } type traceNetworkServiceEndpointRegistryServer struct { - verbose registry.NetworkServiceEndpointRegistryServer - concise registry.NetworkServiceEndpointRegistryServer + verbose, concise, original registry.NetworkServiceEndpointRegistryServer } // NewNetworkServiceEndpointRegistryServer - wraps registry.NetworkServiceEndpointRegistryServer with tracing func NewNetworkServiceEndpointRegistryServer(traced registry.NetworkServiceEndpointRegistryServer) registry.NetworkServiceEndpointRegistryServer { return &traceNetworkServiceEndpointRegistryServer{ - verbose: traceverbose.NewNetworkServiceEndpointRegistryServer(traced), - concise: traceconcise.NewNetworkServiceEndpointRegistryServer(traced), + verbose: traceverbose.NewNetworkServiceEndpointRegistryServer(traced), + concise: traceconcise.NewNetworkServiceEndpointRegistryServer(traced), + original: traced, } } func (t *traceNetworkServiceEndpointRegistryServer) Register(ctx context.Context, in *registry.NetworkServiceEndpoint) (*registry.NetworkServiceEndpoint, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Register(ctx, in) } - return t.concise.Register(ctx, in) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Register(ctx, in) + } + return t.original.Register(ctx, in) } func (t *traceNetworkServiceEndpointRegistryServer) Find(in *registry.NetworkServiceEndpointQuery, s registry.NetworkServiceEndpointRegistry_FindServer) error { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Find(in, s) } - return t.concise.Find(in, s) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Find(in, s) + } + return t.original.Find(in, s) } func (t *traceNetworkServiceEndpointRegistryServer) Unregister(ctx context.Context, in *registry.NetworkServiceEndpoint) (*empty.Empty, error) { - if logrus.GetLevel() == logrus.TraceLevel { + if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Unregister(ctx, in) } - return t.concise.Unregister(ctx, in) + if logrus.GetLevel() <= logrus.WarnLevel { + return t.concise.Unregister(ctx, in) + } + return t.original.Unregister(ctx, in) } From f1bf3077f89e7c24c9027842c8f321d0ca837c51 Mon Sep 17 00:00:00 2001 From: denis-tingaikin Date: Mon, 16 Dec 2024 14:24:22 +0300 Subject: [PATCH 4/5] apply comments and fix https://github.com/networkservicemesh/sdk/issues/1707 Signed-off-by: denis-tingaikin --- pkg/networkservice/core/trace/README.md | 4 +-- .../core/trace/server_bench_test.go | 2 +- pkg/networkservice/core/trace/server_test.go | 34 +++++++++---------- .../core/trace/traceconcise/common.go | 2 +- .../core/trace/traceverbose/common.go | 4 +-- .../core/trace/traceconcise/common.go | 2 +- .../core/trace/traceverbose/common.go | 2 +- pkg/tools/log/defaultlogger.go | 2 +- pkg/tools/log/logruslogger/logruslogger.go | 4 +-- pkg/tools/log/spanlogger/spanlogger.go | 2 +- pkg/tools/stringutils/stringutils.go | 4 +-- 11 files changed, 31 insertions(+), 31 deletions(-) diff --git a/pkg/networkservice/core/trace/README.md b/pkg/networkservice/core/trace/README.md index dfefaceba..f0c0b3ef7 100644 --- a/pkg/networkservice/core/trace/README.md +++ b/pkg/networkservice/core/trace/README.md @@ -14,7 +14,7 @@ Benchmark_LongRequest_Info-8 340 3765718 ns/op 273254 B/op Benchmark_ShortRequest_Trace-8 79 13600986 ns/op 344445 B/op 8475 allocs/op Benchmark_LongRequest_Trace-8 2 916385562 ns/op 20998324 B/op 694678 allocs/op -Benchmark_LongRequest_Trace_NoDiff-8 2 565520104 ns/op 12236116 B/op 585667 allocs/op +Benchmark_LongRequest_NoDiff_Trace-8 2 565520104 ns/op 12236116 B/op 585667 allocs/op Benchmark_LongRequest_Diff_Warn-8 340 3765718 ns/op 273254 B/op 861 allocs/op ``` @@ -28,7 +28,7 @@ Benchmark_LongRequest_Info-8 373 3064039 ns/op 253359 B/op Benchmark_ShortRequest_Trace-8 543 2599280 ns/op 237262 B/op 1825 allocs/op Benchmark_LongRequest_Trace-8 9 131145361 ns/op 22433480 B/op 20749 allocs/op -Benchmark_LongRequest_Trace_NoDiff-8 18 72167456 ns/op 10900859 B/op 13685 allocs/op +Benchmark_LongRequest_NoDiff_Trace-8 18 72167456 ns/op 10900859 B/op 13685 allocs/op Benchmark_LongRequest_Diff_Warn-8 31128 36019 ns/op 9600 B/op 200 allocs/op ``` diff --git a/pkg/networkservice/core/trace/server_bench_test.go b/pkg/networkservice/core/trace/server_bench_test.go index 5548feed9..bdcbbd079 100644 --- a/pkg/networkservice/core/trace/server_bench_test.go +++ b/pkg/networkservice/core/trace/server_bench_test.go @@ -140,7 +140,7 @@ func Benchmark_LongRequest_Trace(b *testing.B) { } } -func Benchmark_LongRequest_Trace_NoDiff(b *testing.B) { +func Benchmark_LongRequest_NoDiff_Trace(b *testing.B) { var s = newTestStaticServerChain(100) var request = newTestRequest(100) var ctx = context.Background() diff --git a/pkg/networkservice/core/trace/server_test.go b/pkg/networkservice/core/trace/server_test.go index 5ba8d1a48..71cbb12d3 100644 --- a/pkg/networkservice/core/trace/server_test.go +++ b/pkg/networkservice/core/trace/server_test.go @@ -97,21 +97,21 @@ func TestTraceOutput(t *testing.T) { require.NotNil(t, e) expectedOutput := ` [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Request() - [INFO] [id:conn-1] [type:networkService] (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"}}]} - [INFO] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (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"}}]} + [TRAC] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Request() - [INFO] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} - [INFO] [id:conn-1] [type:networkService] (2.2) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} - [INFO] [id:conn-1] [type:networkService] (2.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"C"}} - [INFO] [id:conn-1] [type:networkService] (1.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} + [TRAC] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (2.2) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} + [TRAC] [id:conn-1] [type:networkService] (2.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"C"}} + [TRAC] [id:conn-1] [type:networkService] (1.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Close() - [INFO] [id:conn-1] [type:networkService] (1.1) close={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} - [INFO] [id:conn-1] [type:networkService] (1.2) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"W"}} + [TRAC] [id:conn-1] [type:networkService] (1.1) close={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} + [TRAC] [id:conn-1] [type:networkService] (1.2) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"W"}} [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Close() - [INFO] [id:conn-1] [type:networkService] (2.1) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} - [INFO] [id:conn-1] [type:networkService] (2.2) close-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} - [INFO] [id:conn-1] [type:networkService] (2.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Y"}} - [INFO] [id:conn-1] [type:networkService] (1.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Z"}} + [TRAC] [id:conn-1] [type:networkService] (2.1) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} + [TRAC] [id:conn-1] [type:networkService] (2.2) close-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} + [TRAC] [id:conn-1] [type:networkService] (2.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Y"}} + [TRAC] [id:conn-1] [type:networkService] (1.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Z"}} ` result := testutil.TrimLogTime(&buff) @@ -146,14 +146,14 @@ func TestErrorOutput(t *testing.T) { require.Nil(t, conn) expectedOutput := ` [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Request() - [INFO] [id:conn-1] [type:networkService] (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"}}]} - [INFO] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (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"}}]} + [TRAC] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Request() - [INFO] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} [TRAC] [id:conn-1] [type:networkService] (3) ⎆ testutil/ErrorServer.Request() - [INFO] [id:conn-1] [type:networkService] (3.1) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} + [TRAC] [id:conn-1] [type:networkService] (3.1) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} [ERRO] [id:conn-1] [type:networkService] (3.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; - [INFO] [id:conn-1] [type:networkService] (2.2) request-response-diff=null + [TRAC] [id:conn-1] [type:networkService] (2.2) request-response-diff=null [ERRO] [id:conn-1] [type:networkService] (2.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; [ERRO] [id:conn-1] [type:networkService] (1.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; ` diff --git a/pkg/networkservice/core/trace/traceconcise/common.go b/pkg/networkservice/core/trace/traceconcise/common.go index 6d9baa438..7f0c1ee04 100644 --- a/pkg/networkservice/core/trace/traceconcise/common.go +++ b/pkg/networkservice/core/trace/traceconcise/common.go @@ -55,7 +55,7 @@ func logObject(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/networkservice/core/trace/traceverbose/common.go b/pkg/networkservice/core/trace/traceverbose/common.go index 941206c0f..99b766b79 100644 --- a/pkg/networkservice/core/trace/traceverbose/common.go +++ b/pkg/networkservice/core/trace/traceverbose/common.go @@ -216,9 +216,9 @@ func logObjectTrace(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } - s.Infof("%v=%s", k, msg) + s.Tracef("%v=%s", k, msg) } diff --git a/pkg/registry/core/trace/traceconcise/common.go b/pkg/registry/core/trace/traceconcise/common.go index 058b13d0d..af71b1ba8 100644 --- a/pkg/registry/core/trace/traceconcise/common.go +++ b/pkg/registry/core/trace/traceconcise/common.go @@ -44,7 +44,7 @@ func logObject(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/registry/core/trace/traceverbose/common.go b/pkg/registry/core/trace/traceverbose/common.go index e17b4edb9..f6915c3cb 100644 --- a/pkg/registry/core/trace/traceverbose/common.go +++ b/pkg/registry/core/trace/traceverbose/common.go @@ -58,7 +58,7 @@ func logObjectTrace(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/defaultlogger.go b/pkg/tools/log/defaultlogger.go index 93e28503b..b5aec37aa 100644 --- a/pkg/tools/log/defaultlogger.go +++ b/pkg/tools/log/defaultlogger.go @@ -92,7 +92,7 @@ func (l *defaultLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/logruslogger/logruslogger.go b/pkg/tools/log/logruslogger/logruslogger.go index b6fb71da9..4e1136051 100644 --- a/pkg/tools/log/logruslogger/logruslogger.go +++ b/pkg/tools/log/logruslogger/logruslogger.go @@ -93,7 +93,7 @@ func (s *logrusLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } @@ -197,7 +197,7 @@ func (s *traceLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/spanlogger/spanlogger.go b/pkg/tools/log/spanlogger/spanlogger.go index 2f7249c6a..d92393648 100644 --- a/pkg/tools/log/spanlogger/spanlogger.go +++ b/pkg/tools/log/spanlogger/spanlogger.go @@ -93,7 +93,7 @@ func (s *spanLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/stringutils/stringutils.go b/pkg/tools/stringutils/stringutils.go index 9a3ac3fd5..d28550bca 100644 --- a/pkg/tools/stringutils/stringutils.go +++ b/pkg/tools/stringutils/stringutils.go @@ -19,9 +19,9 @@ package stringutils import "unsafe" -// CovertBytesToString converts slice of bytes to string via unsafe package with zero allocations. +// ConvertBytesToString converts slice of bytes to string via unsafe package with zero allocations. // Note: slice MUST NOT be modified after using this function. -func CovertBytesToString(slice []byte) string { +func ConvertBytesToString(slice []byte) string { // nolint return *(*string)(unsafe.Pointer(&slice)) } From d9daf1b9ed0fa1b4c16b4fc8994e1cdd0b24eccf Mon Sep 17 00:00:00 2001 From: denis-tingaikin Date: Thu, 19 Dec 2024 15:44:33 +0300 Subject: [PATCH 5/5] use the logrus logger by default to not miss useful logs. Signed-off-by: denis-tingaikin --- pkg/networkservice/core/trace/client.go | 9 ++++++ pkg/networkservice/core/trace/server.go | 8 +++++ pkg/networkservice/core/trace/server_test.go | 33 ++++++++++++++++++++ pkg/registry/core/trace/ns_registry.go | 17 ++++++++++ pkg/registry/core/trace/nse_registry.go | 14 +++++++++ 5 files changed, 81 insertions(+) diff --git a/pkg/networkservice/core/trace/client.go b/pkg/networkservice/core/trace/client.go index 93c7b3f3c..cc6cf4882 100644 --- a/pkg/networkservice/core/trace/client.go +++ b/pkg/networkservice/core/trace/client.go @@ -29,6 +29,8 @@ import ( "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/traceconcise" "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/traceverbose" + "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/log/logruslogger" ) type traceClient struct { @@ -48,16 +50,23 @@ func NewNetworkServiceClient(traced networkservice.NetworkServiceClient) network func (t *traceClient) Request(ctx context.Context, request *networkservice.NetworkServiceRequest, opts ...grpc.CallOption) (*networkservice.Connection, error) { if logrus.GetLevel() <= logrus.WarnLevel { + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Request(ctx, request) } if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Request(ctx, request, opts...) } + return t.concise.Request(ctx, request, opts...) } func (t *traceClient) Close(ctx context.Context, conn *networkservice.Connection, opts ...grpc.CallOption) (*empty.Empty, error) { if logrus.GetLevel() <= logrus.WarnLevel { + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Close(ctx, conn) } if logrus.GetLevel() >= logrus.DebugLevel { diff --git a/pkg/networkservice/core/trace/server.go b/pkg/networkservice/core/trace/server.go index dc3d0e635..4f702aa80 100644 --- a/pkg/networkservice/core/trace/server.go +++ b/pkg/networkservice/core/trace/server.go @@ -23,6 +23,8 @@ import ( "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/traceconcise" "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/traceverbose" + "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/log/logruslogger" "github.com/golang/protobuf/ptypes/empty" @@ -44,6 +46,9 @@ func NewNetworkServiceServer(traced networkservice.NetworkServiceServer) network func (t *traceServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) { if logrus.GetLevel() <= logrus.WarnLevel { + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Request(ctx, request) } if logrus.GetLevel() >= logrus.DebugLevel { @@ -55,6 +60,9 @@ func (t *traceServer) Request(ctx context.Context, request *networkservice.Netwo func (t *traceServer) Close(ctx context.Context, conn *networkservice.Connection) (*empty.Empty, error) { if logrus.GetLevel() <= logrus.WarnLevel { + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Close(ctx, conn) } if logrus.GetLevel() >= logrus.DebugLevel { diff --git a/pkg/networkservice/core/trace/server_test.go b/pkg/networkservice/core/trace/server_test.go index 71cbb12d3..b631cd1a8 100644 --- a/pkg/networkservice/core/trace/server_test.go +++ b/pkg/networkservice/core/trace/server_test.go @@ -33,6 +33,7 @@ import ( "github.com/networkservicemesh/sdk/pkg/networkservice/core/chain" "github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil" + "github.com/networkservicemesh/sdk/pkg/networkservice/utils/checks/checkcontext" "github.com/networkservicemesh/sdk/pkg/tools/log" ) @@ -165,6 +166,38 @@ func TestErrorOutput(t *testing.T) { require.Equal(t, expectedOutput, result) } +func Test_ErrorOutput_InfoLevel(t *testing.T) { + // Configure logging + // Set output to buffer + var buff bytes.Buffer + logrus.SetOutput(&buff) + logrus.SetFormatter(&logrus.TextFormatter{ + DisableTimestamp: true, + }) + logrus.SetLevel(logrus.WarnLevel) + log.EnableTracing(true) + + // Create a chain with modifying elements + ch := chain.NewNetworkServiceServer( + checkcontext.NewServer(t, func(t *testing.T, ctx context.Context) { + log.FromContext(ctx).Error("error details") + }), + ) + + request := testutil.NewConnection() + + _, err := ch.Request(context.Background(), request) + require.NoError(t, err) + + expectedOutput := "[ERRO] error details\n" + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + require.Equal(t, expectedOutput, result) +} + func TestOutput_Info(t *testing.T) { // Configure logging // Set output to buffer diff --git a/pkg/registry/core/trace/ns_registry.go b/pkg/registry/core/trace/ns_registry.go index f6256b2cb..a4934319a 100644 --- a/pkg/registry/core/trace/ns_registry.go +++ b/pkg/registry/core/trace/ns_registry.go @@ -28,6 +28,8 @@ import ( "github.com/networkservicemesh/sdk/pkg/registry/core/trace/traceconcise" "github.com/networkservicemesh/sdk/pkg/registry/core/trace/traceverbose" + "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/log/logruslogger" ) type traceNetworkServiceRegistryClient struct { @@ -50,6 +52,9 @@ func (t *traceNetworkServiceRegistryClient) Register(ctx context.Context, in *re if logrus.GetLevel() >= logrus.DebugLevel { return t.verbose.Register(ctx, in, opts...) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Register(ctx, in, opts...) } func (t *traceNetworkServiceRegistryClient) Find(ctx context.Context, in *registry.NetworkServiceQuery, opts ...grpc.CallOption) (registry.NetworkServiceRegistry_FindClient, error) { @@ -59,6 +64,9 @@ func (t *traceNetworkServiceRegistryClient) Find(ctx context.Context, in *regist if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Find(ctx, in, opts...) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Find(ctx, in, opts...) } @@ -69,6 +77,9 @@ func (t *traceNetworkServiceRegistryClient) Unregister(ctx context.Context, in * if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Unregister(ctx, in, opts...) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Unregister(ctx, in, opts...) } @@ -92,6 +103,9 @@ func (t *traceNetworkServiceRegistryServer) Register(ctx context.Context, in *re if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Register(ctx, in) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Register(ctx, in) } @@ -112,5 +126,8 @@ func (t *traceNetworkServiceRegistryServer) Unregister(ctx context.Context, in * if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Unregister(ctx, in) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Unregister(ctx, in) } diff --git a/pkg/registry/core/trace/nse_registry.go b/pkg/registry/core/trace/nse_registry.go index 52564eba3..b4f14ab46 100644 --- a/pkg/registry/core/trace/nse_registry.go +++ b/pkg/registry/core/trace/nse_registry.go @@ -27,6 +27,8 @@ import ( "github.com/networkservicemesh/sdk/pkg/registry/core/trace/traceconcise" "github.com/networkservicemesh/sdk/pkg/registry/core/trace/traceverbose" + "github.com/networkservicemesh/sdk/pkg/tools/log" + "github.com/networkservicemesh/sdk/pkg/tools/log/logruslogger" ) type traceNetworkServiceEndpointRegistryClient struct { @@ -59,6 +61,9 @@ func (t *traceNetworkServiceEndpointRegistryClient) Find(ctx context.Context, in if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Find(ctx, in, opts...) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Find(ctx, in, opts...) } @@ -69,6 +74,9 @@ func (t *traceNetworkServiceEndpointRegistryClient) Unregister(ctx context.Conte if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Unregister(ctx, in, opts...) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Unregister(ctx, in, opts...) } @@ -92,6 +100,9 @@ func (t *traceNetworkServiceEndpointRegistryServer) Register(ctx context.Context if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Register(ctx, in) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Register(ctx, in) } @@ -112,5 +123,8 @@ func (t *traceNetworkServiceEndpointRegistryServer) Unregister(ctx context.Conte if logrus.GetLevel() <= logrus.WarnLevel { return t.concise.Unregister(ctx, in) } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } return t.original.Unregister(ctx, in) }