Merge pull request 'logging: add debug logging for request and response' (#107) from logging into v3

Reviewed-on: #107

go.mod

@@ -1,5 +1,5 @@
 module go.unistack.org/micro-client-http/v3
 
-go 1.16
+go 1.18
 
-require go.unistack.org/micro/v3 v3.10.14
+require go.unistack.org/micro/v3 v3.10.16

go.sum

@@ -1,8 +1,8 @@
 github.com/imdario/mergo v0.3.13/go.mod h1:4lJ1jqUDcsbIECGy0RUJAXNIhg+6ocWgb1ALK2O4oXg=
 github.com/patrickmn/go-cache v2.1.0+incompatible/go.mod h1:3Qf8kWWT7OJRJbdiICTKqZju1ZixQ/KpMGzzAfe6+WQ=
 github.com/silas/dag v0.0.0-20211117232152-9d50aa809f35/go.mod h1:7RTUFBdIRC9nZ7/3RyRNH1bdqIShrDejd1YbLwgPS+I=
-go.unistack.org/micro/v3 v3.10.14 h1:7fgLpwGlCN67twhwtngJDEQvrMkUBDSA5vzZqxIDqNE=
+go.unistack.org/micro/v3 v3.10.16 h1:2er/SKKYbV60M+UuJM4eYCF0MZYAIq/yNUrAbTfgq8Q=
-go.unistack.org/micro/v3 v3.10.14/go.mod h1:uMAc0U/x7dmtICCrblGf0ZLgYegu3VwQAquu+OFCw1Q=
+go.unistack.org/micro/v3 v3.10.16/go.mod h1:uMAc0U/x7dmtICCrblGf0ZLgYegu3VwQAquu+OFCw1Q=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v3 v3.0.0/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

http.go

@@ -19,6 +19,7 @@ import (
 	"go.unistack.org/micro/v3/client"
 	"go.unistack.org/micro/v3/codec"
 	"go.unistack.org/micro/v3/errors"
+	"go.unistack.org/micro/v3/logger"
 	"go.unistack.org/micro/v3/metadata"
 	"go.unistack.org/micro/v3/selector"
 	rutil "go.unistack.org/micro/v3/util/reflect"
@@ -40,7 +41,7 @@ type httpClient struct {
 	init bool
 }
 
-func newRequest(ctx context.Context, addr string, req client.Request, ct string, cf codec.Codec, msg interface{}, opts client.CallOptions) (*http.Request, error) {
+func newRequest(ctx context.Context, log logger.Logger, addr string, req client.Request, ct string, cf codec.Codec, msg interface{}, opts client.CallOptions) (*http.Request, error) {
 	var tags []string
 	var parameters map[string]map[string]string
 	scheme := "http"
@@ -210,6 +211,10 @@ func newRequest(ctx context.Context, addr string, req client.Request, ct string,
 		hreq.AddCookie(cookie)
 	}
 
+	if log.V(logger.DebugLevel) {
+		log.Debugf(ctx, "request %s to %s with headers %v body %s", method, u.String(), hreq.Header, b)
+	}
+
 	return hreq, nil
 }
 
@@ -221,9 +226,9 @@ func (h *httpClient) call(ctx context.Context, addr string, req client.Request,
 
 	cf, err := h.newCodec(ct)
 	if err != nil {
-		return errors.InternalServerError("go.micro.client", err.Error())
+		return errors.BadRequest("go.micro.client", err.Error())
 	}
-	hreq, err := newRequest(ctx, addr, req, ct, cf, req.Body(), opts)
+	hreq, err := newRequest(ctx, h.opts.Logger, addr, req, ct, cf, req.Body(), opts)
 	if err != nil {
 		return err
 	}
@@ -258,7 +263,7 @@ func (h *httpClient) stream(ctx context.Context, addr string, req client.Request
 	// get codec
 	cf, err := h.newCodec(ct)
 	if err != nil {
-		return nil, errors.InternalServerError("go.micro.client", err.Error())
+		return nil, errors.BadRequest("go.micro.client", err.Error())
 	}
 
 	cc, err := (h.httpcli.Transport).(*http.Transport).DialContext(ctx, "tcp", addr)
@@ -268,6 +273,7 @@ func (h *httpClient) stream(ctx context.Context, addr string, req client.Request
 
 	return &httpStream{
 		address: addr,
+		logger:  h.opts.Logger,
 		context: ctx,
 		closed:  make(chan bool),
 		opts:    opts,

stream.go

@@ -2,9 +2,11 @@ package http
 
 import (
 	"bufio"
+	"bytes"
 	"context"
 	"fmt"
 	"io"
+	"io/ioutil"
 	"net"
 	"net/http"
 	"sync"
@@ -12,6 +14,7 @@ import (
 	"go.unistack.org/micro/v3/client"
 	"go.unistack.org/micro/v3/codec"
 	"go.unistack.org/micro/v3/errors"
+	"go.unistack.org/micro/v3/logger"
 )
 
 // Implements the streamer interface
@@ -20,6 +23,7 @@ type httpStream struct {
 	conn    net.Conn
 	cf      codec.Codec
 	context context.Context
+	logger  logger.Logger
 	request client.Request
 	closed  chan bool
 	reader  *bufio.Reader
@@ -65,7 +69,7 @@ func (h *httpStream) Send(msg interface{}) error {
 		return errShutdown
 	}
 
-	hreq, err := newRequest(h.context, h.address, h.request, h.ct, h.cf, msg, h.opts)
+	hreq, err := newRequest(h.context, h.logger, h.address, h.request, h.ct, h.cf, msg, h.opts)
 	if err != nil {
 		return err
 	}
@@ -92,7 +96,7 @@ func (h *httpStream) Recv(msg interface{}) error {
 	}
 	defer hrsp.Body.Close()
 
-	return h.parseRsp(h.context, hrsp, h.cf, msg, h.opts)
+	return h.parseRsp(h.context, h.logger, hrsp, h.cf, msg, h.opts)
 }
 
 func (h *httpStream) Error() error {
@@ -115,7 +119,7 @@ func (h *httpStream) Close() error {
 	}
 }
 
-func (h *httpStream) parseRsp(ctx context.Context, hrsp *http.Response, cf codec.Codec, rsp interface{}, opts client.CallOptions) error {
+func (h *httpStream) parseRsp(ctx context.Context, log logger.Logger, hrsp *http.Response, cf codec.Codec, rsp interface{}, opts client.CallOptions) error {
 	var err error
 
 	select {
@@ -128,6 +132,14 @@ func (h *httpStream) parseRsp(ctx context.Context, hrsp *http.Response, cf codec
 		}
 
 		if hrsp.StatusCode < 400 {
+			if log.V(logger.DebugLevel) {
+				buf, rerr := io.ReadAll(hrsp.Body)
+				log.Debugf(ctx, "response %s with %v", buf, hrsp.Header)
+				if err != nil {
+					return errors.InternalServerError("go.micro.client", rerr.Error())
+				}
+				hrsp.Body = ioutil.NopCloser(bytes.NewBuffer(buf))
+			}
 			if err = cf.ReadBody(hrsp.Body, rsp); err != nil {
 				return errors.InternalServerError("go.micro.client", err.Error())
 			}
@@ -142,12 +154,24 @@ func (h *httpStream) parseRsp(ctx context.Context, hrsp *http.Response, cf codec
 		}
 		if !ok || err == nil {
 			buf, cerr := io.ReadAll(hrsp.Body)
+			if log.V(logger.DebugLevel) {
+				log.Debugf(ctx, "response %s with %v", buf, hrsp.Header)
+			}
 			if cerr != nil {
 				return errors.InternalServerError("go.micro.client", cerr.Error())
 			}
 			return errors.New("go.micro.client", string(buf), int32(hrsp.StatusCode))
 		}
 
+		if log.V(logger.DebugLevel) {
+			buf, rerr := io.ReadAll(hrsp.Body)
+			log.Debugf(ctx, "response %s with %v", buf, hrsp.Header)
+			if err != nil {
+				return errors.InternalServerError("go.micro.client", rerr.Error())
+			}
+			hrsp.Body = ioutil.NopCloser(bytes.NewBuffer(buf))
+		}
+
 		if cerr := cf.ReadBody(hrsp.Body, err); cerr != nil {
 			err = errors.InternalServerError("go.micro.client", cerr.Error())
 		}

util.go

@@ -1,9 +1,11 @@
 package http
 
 import (
+	"bytes"
 	"context"
 	"fmt"
 	"io"
+	"io/ioutil"
 	"net/http"
 	"net/url"
 	"reflect"
@@ -269,9 +271,15 @@ func (h *httpClient) parseRsp(ctx context.Context, hrsp *http.Response, rsp inte
 					h.opts.Logger.Errorf(ctx, "failed to read body: %v", err)
 				}
 			}
+			if h.opts.Logger.V(logger.DebugLevel) {
+				h.opts.Logger.Debugf(ctx, "response %s with %v", buf, hrsp.Header)
+			}
 			// response like text/plain or something else, return original error
 			return errors.New("go.micro.client", string(buf), int32(hrsp.StatusCode))
 		} else if cerr != nil {
+			if h.opts.Logger.V(logger.DebugLevel) {
+				h.opts.Logger.Debugf(ctx, "response with %v unknown content-type", hrsp.Header, ct)
+			}
 			return errors.InternalServerError("go.micro.client", cerr.Error())
 		}
 
@@ -295,12 +303,24 @@ func (h *httpClient) parseRsp(ctx context.Context, hrsp *http.Response, rsp inte
 
 		if !ok || rerr == nil {
 			buf, rerr := io.ReadAll(hrsp.Body)
+			if h.opts.Logger.V(logger.DebugLevel) {
+				h.opts.Logger.Debugf(ctx, "response %s with %v", buf, hrsp.Header)
+			}
 			if rerr != nil {
 				return errors.InternalServerError("go.micro.client", rerr.Error())
 			}
 			return errors.New("go.micro.client", string(buf), int32(hrsp.StatusCode))
 		}
 
+		if h.opts.Logger.V(logger.DebugLevel) {
+			buf, rerr := io.ReadAll(hrsp.Body)
+			h.opts.Logger.Debugf(ctx, "response %s with %v", buf, hrsp.Header)
+			if err != nil {
+				return errors.InternalServerError("go.micro.client", rerr.Error())
+			}
+			hrsp.Body = ioutil.NopCloser(bytes.NewBuffer(buf))
+		}
+
 		if cerr := cf.ReadBody(hrsp.Body, rerr); cerr != nil {
 			return errors.InternalServerError("go.micro.client", cerr.Error())
 		}