Add logging and journal entry for post serve action (#1124)

* initial commit for logging and journal entry, also fixed breaking tests

* change to buffered channel

* add UTs

* update documentation

* update view

* small bugfix

* review comment changes

* review comment changes

core/action/action.go

@@ -14,7 +14,9 @@ import (
 	"time"
 
 	v2 "github.com/SpectoLabs/hoverfly/core/handlers/v2"
+	"github.com/SpectoLabs/hoverfly/core/journal"
 	"github.com/SpectoLabs/hoverfly/core/models"
+	"github.com/pborman/uuid"
 	log "github.com/sirupsen/logrus"
 )
 
@@ -117,7 +119,7 @@ func (action *Action) GetActionView(actionName string) v2.ActionView {
 	}
 }
 
-func (action *Action) Execute(pair *models.RequestResponsePair) error {
+func (action *Action) Execute(pair *models.RequestResponsePair, journalIDChannel chan string, journal *journal.Journal) error {
 
 	pairViewBytes, err := json.Marshal(pair.ConvertToRequestResponsePairView())
 	if err != nil {
@@ -142,24 +144,35 @@ func (action *Action) Execute(pair *models.RequestResponsePair) error {
 			return err
 		}
 
+		correlationID := uuid.New()
+		invokedTime := time.Now()
 		req.Header.Add("Content-Type", "application/json")
+		req.Header.Add("X-CORRELATION-ID", correlationID)
 
 		resp, err := http.DefaultClient.Do(req)
+		completionTime := time.Now()
+		journalID, received := receiveJournalIdWithTimeout(journalIDChannel, time.Second)
+		log.Info("Journal ID received ", journalID)
+
 		if err != nil {
+			updateJournal(pair, received, journal, journalID, correlationID, invokedTime, completionTime, 0)
 			log.WithFields(log.Fields{
 				"error": err.Error(),
 			}).Error("Error when communicating with remote post serve action")
 			return err
 		}
 
+		updateJournal(pair, received, journal, journalID, correlationID, invokedTime, completionTime, resp.StatusCode)
 		if resp.StatusCode != 200 {
 			log.Error("Remote post serve action did not process payload")
+
 			return nil
 		}
 		log.Info("Remote post serve action invoked successfully")
 		return nil
 	}
 
+	invokedTime := time.Now()
 	actionCommand := exec.Command(action.Binary, action.Script.Name())
 	actionCommand.Stdin = bytes.NewReader(pairViewBytes)
 	var stdout bytes.Buffer
@@ -173,6 +186,9 @@ func (action *Action) Execute(pair *models.RequestResponsePair) error {
 	if err := actionCommand.Wait(); err != nil {
 		return err
 	}
+	completionTime := time.Now()
+	journalID, received := receiveJournalIdWithTimeout(journalIDChannel, time.Second)
+	updateJournal(pair, received, journal, journalID, "", invokedTime, completionTime, 0)
 
 	if len(stderr.Bytes()) > 0 {
 		log.Error("Error occurred while executing script " + stderr.String())
@@ -184,6 +200,34 @@ func (action *Action) Execute(pair *models.RequestResponsePair) error {
 	return nil
 }
 
+func updateJournal(pair *models.RequestResponsePair,
+	received bool,
+	journal *journal.Journal,
+	journalID string,
+	correlationID string,
+	invokedTime time.Time,
+	completionTime time.Time,
+	httpStatus int) {
+
+	if received {
+		journal.UpdatePostServeActionDetailsInJournal(journalID,
+			pair.Response.PostServeAction,
+			correlationID,
+			invokedTime,
+			completionTime,
+			httpStatus)
+	}
+}
+
+func receiveJournalIdWithTimeout(journalIDChannel chan string, timeout time.Duration) (string, bool) {
+	select {
+	case msg := <-journalIDChannel:
+		return msg, true
+	case <-time.After(timeout):
+		return "", false
+	}
+}
+
 func isValidURL(host string) bool {
 
 	if _, err := url.ParseRequestURI(host); err == nil {

core/action/action_test.go

@@ -1,6 +1,7 @@
 package action_test
 
 import (
+	"github.com/SpectoLabs/hoverfly/core/journal"
 	"github.com/gorilla/mux"
 	"net/http"
 	"net/http/httptest"
@@ -110,7 +111,12 @@ func Test_ExecuteLocalPostServeAction(t *testing.T) {
 
 	originalPair := models.RequestResponsePair{Response: resp, Request: req}
 
-	err = newAction.Execute(&originalPair)
+	//not adding entry as update journal method will be tested in its file
+	journalIDChannel := make(chan string, 1)
+	newJournal := journal.NewJournal()
+	journalIDChannel <- "demo-id"
+	err = newAction.Execute(&originalPair, journalIDChannel, newJournal)
+	close(journalIDChannel)
 	Expect(err).To(BeNil())
 }
 
@@ -126,10 +132,14 @@ func Test_ExecuteRemotePostServeAction(t *testing.T) {
 			Body: "Normal body",
 		},
 	}
-
+	//not adding entry as update journal method will be tested in its file
+	journalIDChannel := make(chan string, 1)
+	newJournal := journal.NewJournal()
+	journalIDChannel <- "1"
 	newAction, err := action.NewRemoteAction("test-callback", server.URL+"/process", 0)
+	close(journalIDChannel)
 	Expect(err).To(BeNil())
-	err = newAction.Execute(&originalPair)
+	err = newAction.Execute(&originalPair, journalIDChannel, newJournal)
 	Expect(err).To(BeNil())
 }
 
@@ -143,7 +153,12 @@ func Test_ExecuteRemotePostServeAction_WithUnReachableHost(t *testing.T) {
 	newAction, err := action.NewRemoteAction("test-callback", "http://test", 0)
 	Expect(err).To(BeNil())
 
-	err = newAction.Execute(&originalPair)
+	//not adding entry as update journal method will be tested in its file
+	journalIDChannel := make(chan string, 1)
+	newJournal := journal.NewJournal()
+	journalIDChannel <- "1"
+	err = newAction.Execute(&originalPair, journalIDChannel, newJournal)
+	close(journalIDChannel)
 	Expect(err).NotTo(BeNil())
 }
 

core/benchmark_test.go

@@ -181,7 +181,7 @@ func BenchmarkProcessRequest(b *testing.B) {
 		b.Run(bm.name, func(b *testing.B) {
 
 			for n := 0; n < b.N; n++ {
-				resp = hoverfly.processRequest(request)
+				resp, _ = hoverfly.processRequest(request)
 			}
 		})
 	}

core/handlers/v2/views.go

@@ -93,12 +93,21 @@ type JournalView struct {
 }
 
 type JournalEntryView struct {
-	Request     RequestDetailsView  `json:"request"`
-	Response    ResponseDetailsView `json:"response"`
-	Mode        string              `json:"mode"`
-	TimeStarted string              `json:"timeStarted"`
-	Latency     float64             `json:"latency"`
-	Id          string              `json:"id"`
+	Request              RequestDetailsView        `json:"request"`
+	Response             ResponseDetailsView       `json:"response"`
+	Mode                 string                    `json:"mode"`
+	TimeStarted          string                    `json:"timeStarted"`
+	Latency              float64                   `json:"latency"`
+	Id                   string                    `json:"id"`
+	PostServeActionEntry *PostServeActionEntryView `json:"postServeAction,omitEmpty"`
+}
+
+type PostServeActionEntryView struct {
+	ActionName    string `json:"name"`
+	InvokedTime   string `json:"invoked"`
+	CompletedTime string `json:"completed"`
+	CorrelationId string `json:"correlationId,omitempty"`
+	HttpStatus    int    `json:"status,omitempty"`
 }
 
 type JournalEntryFilterView struct {

core/hoverfly.go

@@ -185,16 +185,16 @@ func (hf *Hoverfly) StopProxy() {
 
 // processRequest - processes incoming requests and based on proxy state (record/playback)
 // returns HTTP response.
-func (hf *Hoverfly) processRequest(req *http.Request) *http.Response {
+func (hf *Hoverfly) processRequest(req *http.Request) (*http.Response, chan string) {
 	if hf.Cfg.CORS.Enabled {
 		response := hf.Cfg.CORS.InterceptPreflightRequest(req)
 		if response != nil {
-			return response
+			return response, nil
 		}
 	}
 	requestDetails, err := models.NewRequestDetailsFromHttpRequest(req)
 	if err != nil {
-		return modes.ErrorResponse(req, err, "Could not interpret HTTP request").Response
+		return modes.ErrorResponse(req, err, "Could not interpret HTTP request").Response, nil
 	}
 
 	modeName := hf.Cfg.GetMode()
@@ -208,7 +208,7 @@ func (hf *Hoverfly) processRequest(req *http.Request) *http.Response {
 	// and definitely don't delay people in capture mode
 	// Don't delete the error
 	if err != nil || modeName == modes.Capture {
-		return result.Response
+		return result.Response, nil
 	}
 
 	if result.IsResponseDelayable() {
@@ -221,11 +221,13 @@ func (hf *Hoverfly) processRequest(req *http.Request) *http.Response {
 
 	if result.PostServeActionInputDetails != nil {
 		if postServeAction, ok := hf.PostServeActionDetails.Actions[result.PostServeActionInputDetails.PostServeAction]; ok {
-			go postServeAction.Execute(result.PostServeActionInputDetails.Pair)
+			journalIDChannel := make(chan string, 1)
+			go postServeAction.Execute(result.PostServeActionInputDetails.Pair, journalIDChannel, hf.Journal)
+			return result.Response, journalIDChannel
 		}
 	}
 
-	return result.Response
+	return result.Response, nil
 }
 
 func (hf *Hoverfly) applyResponseDelay(result modes.ProcessResult) {

core/hoverfly_service.go

@@ -481,6 +481,7 @@ func (hf *Hoverfly) SetLocalPostServeAction(actionName string, binary string, sc
 	if err != nil {
 		return err
 	}
+	log.Info("Local post serve action is set")
 	return nil
 }
 
@@ -494,6 +495,7 @@ func (hf *Hoverfly) SetRemotePostServeAction(actionName, remote string, delayInM
 	if err != nil {
 		return err
 	}
+	log.Info("Remote post serve action is set")
 	return nil
 }