logging: add debug logging for request and response #107

Merged
vtolstov merged 3 commits from logging into v3 2023-03-15 22:26:59 +03:00
4 changed files with 58 additions and 8 deletions
Showing only changes of commit 42bdd79b3d - Show all commits

2
go.mod
View File

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

14
http.go
View File

@ -19,6 +19,7 @@ import (
"go.unistack.org/micro/v3/client" "go.unistack.org/micro/v3/client"
"go.unistack.org/micro/v3/codec" "go.unistack.org/micro/v3/codec"
"go.unistack.org/micro/v3/errors" "go.unistack.org/micro/v3/errors"
"go.unistack.org/micro/v3/logger"
"go.unistack.org/micro/v3/metadata" "go.unistack.org/micro/v3/metadata"
"go.unistack.org/micro/v3/selector" "go.unistack.org/micro/v3/selector"
rutil "go.unistack.org/micro/v3/util/reflect" rutil "go.unistack.org/micro/v3/util/reflect"
@ -40,7 +41,7 @@ type httpClient struct {
init bool 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 tags []string
var parameters map[string]map[string]string var parameters map[string]map[string]string
scheme := "http" scheme := "http"
@ -210,6 +211,10 @@ func newRequest(ctx context.Context, addr string, req client.Request, ct string,
hreq.AddCookie(cookie) 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 return hreq, nil
} }
@ -221,9 +226,9 @@ func (h *httpClient) call(ctx context.Context, addr string, req client.Request,
cf, err := h.newCodec(ct) cf, err := h.newCodec(ct)
if err != nil { 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 { if err != nil {
return err return err
} }
@ -258,7 +263,7 @@ func (h *httpClient) stream(ctx context.Context, addr string, req client.Request
// get codec // get codec
cf, err := h.newCodec(ct) cf, err := h.newCodec(ct)
if err != nil { 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) 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{ return &httpStream{
address: addr, address: addr,
logger: h.opts.Logger,
context: ctx, context: ctx,
closed: make(chan bool), closed: make(chan bool),
opts: opts, opts: opts,

View File

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

20
util.go
View File

@ -1,9 +1,11 @@
package http package http
import ( import (
"bytes"
"context" "context"
"fmt" "fmt"
"io" "io"
"io/ioutil"
"net/http" "net/http"
"net/url" "net/url"
"reflect" "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) 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 // response like text/plain or something else, return original error
return errors.New("go.micro.client", string(buf), int32(hrsp.StatusCode)) return errors.New("go.micro.client", string(buf), int32(hrsp.StatusCode))
} else if cerr != nil { } 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()) 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 { if !ok || rerr == nil {
buf, rerr := io.ReadAll(hrsp.Body) 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 { if rerr != nil {
return errors.InternalServerError("go.micro.client", rerr.Error()) return errors.InternalServerError("go.micro.client", rerr.Error())
} }
return errors.New("go.micro.client", string(buf), int32(hrsp.StatusCode)) 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 { if cerr := cf.ReadBody(hrsp.Body, rerr); cerr != nil {
return errors.InternalServerError("go.micro.client", cerr.Error()) return errors.InternalServerError("go.micro.client", cerr.Error())
} }