diff --git a/go.mod b/go.mod index 750b26b14..a19118b5a 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/README.md b/pkg/networkservice/core/trace/README.md new file mode 100644 index 000000000..f0c0b3ef7 --- /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_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 + +``` + + +**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_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/client.go b/pkg/networkservice/core/trace/client.go index 3a5a6446c..cc6cf4882 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 // @@ -29,30 +29,47 @@ 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 { - 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 { + 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.TraceLevel { + 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 { 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..4f702aa80 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 // @@ -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" @@ -30,27 +32,40 @@ 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 { + 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) } + 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 { + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } + 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..bdcbbd079 --- /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_NoDiff_Trace(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..b631cd1a8 --- /dev/null +++ b/pkg/networkservice/core/trace/server_test.go @@ -0,0 +1,276 @@ +// 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/networkservice/utils/checks/checkcontext" + "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() + [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() + [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() + [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() + [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) + + 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() + [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() + [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() + [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; + [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; +` + result := testutil.TrimLogTime(&buff) + + result = testutil.Normalize(result) + expectedOutput = testutil.Normalize(expectedOutput) + + 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 + 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..7f0c1ee04 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.ConvertBytesToString(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..99b766b79 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,12 +206,17 @@ 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.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } 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..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"); @@ -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_registry.go b/pkg/registry/core/trace/ns_registry.go index 89307f79b..a4934319a 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 // @@ -28,71 +28,106 @@ 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 { - 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...) + 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) { - 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...) + } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } + 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...) + } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } + 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) + } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } + 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) + } + 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/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_registry.go b/pkg/registry/core/trace/nse_registry.go index 246124c2e..b4f14ab46 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 // @@ -27,71 +27,104 @@ 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 { - 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...) + } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } + 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...) + } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } + 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) + } + if log.FromContext(ctx) == log.L() { + ctx = log.WithLog(ctx, logruslogger.New(ctx)) + } + 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) + } + 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_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..af71b1ba8 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.ConvertBytesToString(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..f6915c3cb 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.ConvertBytesToString(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..b5aec37aa 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.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/logruslogger/logruslogger.go b/pkg/tools/log/logruslogger/logruslogger.go index 41d9b3bc2..4e1136051 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.ConvertBytesToString(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.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/spanlogger/spanlogger.go b/pkg/tools/log/spanlogger/spanlogger.go index 64e3810f0..d92393648 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.ConvertBytesToString(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..d28550bca --- /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" + +// ConvertBytesToString converts slice of bytes to string via unsafe package with zero allocations. +// Note: slice MUST NOT be modified after using this function. +func ConvertBytesToString(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() }