Adding logs on communication with Agent

Debugging messages are prepended with tag [VROUTER-AGENT].
Parameter logged:
- for request: method, url, header, body;
- for response: status, header, body.

Change-Id: If8f94e05fc7c8df2d7bfea881b2a7268858e66ac
Closes-Bug: #1793479

adapters/secondary/port_association/agent/agent.go

@@ -22,6 +22,9 @@ import (
 	"net/http"
 	"net/url"
 	"time"
+
+	"github.com/Juniper/contrail-windows-docker-driver/logging"
+	log "github.com/sirupsen/logrus"
 )
 
 // It should be equal to PortSubscribeEntry::Type defined in Contrail Vrouter Agent
@@ -31,6 +34,10 @@ const (
 	remotePortType = 2
 )
 
+const (
+	loggerPackageTag = "VROUTER-AGENT"
+)
+
 type PortRequestMsg struct {
 	Time        string `json:"time"`
 	VmUUID      string `json:"instance-id"`
@@ -57,7 +64,9 @@ func NewAgentRestAPI(httpClient *http.Client, url *url.URL) *agentRestAPI {
 }
 
 func (agent *agentRestAPI) sendRequest(request *http.Request) error {
+	log.Debugln(logging.HTTPMessage(loggerPackageTag, request))
 	response, err := agent.httpClient.Do(request)
+	log.Debugln(logging.HTTPMessage(loggerPackageTag, response))
 	if err != nil {
 		return err
 	}

logging/log.go

@@ -16,14 +16,24 @@
 package logging
 
 import (
+	"bytes"
 	"encoding/json"
 	"fmt"
+	"io"
+	"io/ioutil"
+	"net/http"
 	"os"
 	"path/filepath"
 
 	log "github.com/sirupsen/logrus"
 )
 
+const (
+	EmptyRequestResponseMessage = "Empty request/response."
+	WrongHTTPMessageParameter   = "HTTPMessage run with wrong parameter (not request or response)"
+	EmptyHTTPBody               = "Body is empty."
+)
+
 func SetupHook(logPath, logLevelString string) (*LogToFileHook, error) {
 	logLevel, err := log.ParseLevel(logLevelString)
 	if err != nil {
@@ -65,3 +75,69 @@ func VariableToJSON(variable interface{}) string {
 	}
 	return string(jsonOutput)
 }
+
+func readMessageBody(body io.ReadCloser) ([]byte, error) {
+	var buf []byte
+	var err error
+
+	if body == nil {
+		buf = []byte(EmptyHTTPBody)
+	} else {
+		buf, err = ioutil.ReadAll(body)
+		if err != nil {
+			log.Debugln("Cannot read request/response body.", err)
+			buf = []byte("")
+		}
+	}
+	return buf, err
+}
+
+func buildLogMessage(packageTag string, param interface{}, bodyBuffer *[]byte) string {
+
+	var logMsg string
+
+	switch param.(type) {
+	case *http.Request:
+		request := param.(*http.Request)
+		// Body is a io.ReadCloser, so we need to construct one
+		// in place of the one that we already read based on buffer
+		// containing body content
+		request.Body = ioutil.NopCloser(bytes.NewBuffer(*bodyBuffer))
+		logMsg = fmt.Sprintf("[%s][%s]=>[%s] { Header: %s, Body: %s }", packageTag, request.Method, request.URL.String(), VariableToJSON(request.Header), *bodyBuffer)
+	case *http.Response:
+		response := param.(*http.Response)
+		response.Body = ioutil.NopCloser(bytes.NewBuffer(*bodyBuffer))
+		logMsg = fmt.Sprintf("[%s]{ Status: %s, Header: %s, Body: %s }", packageTag, response.Status, VariableToJSON(response.Header), *bodyBuffer)
+	}
+
+	return logMsg
+}
+
+func HTTPMessage(packageTag string, param interface{}) string {
+
+	if param == nil {
+		return EmptyRequestResponseMessage
+	}
+
+	var buf []byte
+
+	switch paramType := param.(type) {
+	default:
+		log.Debugln(WrongHTTPMessageParameter)
+		return WrongHTTPMessageParameter
+	case *http.Request:
+		if nil == paramType {
+			return EmptyRequestResponseMessage
+		} else {
+			buf, _ = readMessageBody((param.(*http.Request)).Body)
+		}
+	case *http.Response:
+		if nil == paramType {
+			return EmptyRequestResponseMessage
+		} else {
+			buf, _ = readMessageBody((param.(*http.Response)).Body)
+		}
+	}
+
+	return buildLogMessage(packageTag, param, &buf)
+}

logging/logging_test.go

@@ -18,14 +18,253 @@
 package logging_test
 
 import (
+	"bytes"
+	"io/ioutil"
+	"net"
+	"net/http"
 	"testing"
 
+	"github.com/Juniper/contrail-windows-docker-driver/logging"
 	. "github.com/onsi/ginkgo"
+	"github.com/onsi/ginkgo/reporters"
 	. "github.com/onsi/gomega"
+	"github.com/onsi/gomega/ghttp"
 )
 
-// Stub to enable code coverage collection (go cov totally ignores modules without tests)
 func TestLogging(t *testing.T) {
 	RegisterFailHandler(Fail)
-	RunSpecs(t, "Logging")
+	junitReporter := reporters.NewJUnitReporter("logging_junit.xml")
+	RunSpecsWithDefaultAndCustomReporters(t, "Logging test suite",
+		[]Reporter{junitReporter})
+}
+
+var _ = Describe("Logging tests", func() {
+	packageTag := "LoggingTest"
+	Context("HTTP request log text test", func() {
+		It("returns error message when given not response nor request", func() {
+			ret := logging.HTTPMessage(packageTag, "abcdefgh")
+			Expect(ret).To(Equal(logging.WrongHTTPMessageParameter))
+		})
+
+		It("returns error message when request is nil", func() {
+			var request *http.Request
+			request = nil
+			ret := logging.HTTPMessage(packageTag, request)
+			Expect(ret).To(Equal(logging.EmptyRequestResponseMessage))
+		})
+
+		It("returns information when request body is nil", func() {
+			request, _ := http.NewRequest("GET", "", nil)
+
+			ret := logging.HTTPMessage(packageTag, request)
+
+			Expect(ret).To(ContainSubstring(logging.EmptyHTTPBody))
+		})
+
+		It("shows correct body when it exists", func() {
+			request, _ := http.NewRequest("GET", "", ioutil.NopCloser(bytes.NewBufferString("Ala ma kota.")))
+
+			ret := logging.HTTPMessage(packageTag, request)
+
+			Expect(ret).To(ContainSubstring("Ala ma kota."))
+		})
+
+		It("preserves body in request", func() {
+			request, _ := http.NewRequest("GET", "", ioutil.NopCloser(bytes.NewBufferString("Ala ma kota.")))
+
+			ret := logging.HTTPMessage(packageTag, request)
+			ret2 := logging.HTTPMessage(packageTag, request)
+
+			Expect(ret).To(ContainSubstring("Ala ma kota."))
+			Expect(ret).To(Equal(ret2))
+		})
+
+		It("shows correct method", func() {
+			requestGet, _ := http.NewRequest("GET", "", nil)
+			requestPost, _ := http.NewRequest("POST", "", nil)
+			requestDelete, _ := http.NewRequest("DELETE", "", nil)
+
+			retGet := logging.HTTPMessage(packageTag, requestGet)
+			retPost := logging.HTTPMessage(packageTag, requestPost)
+			retDelete := logging.HTTPMessage(packageTag, requestDelete)
+
+			Expect(retGet).To(ContainSubstring("GET"))
+			Expect(retPost).To(ContainSubstring("POST"))
+			Expect(retDelete).To(ContainSubstring("DELETE"))
+		})
+
+		It("shows correct header", func() {
+			request, _ := http.NewRequest("GET", "", nil)
+			request.Header.Set("Content-Type", "application/json")
+
+			ret := logging.HTTPMessage(packageTag, request)
+
+			Expect(ret).To(ContainSubstring("application/json"))
+		})
+
+		It("shows correct url", func() {
+			request1, _ := http.NewRequest("GET", "http://abc.def/path1", nil)
+			request2, _ := http.NewRequest("GET", "http://abc.def/path2", nil)
+			request3, _ := http.NewRequest("GET", "http://abc.def/path3", nil)
+
+			ret1 := logging.HTTPMessage(packageTag, request1)
+			ret2 := logging.HTTPMessage(packageTag, request2)
+			ret3 := logging.HTTPMessage(packageTag, request3)
+
+			Expect(ret1).To(ContainSubstring("[http://abc.def/path1]"))
+			Expect(ret2).To(ContainSubstring("[http://abc.def/path2]"))
+			Expect(ret3).To(ContainSubstring("[http://abc.def/path3]"))
+		})
+
+		It("shows correct tag", func() {
+			request, _ := http.NewRequest("GET", "", nil)
+			request.Header.Set("Content-Type", "application/json")
+
+			ret := logging.HTTPMessage(packageTag, request)
+
+			Expect(ret).To(ContainSubstring("[%s]", packageTag))
+		})
+
+	})
+
+	Context("HTTP response log text test", func() {
+		client := &http.Client{}
+		server := testServer(make(chan interface{}))
+		testHeader := http.Header{}
+		testHeader.Add("headerTxt", "Ala Ma Kota W Glowie")
+
+		It("returns error message when response is nil", func() {
+			var response *http.Response
+			response = nil
+			ret := logging.HTTPMessage(packageTag, response)
+
+			Expect(ret).To(Equal(logging.EmptyRequestResponseMessage))
+		})
+
+		It("returns information when response body is nil", func() {
+			server.AppendHandlers(
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/"),
+					ghttp.RespondWith(http.StatusOK, ""),
+				),
+			)
+			request, _ := http.NewRequest("GET", "http://127.0.0.1:9091/", nil)
+
+			response, _ := client.Do(request)
+			response.Body = nil
+
+			ret := logging.HTTPMessage(packageTag, response)
+
+			Expect(ret).To(ContainSubstring("Body is empty."))
+		})
+
+		It("shows correct body when it exists", func() {
+			server.AppendHandlers(
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/bodyTest"),
+					ghttp.RespondWith(http.StatusOK, "Ala Ma Kota"),
+				),
+			)
+			request, _ := http.NewRequest("GET", "http://127.0.0.1:9091/bodyTest", nil)
+
+			response, _ := client.Do(request)
+
+			ret := logging.HTTPMessage(packageTag, response)
+
+			Expect(ret).To(ContainSubstring("Body: Ala Ma Kota"))
+		})
+
+		It("preserves body in response", func() {
+			server.AppendHandlers(
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/bodyTest"),
+					ghttp.RespondWith(http.StatusOK, "Ala Ma Kota"),
+				),
+			)
+			request, _ := http.NewRequest("GET", "http://127.0.0.1:9091/bodyTest", nil)
+
+			response, _ := client.Do(request)
+
+			ret := logging.HTTPMessage(packageTag, response)
+			ret2 := logging.HTTPMessage(packageTag, response)
+
+			Expect(ret).To(ContainSubstring("Body: Ala Ma Kota"))
+			Expect(ret).To(Equal(ret2))
+		})
+
+		It("shows correct header", func() {
+			server.AppendHandlers(
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/headerTest"),
+					ghttp.RespondWith(http.StatusOK, "", testHeader),
+				),
+			)
+			request, _ := http.NewRequest("GET", "http://127.0.0.1:9091/headerTest", nil)
+
+			response, _ := client.Do(request)
+			ret := logging.HTTPMessage(packageTag, response)
+
+			Expect(ret).To(ContainSubstring("\"Headertxt\":[\"Ala Ma Kota W Glowie\"]"))
+		})
+
+		It("shows correct status", func() {
+			server.AppendHandlers(
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/status/200"),
+					ghttp.RespondWith(http.StatusOK, ""),
+				),
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/status/404"),
+					ghttp.RespondWith(http.StatusNotFound, ""),
+				),
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/status/500"),
+					ghttp.RespondWith(http.StatusInternalServerError, ""),
+				),
+			)
+
+			request200, _ := http.NewRequest("GET", "http://127.0.0.1:9091/status/200", nil)
+			request404, _ := http.NewRequest("GET", "http://127.0.0.1:9091/status/404", nil)
+			request500, _ := http.NewRequest("GET", "http://127.0.0.1:9091/status/500", nil)
+
+			response200, _ := client.Do(request200)
+			response404, _ := client.Do(request404)
+			response500, _ := client.Do(request500)
+
+			ret200 := logging.HTTPMessage(packageTag, response200)
+			ret404 := logging.HTTPMessage(packageTag, response404)
+			ret500 := logging.HTTPMessage(packageTag, response500)
+
+			Expect(ret200).To(ContainSubstring("Status: %d", http.StatusOK))
+			Expect(ret404).To(ContainSubstring("Status: %d", http.StatusNotFound))
+			Expect(ret500).To(ContainSubstring("Status: %d", http.StatusInternalServerError))
+		})
+
+		It("shows correct tag", func() {
+			server.AppendHandlers(
+				ghttp.CombineHandlers(
+					ghttp.VerifyRequest("GET", "/"),
+					ghttp.RespondWith(http.StatusOK, ""),
+				),
+			)
+
+			request, _ := http.NewRequest("GET", "http://127.0.0.1:9091/", nil)
+
+			response, _ := client.Do(request)
+
+			ret := logging.HTTPMessage(packageTag, response)
+
+			Expect(ret).To(ContainSubstring("[%s]", packageTag))
+		})
+
+	})
+})
+
+func testServer(recv chan interface{}) *ghttp.Server {
+	server := ghttp.NewUnstartedServer()
+	listener, _ := net.Listen("tcp", "127.0.0.1:9091")
+	server.HTTPTestServer.Listener = listener
+
+	server.Start()
+	return server
 }