Logging request / response body should not allocate

Putting string(data) in the critical path causes an allocation which can be very large, and happens regardless of whether logging is enabled. Also, use the more sophisticated logging of body output that avoids causing quoting of JSON output (current behavior is "{\"key\":...}" and should be {"key":...} for readability).
parent 8ccecf93
...@@ -540,10 +540,10 @@ func (r *Request) Body(obj interface{}) *Request { ...@@ -540,10 +540,10 @@ func (r *Request) Body(obj interface{}) *Request {
r.err = err r.err = err
return r return r
} }
glog.V(8).Infof("Request Body: %#v", string(data)) glogBody("Request Body", data)
r.body = bytes.NewReader(data) r.body = bytes.NewReader(data)
case []byte: case []byte:
glog.V(8).Infof("Request Body: %#v", string(t)) glogBody("Request Body", t)
r.body = bytes.NewReader(t) r.body = bytes.NewReader(t)
case io.Reader: case io.Reader:
r.body = t r.body = t
...@@ -557,7 +557,7 @@ func (r *Request) Body(obj interface{}) *Request { ...@@ -557,7 +557,7 @@ func (r *Request) Body(obj interface{}) *Request {
r.err = err r.err = err
return r return r
} }
glog.V(8).Infof("Request Body: %#v", string(data)) glogBody("Request Body", data)
r.body = bytes.NewReader(data) r.body = bytes.NewReader(data)
r.SetHeader("Content-Type", r.content.ContentType) r.SetHeader("Content-Type", r.content.ContentType)
default: default:
...@@ -878,6 +878,7 @@ func (r *Request) DoRaw() ([]byte, error) { ...@@ -878,6 +878,7 @@ func (r *Request) DoRaw() ([]byte, error) {
var result Result var result Result
err := r.request(func(req *http.Request, resp *http.Response) { err := r.request(func(req *http.Request, resp *http.Response) {
result.body, result.err = ioutil.ReadAll(resp.Body) result.body, result.err = ioutil.ReadAll(resp.Body)
glogBody("Response Body", result.body)
if resp.StatusCode < http.StatusOK || resp.StatusCode > http.StatusPartialContent { if resp.StatusCode < http.StatusOK || resp.StatusCode > http.StatusPartialContent {
result.err = r.transformUnstructuredResponseError(resp, req, result.body) result.err = r.transformUnstructuredResponseError(resp, req, result.body)
} }
...@@ -897,15 +898,7 @@ func (r *Request) transformResponse(resp *http.Response, req *http.Request) Resu ...@@ -897,15 +898,7 @@ func (r *Request) transformResponse(resp *http.Response, req *http.Request) Resu
} }
} }
if glog.V(8) { glogBody("Response Body", body)
if bytes.IndexFunc(body, func(r rune) bool {
return r < 0x0a
}) != -1 {
glog.Infof("Response Body:\n%s", hex.Dump(body))
} else {
glog.Infof("Response Body: %s", string(body))
}
}
// verify the content type is accurate // verify the content type is accurate
contentType := resp.Header.Get("Content-Type") contentType := resp.Header.Get("Content-Type")
...@@ -957,6 +950,21 @@ func (r *Request) transformResponse(resp *http.Response, req *http.Request) Resu ...@@ -957,6 +950,21 @@ func (r *Request) transformResponse(resp *http.Response, req *http.Request) Resu
} }
} }
// glogBody logs a body output that could be either JSON or protobuf. It explicitly guards against
// allocating a new string for the body output unless necessary. Uses a simple heuristic to determine
// whether the body is printable.
func glogBody(prefix string, body []byte) {
if glog.V(8) {
if bytes.IndexFunc(body, func(r rune) bool {
return r < 0x0a
}) != -1 {
glog.Infof("%s:\n%s", prefix, hex.Dump(body))
} else {
glog.Infof("%s: %s", prefix, string(body))
}
}
}
// maxUnstructuredResponseTextBytes is an upper bound on how much output to include in the unstructured error. // maxUnstructuredResponseTextBytes is an upper bound on how much output to include in the unstructured error.
const maxUnstructuredResponseTextBytes = 2048 const maxUnstructuredResponseTextBytes = 2048
...@@ -994,7 +1002,6 @@ func (r *Request) newUnstructuredResponseError(body []byte, isTextResponse bool, ...@@ -994,7 +1002,6 @@ func (r *Request) newUnstructuredResponseError(body []byte, isTextResponse bool,
if len(body) > maxUnstructuredResponseTextBytes { if len(body) > maxUnstructuredResponseTextBytes {
body = body[:maxUnstructuredResponseTextBytes] body = body[:maxUnstructuredResponseTextBytes]
} }
glog.V(8).Infof("Response Body: %#v", string(body))
message := "unknown" message := "unknown"
if isTextResponse { if isTextResponse {
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment