fix (daemon) : Add logging to provide additional information for non-200 status codes (#3766)

cmd/crc/cmd/custom_response_writer.go

@@ -0,0 +1,49 @@
+package cmd
+
+import (
+	"bytes"
+	"net/http"
+)
+
+// CustomResponseWriter wraps the standard http.ResponseWriter and captures the response body
+type CustomResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+	body       *bytes.Buffer
+}
+
+// NewCustomResponseWriter creates a new CustomResponseWriter
+func NewCustomResponseWriter(w http.ResponseWriter) *CustomResponseWriter {
+	return &CustomResponseWriter{
+		ResponseWriter: w,
+		statusCode:     http.StatusOK,
+		body:           &bytes.Buffer{},
+	}
+}
+
+// WriteHeader allows capturing and modifying the status code
+func (rw *CustomResponseWriter) WriteHeader(statusCode int) {
+	rw.statusCode = statusCode
+	rw.ResponseWriter.WriteHeader(statusCode)
+}
+
+// Write captures the response body and logs it
+func (rw *CustomResponseWriter) Write(p []byte) (int, error) {
+	bufferLen, err := rw.body.Write(p)
+	if err != nil {
+		return bufferLen, err
+	}
+
+	return rw.ResponseWriter.Write(p)
+}
+
+// interceptResponseBodyMiddleware injects the custom bodyConsumer function (received as second argument) into
+// http.HandleFunc logic that allows users to intercept response body as per their requirements (e.g. logging)
+// and returns updated http.Handler
+func interceptResponseBodyMiddleware(next http.Handler, bodyConsumer func(statusCode int, buffer *bytes.Buffer, r *http.Request)) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		responseWriter := NewCustomResponseWriter(w)
+		next.ServeHTTP(responseWriter, r)
+		bodyConsumer(responseWriter.statusCode, responseWriter.body, r)
+	})
+}

cmd/crc/cmd/custom_response_writer_test.go

@@ -0,0 +1,51 @@
+package cmd
+
+import (
+	"bytes"
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+type TestHandler struct {
+}
+
+func (t *TestHandler) ServeHTTP(w http.ResponseWriter, _ *http.Request) {
+	_, err := fmt.Fprint(w, "Testing!")
+	if err != nil {
+		return
+	}
+}
+
+func TestLogResponseBodyMiddlewareCapturesResponseAsExpected(t *testing.T) {
+	// Given
+	interceptedResponseStatusCode := -1
+	interceptedResponseBody := ""
+	responseBodyConsumer := func(statusCode int, buffer *bytes.Buffer, _ *http.Request) {
+		interceptedResponseStatusCode = statusCode
+		interceptedResponseBody = buffer.String()
+	}
+	testHandler := &TestHandler{}
+	server := httptest.NewServer(interceptResponseBodyMiddleware(http.StripPrefix("/", testHandler), responseBodyConsumer))
+	defer server.Close()
+	// When
+	resp, err := http.Get(server.URL)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	// Then
+	responseBody := new(bytes.Buffer)
+	bytesRead, err := responseBody.ReadFrom(resp.Body)
+	if err != nil {
+		t.Fatal(err)
+	}
+	assert.Equal(t, 200, resp.StatusCode)
+	assert.Equal(t, 200, interceptedResponseStatusCode)
+	assert.Equal(t, int64(8), bytesRead)
+	assert.Equal(t, "Testing!", responseBody.String())
+	assert.Equal(t, "Testing!", interceptedResponseBody)
+}

cmd/crc/cmd/daemon.go

@@ -1,6 +1,7 @@
 package cmd
 
 import (
+	"bytes"
 	"encoding/json"
 	"fmt"
 	"io"
@@ -142,10 +143,10 @@ func run(configuration *types.Configuration) error {
 			return
 		}
 		mux := http.NewServeMux()
-		mux.Handle("/network/", http.StripPrefix("/network", vn.Mux()))
+		mux.Handle("/network/", interceptResponseBodyMiddleware(http.StripPrefix("/network", vn.Mux()), logResponseBodyConditionally))
 		machineClient := newMachine()
-		mux.Handle("/api/", http.StripPrefix("/api", api.NewMux(config, machineClient, logging.Memory, segmentClient)))
-		mux.Handle("/events", http.StripPrefix("/events", events.NewEventServer(machineClient)))
+		mux.Handle("/api/", interceptResponseBodyMiddleware(http.StripPrefix("/api", api.NewMux(config, machineClient, logging.Memory, segmentClient)), logResponseBodyConditionally))
+		mux.Handle("/events", interceptResponseBodyMiddleware(http.StripPrefix("/events", events.NewEventServer(machineClient)), logResponseBodyConditionally))
 		s := &http.Server{
 			Handler:           handlers.LoggingHandler(os.Stderr, mux),
 			ReadHeaderTimeout: 10 * time.Second,
@@ -271,3 +272,11 @@ func acceptJSONStringArray(w http.ResponseWriter, r *http.Request, fun func(host
 	}
 	w.WriteHeader(http.StatusOK)
 }
+
+func logResponseBodyConditionally(statusCode int, buffer *bytes.Buffer, r *http.Request) {
+	responseBody := buffer.String()
+	if statusCode != http.StatusOK && responseBody != "" {
+		log.Errorf("[%s] \"%s %s\" Response Body: %s\n", time.Now().Format("02/Jan/2006:15:04:05 -0700"),
+			r.Method, r.URL.Path, buffer.String())
+	}
+}

cmd/crc/cmd/daemon_test.go

@@ -0,0 +1,55 @@
+package cmd
+
+import (
+	"bytes"
+	"net/http"
+	"net/url"
+	"os"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestLogResponseBodyLogsResponseBodyForFailedResponseCodes(t *testing.T) {
+	// Given
+	var logBuffer bytes.Buffer
+	var responseBuffer bytes.Buffer
+	responseBuffer.WriteString("{\"status\": \"FAILURE\"}")
+	logrus.SetOutput(&logBuffer)
+	defer logrus.SetOutput(os.Stdout)
+	requestURL, err := url.Parse("http://127.0.0.1/log")
+	assert.NoError(t, err)
+	httpRequest := &http.Request{
+		Method: "GET",
+		URL:    requestURL,
+	}
+
+	// When
+	logResponseBodyConditionally(500, &responseBuffer, httpRequest)
+
+	// Then
+	assert.Greater(t, logBuffer.Len(), 0)
+	assert.Contains(t, logBuffer.String(), ("\\\"GET /log\\\" Response Body: {\\\"status\\\": \\\"FAILURE\\\"}"))
+}
+
+func TestLogResponseBodyLogsNothingWhenResponseSuccessful(t *testing.T) {
+	// Given
+	var logBuffer bytes.Buffer
+	var responseBuffer bytes.Buffer
+	responseBuffer.WriteString("{\"status\": \"SUCCESS\"}")
+	logrus.SetOutput(&logBuffer)
+	defer logrus.SetOutput(os.Stdout)
+	requestURL, err := url.Parse("http://127.0.0.1/log")
+	assert.NoError(t, err)
+	httpRequest := &http.Request{
+		Method: "GET",
+		URL:    requestURL,
+	}
+
+	// When
+	logResponseBodyConditionally(200, &responseBuffer, httpRequest)
+
+	// Then
+	assert.Equal(t, logBuffer.Len(), 0)
+}