From faec55dd01f8759b6c4001930aeb6a2b99779893 Mon Sep 17 00:00:00 2001 From: Julien Neuhart Date: Wed, 16 May 2018 10:02:07 +0200 Subject: [PATCH] slighty improvement of logging (#6) --- app/context/context.go | 32 +++++++++++++++++++- app/context/context_test.go | 60 ++++++++++++++++++++++++++++--------- app/handlers.go | 15 ++++++++-- 3 files changed, 90 insertions(+), 17 deletions(-) diff --git a/app/context/context.go b/app/context/context.go index 5b7ab7a5..39e84936 100644 --- a/app/context/context.go +++ b/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 { diff --git a/app/context/context_test.go b/app/context/context_test.go index 17def1dd..cae489fa 100644 --- a/app/context/context_test.go +++ b/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) - } -} diff --git a/app/handlers.go b/app/handlers.go index 784b88ff..ada30abc 100644 --- a/app/handlers.go +++ b/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) }