elasticsearch: adds some more/better debug logging to client

pkg/tsdb/elasticsearch/client/client.go

@@ -119,6 +119,9 @@ type multiRequest struct {
 }
 }
 
 
 func (c *baseClientImpl) executeBatchRequest(uriPath string, requests []*multiRequest) (*http.Response, error) {
 func (c *baseClientImpl) executeBatchRequest(uriPath string, requests []*multiRequest) (*http.Response, error) {
+	clientLog.Debug("Encoding batch requests to json", "batch requests", len(requests))
+	start := time.Now()
+
 	payload := bytes.Buffer{}
 	payload := bytes.Buffer{}
 	for _, r := range requests {
 	for _, r := range requests {
 		reqHeader, err := json.Marshal(r.header)
 		reqHeader, err := json.Marshal(r.header)
@@ -134,6 +137,9 @@ func (c *baseClientImpl) executeBatchRequest(uriPath string, requests []*multiRe
 		payload.WriteString(string(reqBody) + "\n")
 		payload.WriteString(string(reqBody) + "\n")
 	}
 	}
 
 
+	elapsed := time.Now().Sub(start)
+	clientLog.Debug("Encoded batch requests to json", "took", elapsed)
+
 	return c.executeRequest(http.MethodPost, uriPath, payload.Bytes())
 	return c.executeRequest(http.MethodPost, uriPath, payload.Bytes())
 }
 }
 
 
@@ -151,6 +157,9 @@ func (c *baseClientImpl) executeRequest(method, uriPath string, body []byte) (*h
 	if err != nil {
 	if err != nil {
 		return nil, err
 		return nil, err
 	}
 	}
+
+	clientLog.Debug("Executing request", "url", req.URL.String(), "method", method)
+
 	req.Header.Set("User-Agent", "Grafana")
 	req.Header.Set("User-Agent", "Grafana")
 	req.Header.Set("Content-Type", "application/json")
 	req.Header.Set("Content-Type", "application/json")
 
 
@@ -169,22 +178,28 @@ func (c *baseClientImpl) executeRequest(method, uriPath string, body []byte) (*h
 		return nil, err
 		return nil, err
 	}
 	}
 
 
-	if method == http.MethodPost {
-		clientLog.Debug("Executing request", "url", req.URL.String(), "method", method)
-	} else {
-		clientLog.Debug("Executing request", "url", req.URL.String(), "method", method)
-	}
-
+	start := time.Now()
+	defer func() {
+		elapsed := time.Now().Sub(start)
+		clientLog.Debug("Executed request", "took", elapsed)
+	}()
 	return ctxhttp.Do(c.ctx, httpClient, req)
 	return ctxhttp.Do(c.ctx, httpClient, req)
 }
 }
 
 
 func (c *baseClientImpl) ExecuteMultisearch(r *MultiSearchRequest) (*MultiSearchResponse, error) {
 func (c *baseClientImpl) ExecuteMultisearch(r *MultiSearchRequest) (*MultiSearchResponse, error) {
+	clientLog.Debug("Executing multisearch", "search requests", len(r.Requests))
+
 	multiRequests := c.createMultiSearchRequests(r.Requests)
 	multiRequests := c.createMultiSearchRequests(r.Requests)
 	res, err := c.executeBatchRequest("_msearch", multiRequests)
 	res, err := c.executeBatchRequest("_msearch", multiRequests)
 	if err != nil {
 	if err != nil {
 		return nil, err
 		return nil, err
 	}
 	}
 
 
+	clientLog.Debug("Received multisearch response", "code", res.StatusCode, "status", res.Status, "content-length", res.ContentLength)
+
+	start := time.Now()
+	clientLog.Debug("Decoding multisearch json response")
+
 	var msr MultiSearchResponse
 	var msr MultiSearchResponse
 	defer res.Body.Close()
 	defer res.Body.Close()
 	dec := json.NewDecoder(res.Body)
 	dec := json.NewDecoder(res.Body)
@@ -193,7 +208,8 @@ func (c *baseClientImpl) ExecuteMultisearch(r *MultiSearchRequest) (*MultiSearch
 		return nil, err
 		return nil, err
 	}
 	}
 
 
-	clientLog.Debug("Received multisearch response", "code", res.StatusCode, "status", res.Status, "content-length", res.ContentLength)
+	elapsed := time.Now().Sub(start)
+	clientLog.Debug("Decoded multisearch json response", "took", elapsed)
 
 
 	msr.status = res.StatusCode
 	msr.status = res.StatusCode