fix(timer): extend time to let container write logs

Signed-off-by: Felipe Zipitria <[email protected]>

http/client.go

@@ -77,3 +77,13 @@ func (c *Client) Do(req Request) (*Response, error) {
 func (c *Client) GetRoundTripTime() *RoundTripTime {
 	return c.Transport.GetRoundTripTime()
 }
+
+// StartTrackingTime sets the timer to start transactions. This will be the starting time in logs.
+func (c *Client) StartTrackingTime() {
+	c.Transport.StartTrackingTime()
+}
+
+// StopTrackingTime stops the timer. When looking at logs, we will read up to this one.
+func (c *Client) StopTrackingTime() {
+	c.Transport.StopTrackingTime()
+}

http/connection.go

@@ -27,11 +27,13 @@ func DestinationFromString(urlString string) *Destination {
 	return d
 }
 
-func (c *Connection) startTracking() {
+// StartTrackingTime initializes timer
+func (c *Connection) StartTrackingTime() {
 	c.duration.StartTracking()
 }
 
-func (c *Connection) stopTracking() {
+// StopTrackingTime stops timer
+func (c *Connection) StopTrackingTime() {
 	c.duration.StopTracking()
 }
 
@@ -46,7 +48,6 @@ func (c *Connection) send(data []byte) (int, error) {
 
 	log.Trace().Msg("ftw/http: sending data")
 	// Store times for searching in logs, if necessary
-	c.startTracking()
 
 	if c.connection != nil {
 		sent, err = c.connection.Write(data)
@@ -79,7 +80,6 @@ func (c *Connection) receive() ([]byte, error) {
 		err = nil
 	}
 	log.Trace().Msgf("ftw/http: received data - %q", buf)
-	c.stopTracking()
 
 	return buf, err
 }

http/request.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"net/http"
 	"net/url"
+	"strings"
 
 	"github.com/fzipi/go-ftw/utils"
 
@@ -160,6 +161,7 @@ func (r Request) isRaw() bool {
 func buildRequest(r *Request) ([]byte, error) {
 	var err error
 	var b bytes.Buffer
+	var data []byte
 
 	// Check if we need to create from all fields
 	if !r.isRaw() {
@@ -181,6 +183,16 @@ func buildRequest(r *Request) ([]byte, error) {
 			}
 		}
 
+		// Multipart form data needs to end in \r\n, per RFC (and modsecurity make a scene if not)
+		if ct := r.headers.Value("Content-Type"); strings.HasPrefix(ct, "multipart/form-data") {
+			crlf := []byte("\r\n")
+			lf := []byte("\n")
+			log.Debug().Msgf("ftw/http: with LF only - %d bytes:\n%x\n", len(r.data), r.data)
+			data = bytes.ReplaceAll(r.data, lf, crlf)
+			log.Debug().Msgf("ftw/http: with CRLF - %d bytes:\n%x\n", len(data), data)
+			r.data = data
+		}
+
 		if r.WithAutoCompleteHeaders() {
 			log.Trace().Msgf("ftw/http: adding standard headers")
 			r.AddStandardHeaders(len(r.data))

http/rtt.go

@@ -19,7 +19,8 @@ func (rtt *RoundTripTime) StartTracking() {
 
 // StopTracking sets the finish time to Now
 func (rtt *RoundTripTime) StopTracking() {
-	rtt.end = time.Now()
+	now := time.Now()
+	rtt.end = now.Add(50 * time.Millisecond)
 }
 
 // StartTime returns the time when this round trip started

runner/run.go

@@ -73,15 +73,13 @@ func Run(include string, exclude string, showTime bool, output bool, ftwtests []
 
 				req = getRequestFromTest(testRequest)
 
+				client.StartTrackingTime()
 				response, err := client.Do(*req)
+				client.StopTrackingTime()
 
 				// Create a new check
 				ftwcheck := check.NewCheck(config.FTWConfig)
-
-				// Logs need a timespan to check
-				startTime := client.GetRoundTripTime().StartTime()
-				endTime := client.GetRoundTripTime().StopTime()
-				ftwcheck.SetRoundTripTime(startTime, endTime)
+				ftwcheck.SetRoundTripTime(client.GetRoundTripTime().StartTime(), client.GetRoundTripTime().StopTime())
 
 				// Set expected test output in check
 				ftwcheck.SetExpectTestOutput(&expectedOutput)