slighty improvement of logging (#6)

app/context/context.go

@@ -12,10 +12,40 @@ import (
 type key uint32
 
 const (
-	converterKey key = iota
+	requestIDKey key = iota
+	converterKey
 	resultFilePathKey
 )
 
+// WithRequestID populates a request's context with the given request ID
+// and returns the updated request.
+func WithRequestID(r *http.Request, requestID string) *http.Request {
+	ctx := r.Context()
+	ctx = context.WithValue(ctx, requestIDKey, requestID)
+	r = r.WithContext(ctx)
+
+	return r
+}
+
+type requestIDNotFoundError struct{}
+
+const requestIDNotFoundErrorMessage = "the request ID was not found in request context"
+
+func (e *requestIDNotFoundError) Error() string {
+	return requestIDNotFoundErrorMessage
+}
+
+// GetRequestID returns the request ID if found in
+// the request's context. Otherwise throws an error.
+func GetRequestID(r *http.Request) (string, error) {
+	ID, ok := r.Context().Value(requestIDKey).(string)
+	if !ok {
+		return "", &requestIDNotFoundError{}
+	}
+
+	return ID, nil
+}
+
 // WithConverter populates a request's context with the given converter
 // and returns the updated request.
 func WithConverter(r *http.Request, converter *converter.Converter) *http.Request {

app/context/context_test.go

@@ -6,8 +6,40 @@ import (
 	"testing"
 
 	"github.com/thecodingmachine/gotenberg/app/converter"
+
+	"github.com/satori/go.uuid"
 )
 
+func TestWithRequestID(t *testing.T) {
+	requestID := uuid.NewV4().String()
+	req := WithRequestID(httptest.NewRequest(http.MethodPost, "/", nil), requestID)
+	if ID, _ := req.Context().Value(requestIDKey).(string); ID != requestID {
+		t.Errorf("Context returned a wrong converter: got '%s' want '%s'", ID, requestID)
+	}
+}
+
+func TestRequestIDNotFoundError(t *testing.T) {
+	err := &requestIDNotFoundError{}
+	if err.Error() != requestIDNotFoundErrorMessage {
+		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), requestIDNotFoundErrorMessage)
+	}
+}
+
+func TestGetRequestID(t *testing.T) {
+	req := httptest.NewRequest(http.MethodPost, "/", nil)
+
+	// case 1: uses a request without a request ID entry in its context.
+	if _, err := GetRequestID(req); err == nil {
+		t.Error("Context should not have a request ID entry")
+	}
+
+	// case 2: uses a request with a request ID entry in its context.
+	req = WithRequestID(req, uuid.NewV4().String())
+	if _, err := GetRequestID(req); err != nil {
+		t.Error("Context should have a request ID entry")
+	}
+}
+
 func TestWithConverter(t *testing.T) {
 	req := WithConverter(httptest.NewRequest(http.MethodPost, "/", nil), &converter.Converter{})
 	if c, _ := req.Context().Value(converterKey).(*converter.Converter); c == nil {
@@ -15,6 +47,13 @@ func TestWithConverter(t *testing.T) {
 	}
 }
 
+func TestConverterNotFoundError(t *testing.T) {
+	err := &converterNotFoundError{}
+	if err.Error() != converterNotFoundErrorMessage {
+		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), converterNotFoundErrorMessage)
+	}
+}
+
 func TestGetConverter(t *testing.T) {
 	req := httptest.NewRequest(http.MethodPost, "/", nil)
 
@@ -38,6 +77,13 @@ func TestWithResultFilePath(t *testing.T) {
 	}
 }
 
+func TestResultFilePathNotFoundError(t *testing.T) {
+	err := &resultFilePathNotFoundError{}
+	if err.Error() != resultFilePathNotFoundErrorMessage {
+		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), resultFilePathNotFoundErrorMessage)
+	}
+}
+
 func TestGetResultFilePath(t *testing.T) {
 	req := httptest.NewRequest(http.MethodPost, "/", nil)
 
@@ -52,17 +98,3 @@ func TestGetResultFilePath(t *testing.T) {
 		t.Error("Context should have a result file path entry")
 	}
 }
-
-func TestConverterNotFoundError(t *testing.T) {
-	err := &converterNotFoundError{}
-	if err.Error() != converterNotFoundErrorMessage {
-		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), converterNotFoundErrorMessage)
-	}
-}
-
-func TestResultFilePathNotFoundError(t *testing.T) {
-	err := &resultFilePathNotFoundError{}
-	if err.Error() != resultFilePathNotFoundErrorMessage {
-		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), resultFilePathNotFoundErrorMessage)
-	}
-}

app/handlers.go

@@ -14,6 +14,7 @@ import (
 
 	"github.com/dustin/go-humanize"
 	"github.com/justinas/alice"
+	"github.com/satori/go.uuid"
 )
 
 // GetHandlersChain returns the handlers chaining
@@ -40,6 +41,10 @@ func enforceContentLengthHandler(next http.Handler) http.Handler {
 			return
 		}
 
+		requestID := uuid.NewV4().String()
+		r = context.WithRequestID(r, requestID)
+		logger.Infof("identified new request (%s) with %s", humanize.Bytes(uint64(r.ContentLength)), requestID)
+
 		next.ServeHTTP(w, r)
 	})
 }
@@ -123,7 +128,12 @@ func serveHandler(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	logger.Debugf("serving result file %s...", path)
+	requestID, err := context.GetRequestID(r)
+	if err != nil {
+		logger.Error(err)
+	}
+
+	logger.Debugf("serving result file %s for request %s...", path, requestID)
 
 	done := make(chan error, 1)
 	go func() {
@@ -139,9 +149,10 @@ func serveHandler(w http.ResponseWriter, r *http.Request) {
 	if err != nil {
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		logger.Error(err)
+	} else {
+		logger.Infof("result file %s (%s) sent for request %s", path, humanize.Bytes(uint64(resultFileInfo.Size())), requestID)
 	}
 
-	logger.Infof("result file %s (%s) sent", path, humanize.Bytes(uint64(resultFileInfo.Size())))
 	cleanup(r)
 }