diff --git a/pkg/networkservice/core/trace/README.md b/pkg/networkservice/core/trace/README.md index dfefaceba..f0c0b3ef7 100644 --- a/pkg/networkservice/core/trace/README.md +++ b/pkg/networkservice/core/trace/README.md @@ -14,7 +14,7 @@ Benchmark_LongRequest_Info-8 340 3765718 ns/op 273254 B/op Benchmark_ShortRequest_Trace-8 79 13600986 ns/op 344445 B/op 8475 allocs/op Benchmark_LongRequest_Trace-8 2 916385562 ns/op 20998324 B/op 694678 allocs/op -Benchmark_LongRequest_Trace_NoDiff-8 2 565520104 ns/op 12236116 B/op 585667 allocs/op +Benchmark_LongRequest_NoDiff_Trace-8 2 565520104 ns/op 12236116 B/op 585667 allocs/op Benchmark_LongRequest_Diff_Warn-8 340 3765718 ns/op 273254 B/op 861 allocs/op ``` @@ -28,7 +28,7 @@ Benchmark_LongRequest_Info-8 373 3064039 ns/op 253359 B/op Benchmark_ShortRequest_Trace-8 543 2599280 ns/op 237262 B/op 1825 allocs/op Benchmark_LongRequest_Trace-8 9 131145361 ns/op 22433480 B/op 20749 allocs/op -Benchmark_LongRequest_Trace_NoDiff-8 18 72167456 ns/op 10900859 B/op 13685 allocs/op +Benchmark_LongRequest_NoDiff_Trace-8 18 72167456 ns/op 10900859 B/op 13685 allocs/op Benchmark_LongRequest_Diff_Warn-8 31128 36019 ns/op 9600 B/op 200 allocs/op ``` diff --git a/pkg/networkservice/core/trace/server_bench_test.go b/pkg/networkservice/core/trace/server_bench_test.go index 5548feed9..bdcbbd079 100644 --- a/pkg/networkservice/core/trace/server_bench_test.go +++ b/pkg/networkservice/core/trace/server_bench_test.go @@ -140,7 +140,7 @@ func Benchmark_LongRequest_Trace(b *testing.B) { } } -func Benchmark_LongRequest_Trace_NoDiff(b *testing.B) { +func Benchmark_LongRequest_NoDiff_Trace(b *testing.B) { var s = newTestStaticServerChain(100) var request = newTestRequest(100) var ctx = context.Background() diff --git a/pkg/networkservice/core/trace/server_test.go b/pkg/networkservice/core/trace/server_test.go index 5ba8d1a48..71cbb12d3 100644 --- a/pkg/networkservice/core/trace/server_test.go +++ b/pkg/networkservice/core/trace/server_test.go @@ -97,21 +97,21 @@ func TestTraceOutput(t *testing.T) { require.NotNil(t, e) expectedOutput := ` [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Request() - [INFO] [id:conn-1] [type:networkService] (1.1) request={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} - [INFO] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (1.1) request={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Request() - [INFO] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} - [INFO] [id:conn-1] [type:networkService] (2.2) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} - [INFO] [id:conn-1] [type:networkService] (2.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"C"}} - [INFO] [id:conn-1] [type:networkService] (1.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} + [TRAC] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (2.2) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} + [TRAC] [id:conn-1] [type:networkService] (2.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"C"}} + [TRAC] [id:conn-1] [type:networkService] (1.3) request-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Close() - [INFO] [id:conn-1] [type:networkService] (1.1) close={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} - [INFO] [id:conn-1] [type:networkService] (1.2) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"W"}} + [TRAC] [id:conn-1] [type:networkService] (1.1) close={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"D"}} + [TRAC] [id:conn-1] [type:networkService] (1.2) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"W"}} [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Close() - [INFO] [id:conn-1] [type:networkService] (2.1) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} - [INFO] [id:conn-1] [type:networkService] (2.2) close-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} - [INFO] [id:conn-1] [type:networkService] (2.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Y"}} - [INFO] [id:conn-1] [type:networkService] (1.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Z"}} + [TRAC] [id:conn-1] [type:networkService] (2.1) close-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} + [TRAC] [id:conn-1] [type:networkService] (2.2) close-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"X"}} + [TRAC] [id:conn-1] [type:networkService] (2.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Y"}} + [TRAC] [id:conn-1] [type:networkService] (1.3) close-response-diff={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"Z"}} ` result := testutil.TrimLogTime(&buff) @@ -146,14 +146,14 @@ func TestErrorOutput(t *testing.T) { require.Nil(t, conn) expectedOutput := ` [TRAC] [id:conn-1] [type:networkService] (1) ⎆ testutil/LabelChangerFirstServer.Request() - [INFO] [id:conn-1] [type:networkService] (1.1) request={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} - [INFO] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (1.1) request={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (1.2) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"A"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} [TRAC] [id:conn-1] [type:networkService] (2) ⎆ testutil/LabelChangerSecondServer.Request() - [INFO] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} + [TRAC] [id:conn-1] [type:networkService] (2.1) request-diff={"connection":{"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}},"mechanism_preferences":[{"cls":"LOCAL","type":"KERNEL"},{"cls":"LOCAL","type":"KERNEL","parameters":{"label":"v2"}}]} [TRAC] [id:conn-1] [type:networkService] (3) ⎆ testutil/ErrorServer.Request() - [INFO] [id:conn-1] [type:networkService] (3.1) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} + [TRAC] [id:conn-1] [type:networkService] (3.1) request-response={"id":"conn-1","context":{"ip_context":{"src_ip_required":true}},"labels":{"Label":"B"}} [ERRO] [id:conn-1] [type:networkService] (3.2) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; - [INFO] [id:conn-1] [type:networkService] (2.2) request-response-diff=null + [TRAC] [id:conn-1] [type:networkService] (2.2) request-response-diff=null [ERRO] [id:conn-1] [type:networkService] (2.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; [ERRO] [id:conn-1] [type:networkService] (1.3) Error returned from api/pkg/api/networkservice/networkServiceClient.Close; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:85; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/trace/client.go:106; github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close; /root/go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210929180427-ec235de055f1/pkg/networkservice/core/next/client.go:65; ` diff --git a/pkg/networkservice/core/trace/traceconcise/common.go b/pkg/networkservice/core/trace/traceconcise/common.go index 6d9baa438..7f0c1ee04 100644 --- a/pkg/networkservice/core/trace/traceconcise/common.go +++ b/pkg/networkservice/core/trace/traceconcise/common.go @@ -55,7 +55,7 @@ func logObject(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/networkservice/core/trace/traceverbose/common.go b/pkg/networkservice/core/trace/traceverbose/common.go index 941206c0f..99b766b79 100644 --- a/pkg/networkservice/core/trace/traceverbose/common.go +++ b/pkg/networkservice/core/trace/traceverbose/common.go @@ -216,9 +216,9 @@ func logObjectTrace(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } - s.Infof("%v=%s", k, msg) + s.Tracef("%v=%s", k, msg) } diff --git a/pkg/registry/core/trace/traceconcise/common.go b/pkg/registry/core/trace/traceconcise/common.go index 058b13d0d..af71b1ba8 100644 --- a/pkg/registry/core/trace/traceconcise/common.go +++ b/pkg/registry/core/trace/traceconcise/common.go @@ -44,7 +44,7 @@ func logObject(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/registry/core/trace/traceverbose/common.go b/pkg/registry/core/trace/traceverbose/common.go index e17b4edb9..f6915c3cb 100644 --- a/pkg/registry/core/trace/traceverbose/common.go +++ b/pkg/registry/core/trace/traceverbose/common.go @@ -58,7 +58,7 @@ func logObjectTrace(ctx context.Context, k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/defaultlogger.go b/pkg/tools/log/defaultlogger.go index 93e28503b..b5aec37aa 100644 --- a/pkg/tools/log/defaultlogger.go +++ b/pkg/tools/log/defaultlogger.go @@ -92,7 +92,7 @@ func (l *defaultLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/logruslogger/logruslogger.go b/pkg/tools/log/logruslogger/logruslogger.go index b6fb71da9..4e1136051 100644 --- a/pkg/tools/log/logruslogger/logruslogger.go +++ b/pkg/tools/log/logruslogger/logruslogger.go @@ -93,7 +93,7 @@ func (s *logrusLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } @@ -197,7 +197,7 @@ func (s *traceLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/log/spanlogger/spanlogger.go b/pkg/tools/log/spanlogger/spanlogger.go index 2f7249c6a..d92393648 100644 --- a/pkg/tools/log/spanlogger/spanlogger.go +++ b/pkg/tools/log/spanlogger/spanlogger.go @@ -93,7 +93,7 @@ func (s *spanLogger) Object(k, v interface{}) { msg := "" cc, err := json.Marshal(v) if err == nil { - msg = stringutils.CovertBytesToString(cc) + msg = stringutils.ConvertBytesToString(cc) } else { msg = fmt.Sprint(v) } diff --git a/pkg/tools/stringutils/stringutils.go b/pkg/tools/stringutils/stringutils.go index 9a3ac3fd5..d28550bca 100644 --- a/pkg/tools/stringutils/stringutils.go +++ b/pkg/tools/stringutils/stringutils.go @@ -19,9 +19,9 @@ package stringutils import "unsafe" -// CovertBytesToString converts slice of bytes to string via unsafe package with zero allocations. +// ConvertBytesToString converts slice of bytes to string via unsafe package with zero allocations. // Note: slice MUST NOT be modified after using this function. -func CovertBytesToString(slice []byte) string { +func ConvertBytesToString(slice []byte) string { // nolint return *(*string)(unsafe.Pointer(&slice)) }