[APICET-42] Add http request time, response time and duration. (#165)

* [APICET-42] Log request time, response time and duration

.github/workflows/check_example.yaml

@@ -12,7 +12,7 @@ permissions:
   contents: read
 
 jobs:
-  lint:
+  example-lint:
     runs-on: ubuntu-latest
     steps:
       - name: checkout repository
@@ -31,7 +31,7 @@ jobs:
       - name: linter
         run: cd examples/service && make mod deps linter GOPATH=$(go env GOPATH)
 
-  test:
+  example-test:
     runs-on: ubuntu-latest
     steps:
       - name: checkout repository
@@ -52,7 +52,7 @@ jobs:
       - name: unit tests
         run: cd examples/service && make mod deps gendoc generate confcheck test GOPATH=$(go env GOPATH)
 
-  integration-test:
+  example-integration-test:
     runs-on: ubuntu-latest
     steps:
       - name: checkout repository

pkg/httpclient/client.go

@@ -50,7 +50,7 @@ func New(opts ...Option) *Client {
 //
 //nolint:gocognit
 func (c *Client) Do(r *http.Request) (*http.Response, error) {
-	start := time.Now()
+	reqTime := time.Now().UTC()
 
 	ctx, cancel := context.WithTimeout(r.Context(), c.client.Timeout)
 	defer cancel()
@@ -61,7 +61,11 @@ func (c *Client) Do(r *http.Request) (*http.Response, error) {
 	var err error
 
 	defer func() {
-		l = l.With(zap.Duration(c.logPrefix+"duration", time.Since(start)))
+		resTime := time.Now().UTC()
+		l = l.With(
+			zap.Time(c.logPrefix+"response_time", resTime),
+			zap.Duration(c.logPrefix+"response_duration", resTime.Sub(reqTime)),
+		)
 
 		if err != nil {
 			l.Error(c.logPrefix+"error", zap.Error(err))
@@ -82,7 +86,8 @@ func (c *Client) Do(r *http.Request) (*http.Response, error) {
 	r = r.WithContext(ctx)
 
 	l = l.With(
-		zap.String(c.logPrefix+"traceid", reqID),
+		zap.String(c.logPrefix+traceid.DefaultLogKey, reqID),
+		zap.Time(c.logPrefix+"request_time", reqTime),
 		zap.String(c.logPrefix+"request_method", r.Method),
 		zap.String(c.logPrefix+"request_path", r.URL.Path),
 		zap.String(c.logPrefix+"request_query", r.URL.RawQuery),

pkg/httpreverseproxy/client.go

@@ -6,6 +6,7 @@ import (
 	"net/http/httputil"
 	"net/url"
 	"strings"
+	"time"
 
 	libhttputil "github.com/nexmoinc/gosrvlib/pkg/httputil"
 	"github.com/nexmoinc/gosrvlib/pkg/logging"
@@ -106,15 +107,26 @@ func (c *httpWrapper) RoundTrip(r *http.Request) (*http.Response, error) {
 
 func defaultErrorHandler(logger *zap.Logger) errHandler {
 	return func(w http.ResponseWriter, r *http.Request, err error) {
+		resTime := time.Now().UTC()
+		ctx := r.Context()
+
+		reqTime, ok := libhttputil.GetRequestTimeFromContext(ctx)
+		if !ok {
+			reqTime = resTime
+		}
+
 		logger.With(
-			zap.String("traceid", traceid.FromContext(r.Context(), "")),
+			zap.String(traceid.DefaultLogKey, traceid.FromContext(ctx, "")),
 			zap.String("request_method", r.Method),
 			zap.String("request_path", r.URL.Path),
 			zap.String("request_query", r.URL.RawQuery),
 			zap.String("request_uri", r.RequestURI),
 			zap.Int("response_code", http.StatusBadGateway),
 			zap.String("response_message", http.StatusText(http.StatusBadGateway)),
 			zap.Any("response_status", libhttputil.Status(http.StatusBadGateway)),
+			zap.Time("request_time", reqTime),
+			zap.Time("response_time", resTime),
+			zap.Duration("response_duration", resTime.Sub(reqTime)),
 		).Error("proxy_error", zap.Error(err))
 
 		http.Error(w, http.StatusText(http.StatusBadGateway), http.StatusBadGateway)

pkg/httpserver/middleware.go

@@ -3,7 +3,9 @@ package httpserver
 import (
 	"net/http"
 	"net/http/httputil"
+	"time"
 
+	libhttputil "github.com/nexmoinc/gosrvlib/pkg/httputil"
 	"github.com/nexmoinc/gosrvlib/pkg/logging"
 	"github.com/nexmoinc/gosrvlib/pkg/traceid"
 	"github.com/nexmoinc/gosrvlib/pkg/uidc"
@@ -37,18 +39,18 @@ type MiddlewareFn func(args MiddlewareArgs, next http.Handler) http.Handler
 // RequestInjectHandler wraps all incoming requests and injects a logger in the request scoped context.
 func RequestInjectHandler(logger *zap.Logger, traceIDHeaderName string, redactFn RedactFn, next http.Handler) http.Handler {
 	fn := func(w http.ResponseWriter, r *http.Request) {
-		ctx := r.Context()
-
+		reqTime := time.Now().UTC()
 		reqID := traceid.FromHTTPRequestHeader(r, traceIDHeaderName, uidc.NewID128())
 
 		l := logger.With(
-			zap.String("traceid", reqID),
+			zap.String(traceid.DefaultLogKey, reqID),
+			zap.Time("request_time", reqTime),
 			zap.String("request_method", r.Method),
 			zap.String("request_path", r.URL.Path),
 			zap.String("request_query", r.URL.RawQuery),
+			zap.String("request_remote_address", r.RemoteAddr),
 			zap.String("request_uri", r.RequestURI),
 			zap.String("request_user_agent", r.UserAgent()),
-			zap.String("request_remote_address", r.RemoteAddr),
 			zap.String("request_x_forwarded_for", r.Header.Get("X-Forwarded-For")),
 		)
 
@@ -57,8 +59,10 @@ func RequestInjectHandler(logger *zap.Logger, traceIDHeaderName string, redactFn
 			l = l.With(zap.String("request", redactFn(string(reqDump))))
 		}
 
-		ctx = logging.WithLogger(ctx, l)
+		ctx := r.Context()
+		ctx = libhttputil.WithRequestTime(ctx, reqTime)
 		ctx = traceid.NewContext(ctx, reqID)
+		ctx = logging.WithLogger(ctx, l)
 
 		next.ServeHTTP(w, r.WithContext(ctx))
 	}

pkg/httpserver/middleware_test.go

@@ -5,6 +5,7 @@ import (
 	"net/http/httptest"
 	"testing"
 
+	"github.com/nexmoinc/gosrvlib/pkg/httputil"
 	"github.com/nexmoinc/gosrvlib/pkg/logging"
 	"github.com/nexmoinc/gosrvlib/pkg/redact"
 	"github.com/nexmoinc/gosrvlib/pkg/testutil"
@@ -21,6 +22,11 @@ func TestRequestInjectHandler(t *testing.T) {
 		require.NotNil(t, l, "logger not found")
 
 		l.Info("injected")
+
+		// check if the request_time can be retrieved.
+		reqTime, ok := httputil.GetRequestTime(r)
+		require.True(t, ok)
+		require.NotEmpty(t, reqTime)
 	})
 
 	ctx, logs := testutil.ContextWithLogObserver(zapcore.DebugLevel)
@@ -35,39 +41,49 @@ func TestRequestInjectHandler(t *testing.T) {
 	logEntry := logEntries[0]
 	logContextMap := logEntry.ContextMap()
 
-	// check request id
-	idValue, idExists := logContextMap["traceid"]
-	require.True(t, idExists, "traceid field missing")
-	require.NotEmpty(t, idValue, "expected requestId value not found")
+	// check traceid
+	tiValue, tiExists := logContextMap[traceid.DefaultLogKey]
+	require.True(t, tiExists, "traceid field missing")
+	require.NotEmpty(t, tiValue, "expected traceid value not found")
+
+	// check request_time
+	rtValue, rtExists := logContextMap["request_time"]
+	require.True(t, rtExists, "request_time field missing")
+	require.NotEmpty(t, rtValue, "expected request_time value not found")
 
-	// check method
+	// check request_method
 	mValue, mExists := logContextMap["request_method"]
 	require.True(t, mExists, "request_method field missing")
 	require.Equal(t, http.MethodGet, mValue)
 
-	// check path
+	// check request_path
 	pValue, pExists := logContextMap["request_path"]
 	require.True(t, pExists, "request_path field missing")
 	require.Equal(t, "/", pValue)
 
-	// request_query
+	// check request_query
 	rqValue, rqExists := logContextMap["request_query"]
 	require.True(t, rqExists, "request_query field missing")
 	require.Equal(t, "", rqValue)
 
-	// request_uri
+	// check request_user_agent
+	_, ipExists := logContextMap["request_remote_address"]
+	require.True(t, ipExists, "request_remote_address field missing")
+
+	// check request_uri
 	ruValue, ruExists := logContextMap["request_uri"]
 	require.True(t, ruExists, "request_uri field missing")
 	require.Equal(t, "/", ruValue)
 
-	// request_user_agent
+	// check request_user_agent
 	uaValue, uaExists := logContextMap["request_user_agent"]
 	require.True(t, uaExists, "request_user_agent field missing")
 	require.Equal(t, "", uaValue)
 
-	// request_user_agent
-	_, ipExists := logContextMap["request_remote_address"]
-	require.True(t, ipExists, "request_remote_address field missing")
+	// check request_x_forwarded_for
+	rxffValue, rxffExists := logContextMap["request_x_forwarded_for"]
+	require.True(t, rxffExists, "request_x_forwarded_for field missing")
+	require.Equal(t, "", rxffValue)
 
 	// message
 	require.Equal(t, "injected", logEntry.Message)

pkg/httputil/request.go

@@ -1,16 +1,23 @@
 package httputil
 
 import (
+	"context"
 	"encoding/base64"
 	"math"
 	"net/http"
 	"net/url"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/julienschmidt/httprouter"
 )
 
+type timeCtxKey string
+
+// ReqTimeCtxKey is the Context key to retrieve the request time.
+const ReqTimeCtxKey = timeCtxKey("request_time")
+
 // AddBasicAuth decorates the provided http.Request with Basic Authorization.
 func AddBasicAuth(apiKey, apiSecret string, r *http.Request) {
 	r.Header.Add("Authorization", "Basic "+base64.StdEncoding.EncodeToString([]byte(apiKey+":"+apiSecret)))
@@ -59,3 +66,21 @@ func QueryUintOrDefault(q url.Values, key string, defaultValue uint) uint {
 
 	return defaultValue
 }
+
+// WithRequestTime returns a new context with the added request time.
+func WithRequestTime(ctx context.Context, t time.Time) context.Context {
+	return context.WithValue(ctx, ReqTimeCtxKey, t)
+}
+
+// GetRequestTimeFromContext returns the request time from the context.
+func GetRequestTimeFromContext(ctx context.Context) (time.Time, bool) {
+	v := ctx.Value(ReqTimeCtxKey)
+	t, ok := v.(time.Time)
+
+	return t, ok
+}
+
+// GetRequestTime returns the request time from the http request.
+func GetRequestTime(r *http.Request) (time.Time, bool) {
+	return GetRequestTimeFromContext(r.Context())
+}

pkg/httputil/request_test.go

@@ -7,6 +7,7 @@ import (
 	"net/http/httptest"
 	"net/url"
 	"testing"
+	"time"
 
 	"github.com/nexmoinc/gosrvlib/pkg/testutil"
 	"github.com/stretchr/testify/require"
@@ -280,3 +281,33 @@ func TestQueryUintOrDefault(t *testing.T) {
 		})
 	}
 }
+
+func TestGetRequestTimeFromContext(t *testing.T) {
+	t.Parallel()
+
+	testTime := time.Date(2023, time.January, 31, 10, 0, 0, 0, time.UTC)
+
+	ctx := context.Background()
+	ctx = WithRequestTime(ctx, testTime)
+
+	outTime, ok := GetRequestTimeFromContext(ctx)
+
+	require.True(t, ok)
+	require.Equal(t, testTime, outTime)
+}
+
+func TestGetRequestTime(t *testing.T) {
+	t.Parallel()
+
+	testTime := time.Date(2023, time.January, 31, 11, 0, 0, 0, time.UTC)
+
+	ctx := context.Background()
+	ctx = WithRequestTime(ctx, testTime)
+
+	r, _ := http.NewRequestWithContext(ctx, http.MethodGet, "/", nil)
+
+	outTime, ok := GetRequestTime(r)
+
+	require.True(t, ok)
+	require.Equal(t, testTime, outTime)
+}

pkg/httputil/response.go

@@ -5,6 +5,7 @@ import (
 	"encoding/json"
 	"encoding/xml"
 	"net/http"
+	"time"
 
 	"github.com/nexmoinc/gosrvlib/pkg/logging"
 	"go.uber.org/zap"
@@ -109,17 +110,26 @@ func writeHeaders(w http.ResponseWriter, statusCode int, contentType string) {
 
 // logResponse logs the response.
 func logResponse(ctx context.Context, statusCode int, dataKey string, data interface{}) {
+	resTime := time.Now().UTC()
+
+	reqTime, ok := GetRequestTimeFromContext(ctx)
+	if !ok {
+		reqTime = resTime
+	}
+
 	l := logging.FromContext(ctx)
-	reqLog := l.With(
+	resLog := l.With(
 		zap.Int("response_code", statusCode),
 		zap.String("response_message", http.StatusText(statusCode)),
 		zap.Any("response_status", Status(statusCode)),
+		zap.Time("response_time", resTime),
+		zap.Duration("response_duration", resTime.Sub(reqTime)),
 		zap.Any(dataKey, data),
 	)
 
 	if statusCode >= http.StatusBadRequest { // 400+
-		reqLog.Error("Request")
+		resLog.Error("Response")
 	} else {
-		reqLog.Debug("Request")
+		resLog.Debug("Response")
 	}
 }

pkg/traceid/traceid.go

@@ -5,6 +5,7 @@ package traceid
 import (
 	"context"
 	"net/http"
+	"regexp"
 )
 
 const (
@@ -13,8 +14,15 @@ const (
 
 	// DefaultValue is the default trace ID value.
 	DefaultValue = ""
+
+	// DefaultLogKey is the default log field key for the Trace ID.
+	DefaultLogKey = "traceid"
 )
 
+const regexPatternValidID = `^[0-9A-Za-z\-\_\.]{1,64}$`
+
+var regexValidID = regexp.MustCompile(regexPatternValidID)
+
 // ctxKey is used to store the trace ID in the context.
 type ctxKey struct{}
 
@@ -52,7 +60,7 @@ func SetHTTPRequestHeaderFromContext(ctx context.Context, r *http.Request, heade
 func FromHTTPRequestHeader(r *http.Request, header, defaultValue string) string {
 	id := r.Header.Get(header)
 
-	if id == "" {
+	if !regexValidID.MatchString(id) {
 		return defaultValue
 	}