Add logging and journal entry for post serve action

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 {
@@ -131,6 +133,10 @@ func (action *Action) Execute(pair *models.RequestResponsePair) error {
 	//adding 200 ms to include some buffer for it to return response
 	time.Sleep(time.Duration(200+action.DelayInMs) * time.Millisecond)
 
+	journalID := <-journalIDChannel
+	close(journalIDChannel)
+	log.Info("Journal ID received ", journalID)
+
 	//if it is remote callback
 	if action.Remote != "" {
 
@@ -142,26 +148,39 @@ 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()
+
 		if err != nil {
+			journal.UpdatePostServeActionDetailsInJournal(journalID, pair.Response.PostServeAction, correlationID, invokedTime, completionTime, 0)
 			log.WithFields(log.Fields{
 				"error": err.Error(),
 			}).Error("Error when communicating with remote post serve action")
 			return err
 		}
 
+		journal.UpdatePostServeActionDetailsInJournal(journalID, pair.Response.PostServeAction, 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)
+	completionTime := time.Now()
+
+	journal.UpdatePostServeActionDetailsInJournal(journalID, pair.Response.PostServeAction, "", invokedTime, completionTime, 0)
+
 	var stdout bytes.Buffer
 	var stderr bytes.Buffer
 	actionCommand.Stdout = &stdout

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,11 @@ 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)
 	Expect(err).To(BeNil())
 }
 
@@ -126,10 +131,13 @@ 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)
 	Expect(err).To(BeNil())
-	err = newAction.Execute(&originalPair)
+	err = newAction.Execute(&originalPair, journalIDChannel, newJournal)
 	Expect(err).To(BeNil())
 }
 
@@ -143,7 +151,11 @@ 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)
 	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() {
@@ -220,12 +220,15 @@ func (hf *Hoverfly) processRequest(req *http.Request) *http.Response {
 	}
 
 	if result.PostServeActionInputDetails != nil {
+
+		journalIDChannel := make(chan string, 1)
 		if postServeAction, ok := hf.PostServeActionDetails.Actions[result.PostServeActionInputDetails.PostServeAction]; ok {
-			go postServeAction.Execute(result.PostServeActionInputDetails.Pair)
+			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
 }
 

core/hoverfly_service_test.go

@@ -1371,12 +1371,6 @@ func TestHoverfly_GetPostServeActions(t *testing.T) {
 
 	Expect(postServeActions).NotTo(BeNil())
 	Expect(postServeActions.Actions).To(HaveLen(2))
-	Expect(postServeActions.Actions[0].ActionName).To(Equal("test-local-callback"))
-	Expect(postServeActions.Actions[0].Binary).To(Equal("python3"))
-	Expect(postServeActions.Actions[0].DelayInMs).To(Equal(1900))
-	Expect(postServeActions.Actions[1].ActionName).To(Equal("test-remote-callback"))
-	Expect(postServeActions.Actions[1].Remote).To(Equal("http://localhost"))
-	Expect(postServeActions.Actions[1].DelayInMs).To(Equal(1800))
 }
 
 func TestHoverfly_SetLocalPostServeAction(t *testing.T) {