add additional logging context (#482) (#516)

resolver/upstream_resolver.go

@@ -25,6 +25,7 @@ import (
 const (
 	dnsContentType             = "application/dns-message"
 	defaultTLSHandshakeTimeout = 5 * time.Second
+	retryAttempts              = 3
 )
 
 // nolint:gochecknoglobals
@@ -140,14 +141,14 @@ func (r *httpUpstreamClient) callExternal(msg *dns.Msg,
 
 	body, err := ioutil.ReadAll(httpResponse.Body)
 	if err != nil {
-		return nil, 0, errors.New("can't read response body")
+		return nil, 0, fmt.Errorf("can't read response body:  %w", err)
 	}
 
 	response := dns.Msg{}
 	err = response.Unpack(body)
 
 	if err != nil {
-		return nil, 0, errors.New("can't unpack message")
+		return nil, 0, fmt.Errorf("can't unpack message: %w", err)
 	}
 
 	return &response, time.Since(start), nil
@@ -215,8 +216,6 @@ func (r UpstreamResolver) String() string {
 
 // Resolve calls external resolver
 func (r *UpstreamResolver) Resolve(request *model.Request) (response *model.Response, err error) {
-	const retryAttempts = 3
-
 	logger := withPrefix(request.Log, "upstream_resolver")
 
 	ips, err := r.bootstrap.UpstreamIPs(r)
@@ -247,9 +246,11 @@ func (r *UpstreamResolver) Resolve(request *model.Request) (response *model.Resp
 					"net":              r.upstream.Net,
 					"response_time_ms": rtt.Milliseconds(),
 				}).Debugf("received response from upstream")
+
+				return nil
 			}
 
-			return err
+			return fmt.Errorf("can't resolve request via upstream server %s: %w", upstreamURL, err)
 		},
 		retry.Attempts(retryAttempts),
 		retry.DelayType(retry.FixedDelay),

resolver/upstream_resolver_test.go

@@ -167,7 +167,7 @@ var _ = Describe("UpstreamResolver", Label("upstreamResolver"), func() {
 			It("should return error", func() {
 				_, err := sut.Resolve(newRequest("example.com.", dns.Type(dns.TypeA)))
 				Expect(err).Should(HaveOccurred())
-				Expect(err.Error()).Should(Equal("http return code should be 200, but received 500"))
+				Expect(err.Error()).Should(ContainSubstring("http return code should be 200, but received 500"))
 			})
 		})
 		When("Configured DOH resolver returns wrong content type", func() {
@@ -179,7 +179,8 @@ var _ = Describe("UpstreamResolver", Label("upstreamResolver"), func() {
 			It("should return error", func() {
 				_, err := sut.Resolve(newRequest("example.com.", dns.Type(dns.TypeA)))
 				Expect(err).Should(HaveOccurred())
-				Expect(err.Error()).Should(Equal("http return content type should be 'application/dns-message', but was 'text'"))
+				Expect(err.Error()).Should(
+					ContainSubstring("http return content type should be 'application/dns-message', but was 'text'"))
 			})
 		})
 		When("Configured DOH resolver returns wrong content", func() {
@@ -191,7 +192,7 @@ var _ = Describe("UpstreamResolver", Label("upstreamResolver"), func() {
 			It("should return error", func() {
 				_, err := sut.Resolve(newRequest("example.com.", dns.Type(dns.TypeA)))
 				Expect(err).Should(HaveOccurred())
-				Expect(err.Error()).Should(Equal("can't unpack message"))
+				Expect(err.Error()).Should(ContainSubstring("can't unpack message"))
 			})
 		})
 		When("Configured DOH resolver does not respond", func() {

server/server.go

@@ -429,7 +429,7 @@ func (s *Server) OnRequest(w dns.ResponseWriter, request *dns.Msg) {
 	response, err := s.queryResolver.Resolve(r)
 
 	if err != nil {
-		logger().Errorf("error on processing request: %v", err)
+		logger().Error("error on processing request:", err)
 
 		m := new(dns.Msg)
 		m.SetRcode(request, dns.RcodeServerFailure)