Add tracing and logs to dns handlers (#1343)

* add logs to dns context functions

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* add tracing to dns handlers

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* resolve conflict

Signed-off-by: anastasia.malysheva <anastasia.malysheva@xored.com>

* use another diff package (looks better)

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* cleanup

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* add ResponseWriter wrapper

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* add ResponseWriter wrapper

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* add logResponse func

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* add wrapper on every trace chain element call (looks working)

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* cleanup

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* cleanup

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* resolve conflict

Signed-off-by: anastasia.malysheva <anastasia.malysheva@xored.com>

* apply review comments

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

* fix after go mod tidy

Signed-off-by: anastasia.malysheva <anastasia.malysheva@xored.com>

Signed-off-by: Nikita Skrynnik <nikita.skrynnik@xored.com>
Signed-off-by: anastasia.malysheva <anastasia.malysheva@xored.com>
Co-authored-by: Nikita Skrynnik <nikita.skrynnik@xored.com>

go.mod

@@ -21,6 +21,7 @@ require (
 	github.com/networkservicemesh/api v1.4.1-0.20220711153918-a59689088578
 	github.com/open-policy-agent/opa v0.43.0
 	github.com/pkg/errors v0.9.1
+	github.com/r3labs/diff v1.1.0
 	github.com/sirupsen/logrus v1.9.0
 	github.com/spiffe/go-spiffe/v2 v2.0.0
 	github.com/stretchr/testify v1.8.0

go.sum

@@ -904,6 +904,8 @@ github.com/prometheus/procfs v0.6.0/go.mod h1:cz+aTbrPOrUb4q7XlbU9ygM+/jj0fzG6c1
 github.com/prometheus/procfs v0.7.3 h1:4jVXhlkAyzOScmCkXBTOLRLTz8EeU+eyjrwB/EPq0VU=
 github.com/prometheus/procfs v0.7.3/go.mod h1:cz+aTbrPOrUb4q7XlbU9ygM+/jj0fzG6c1xBZuNvfVA=
 github.com/prometheus/tsdb v0.7.1/go.mod h1:qhTCs0VvXwvX/y3TZrWD7rabWM+ijKTux40TwIPHuXU=
+github.com/r3labs/diff v1.1.0 h1:V53xhrbTHrWFWq3gI4b94AjgEJOerO1+1l0xyHOBi8M=
+github.com/r3labs/diff v1.1.0/go.mod h1:7WjXasNzi0vJetRcB/RqNl5dlIsmXcTTLmF5IoH6Xig=
 github.com/rabbitmq/amqp091-go v1.1.0/go.mod h1:ogQDLSOACsLPsIq0NpbtiifNZi2YOz0VTJ0kHRghqbM=
 github.com/rcrowley/go-metrics v0.0.0-20200313005456-10cdbea86bc0/go.mod h1:bCqnVzQkZxMG4s8nGwiZ5l3QUCyqpo9Y+/ZMZ9VjZe4=
 github.com/rcrowley/go-metrics v0.0.0-20201227073835-cf1acfcdf475 h1:N/ElC8H3+5XpJzTSTfLsJV/mx9Q9g7kxmchpfZyxgzM=

pkg/tools/clienturlctx/context.go

@@ -58,6 +58,7 @@ func WithClientURLs(parent context.Context, urls []url.URL) context.Context {
 	if parent == nil {
 		panic("cannot create context from nil parent")
 	}
+	log.FromContext(parent).Debugf("passed clientURLs: %v", urls)
 	return context.WithValue(parent, clientURLsKey, urls)
 }
 

pkg/tools/dnsutils/chain/server.go

@@ -0,0 +1,31 @@
+// Copyright (c) 2022 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 chain provides a simple file for creating a dnsutils.Handler from a 'chain' of dnsutils.Handler
+package chain
+
+import (
+	"github.com/networkservicemesh/sdk/pkg/tools/dnsutils"
+	"github.com/networkservicemesh/sdk/pkg/tools/dnsutils/next"
+	"github.com/networkservicemesh/sdk/pkg/tools/dnsutils/trace"
+)
+
+// NewDNSHandler - chains together a list of dnsutils.Handler with tracing
+func NewDNSHandler(handlers ...dnsutils.Handler) dnsutils.Handler {
+	return next.NewDNSHandler(
+		next.NewWrappedDNSHandler(trace.NewDNSHandler, handlers...),
+	)
+}

pkg/tools/dnsutils/fanout/handler.go

@@ -84,7 +84,7 @@ func (h *fanoutHandler) ServeDNS(ctx context.Context, rw dns.ResponseWriter, msg
 		return
 	}
 
-	next.Handler(ctx).ServeDNS(ctx, rw, resp)
+	next.Handler(ctx).ServeDNS(ctx, rw, msg)
 }
 
 func (h *fanoutHandler) waitResponse(ctx context.Context, respCh <-chan *dns.Msg) *dns.Msg {

pkg/tools/dnsutils/next/next.go

@@ -25,17 +25,29 @@ import (
 	"github.com/networkservicemesh/sdk/pkg/tools/dnsutils"
 )
 
-// NewDNSHandler creates a new chain of dns handlers
-func NewDNSHandler(handlers ...dnsutils.Handler) dnsutils.Handler {
-	return &nextDNSHandler{handlers: handlers}
-}
-
 type nextDNSHandler struct {
 	handlers   []dnsutils.Handler
 	index      int
 	nextParent dnsutils.Handler
 }
 
+// ServerWrapper - A function that wraps a dnsutils.Handler
+type ServerWrapper func(dnsutils.Handler) dnsutils.Handler
+
+// NewWrappedDNSHandler - chains together the servers provides with the wrapper wrapped around each one in turn.
+func NewWrappedDNSHandler(wrapper ServerWrapper, handlers ...dnsutils.Handler) dnsutils.Handler {
+	rv := &nextDNSHandler{handlers: make([]dnsutils.Handler, 0, len(handlers))}
+	for _, h := range handlers {
+		rv.handlers = append(rv.handlers, wrapper(h))
+	}
+	return rv
+}
+
+// NewDNSHandler creates a new chain of dns handlers
+func NewDNSHandler(handlers ...dnsutils.Handler) dnsutils.Handler {
+	return &nextDNSHandler{handlers: handlers}
+}
+
 func (n *nextDNSHandler) ServeDNS(ctx context.Context, rp dns.ResponseWriter, m *dns.Msg) {
 	nextHandler, nextCtx := n.getClientAndContext(ctx)
 	nextHandler.ServeDNS(nextCtx, rp, m)

pkg/tools/dnsutils/searches/context.go

@@ -18,6 +18,8 @@ package searches
 
 import (
 	"context"
+
+	"github.com/networkservicemesh/sdk/pkg/tools/log"
 )
 
 const (
@@ -31,6 +33,7 @@ func WithSearchDomains(parent context.Context, domains []string) context.Context
 	if parent == nil {
 		panic("cannot create context from nil parent")
 	}
+	log.FromContext(parent).Debugf("passed SearchDomains: %v", domains)
 	return context.WithValue(parent, searchDomainsKey, domains)
 }
 

pkg/tools/dnsutils/trace/common.go

@@ -0,0 +1,80 @@
+// Copyright (c) 2022 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
+
+import (
+	"context"
+	"encoding/json"
+	"fmt"
+	"strings"
+
+	"github.com/google/go-cmp/cmp"
+	"github.com/miekg/dns"
+	"github.com/r3labs/diff"
+
+	"github.com/networkservicemesh/sdk/pkg/tools/log"
+)
+
+func logRequest(ctx context.Context, message *dns.Msg, prefixes ...string) {
+	msg := strings.Join(append(prefixes, "request"), "-")
+	diffMsg := strings.Join(append(prefixes, "request", "diff"), "-")
+
+	messageInfo, ok := trace(ctx)
+	if ok && !cmp.Equal(messageInfo.RequestMsg, message) {
+		if messageInfo.RequestMsg != nil {
+			messageDiff, _ := diff.Diff(messageInfo.RequestMsg, message)
+			if len(messageDiff) > 0 {
+				logObjectTrace(ctx, diffMsg, messageDiff)
+			}
+		} else {
+			logObjectTrace(ctx, msg, message)
+		}
+		messageInfo.RequestMsg = message.Copy()
+		return
+	}
+}
+
+func logResponse(ctx context.Context, message *dns.Msg, prefixes ...string) {
+	msg := strings.Join(append(prefixes, "response"), "-")
+	diffMsg := strings.Join(append(prefixes, "response", "diff"), "-")
+
+	messageInfo, ok := trace(ctx)
+	if ok && !cmp.Equal(messageInfo.ResponseMsg, message) {
+		if messageInfo.ResponseMsg != nil {
+			messageDiff, _ := diff.Diff(messageInfo.ResponseMsg, message)
+			if len(messageDiff) > 0 {
+				logObjectTrace(ctx, diffMsg, messageDiff)
+			}
+		} else {
+			logObjectTrace(ctx, msg, message)
+		}
+		messageInfo.ResponseMsg = message.Copy()
+		return
+	}
+}
+
+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)
+}

pkg/tools/dnsutils/trace/context.go

@@ -0,0 +1,72 @@
+// Copyright (c) 2020-2022 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 provides a wrapper for tracing around a dnsutils.Handler
+package trace
+
+import (
+	"context"
+
+	"github.com/miekg/dns"
+
+	"github.com/networkservicemesh/sdk/pkg/tools/log"
+	"github.com/networkservicemesh/sdk/pkg/tools/log/logruslogger"
+	"github.com/networkservicemesh/sdk/pkg/tools/log/spanlogger"
+)
+
+type contextKeyType string
+
+const (
+	traceInfoKey contextKeyType = "MessageInfo"
+	loggedType   string         = "dnsServer"
+)
+
+type traceInfo struct {
+	RequestMsg  *dns.Msg
+	ResponseMsg *dns.Msg
+}
+
+func withLog(parent context.Context, operation, messageID string) (c context.Context, f func()) {
+	if parent == nil {
+		panic("cannot create context from nil parent")
+	}
+
+	if log.IsTracingEnabled() {
+		ctx, sLogger, span, sFinish := spanlogger.FromContext(parent, operation, map[string]interface{}{"type": loggedType, "id": messageID})
+		ctx, lLogger, lFinish := logruslogger.FromSpan(ctx, span, operation, map[string]interface{}{"type": loggedType, "id": messageID})
+		return withTrace(log.WithLog(ctx, sLogger, lLogger)), func() {
+			sFinish()
+			lFinish()
+		}
+	}
+	return log.WithLog(parent), func() {}
+}
+
+func withTrace(parent context.Context) context.Context {
+	if parent == nil {
+		panic("cannot create context from nil parent")
+	}
+	if _, ok := trace(parent); ok {
+		return parent
+	}
+
+	return context.WithValue(parent, traceInfoKey, &traceInfo{})
+}
+
+func trace(ctx context.Context) (*traceInfo, bool) {
+	val, ok := ctx.Value(traceInfoKey).(*traceInfo)
+	return val, ok
+}

pkg/tools/dnsutils/trace/handler.go

@@ -0,0 +1,85 @@
+// Copyright (c) 2022 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
+
+import (
+	"context"
+	"strconv"
+
+	"github.com/miekg/dns"
+
+	"github.com/networkservicemesh/sdk/pkg/tools/dnsutils"
+	"github.com/networkservicemesh/sdk/pkg/tools/dnsutils/next"
+	"github.com/networkservicemesh/sdk/pkg/tools/typeutils"
+)
+
+type beginTraceHandler struct {
+	traced dnsutils.Handler
+}
+
+type endTraceHandler struct{}
+
+// NewDNSHandler - wraps tracing around the supplied traced
+func NewDNSHandler(traced dnsutils.Handler) dnsutils.Handler {
+	return next.NewDNSHandler(
+		&beginTraceHandler{traced: traced},
+		&endTraceHandler{},
+	)
+}
+
+func (t *beginTraceHandler) ServeDNS(ctx context.Context, rw dns.ResponseWriter, m *dns.Msg) {
+	operation := typeutils.GetFuncName(t.traced, "ServeDNS")
+	ctx, finish := withLog(ctx, operation, strconv.Itoa(int(m.Id)))
+	defer finish()
+
+	logRequest(ctx, m, "message")
+
+	wrapper := wrapResponseWriter(rw)
+	t.traced.ServeDNS(ctx, wrapper, m)
+
+	logResponse(ctx, &wrapper.responseMsg, "message")
+}
+
+func (t *endTraceHandler) ServeDNS(ctx context.Context, rw dns.ResponseWriter, m *dns.Msg) {
+	logRequest(ctx, m, "message")
+
+	wrapper := wrapResponseWriter(rw)
+	next.Handler(ctx).ServeDNS(ctx, wrapper, m)
+
+	logResponse(ctx, &wrapper.responseMsg, "message")
+}
+
+func wrapResponseWriter(rw dns.ResponseWriter) *traceResponseWriter {
+	wrapper, ok := rw.(*traceResponseWriter)
+	if !ok {
+		wrapper = &traceResponseWriter{
+			ResponseWriter: rw,
+		}
+	}
+
+	return wrapper
+}
+
+type traceResponseWriter struct {
+	dns.ResponseWriter
+	responseMsg dns.Msg
+}
+
+func (rw *traceResponseWriter) WriteMsg(m *dns.Msg) error {
+	rw.responseMsg = *m.Copy()
+	return rw.ResponseWriter.WriteMsg(m)
+}