From 96eb5d3c91f3a7adb2a67acf7b1851562ab67d2e Mon Sep 17 00:00:00 2001 From: Adam Shannon Date: Thu, 13 Dec 2018 13:05:11 -0600 Subject: [PATCH] server: log x-request-id header if present The logging middleware isn't able to show the requestId, which is how we trace requests through all systems. Instead we needed to pull that header off and pass it around to each endpoint function. Our timing metrics were always 0ms as ach currently does everything inmem. --- cmd/server/main.go | 1 - server/batches.go | 55 ++++++++++++++--- server/files.go | 90 ++++++++++++++++++++++------ server/logging.go | 143 --------------------------------------------- server/routing.go | 18 +++--- 5 files changed, 128 insertions(+), 179 deletions(-) delete mode 100644 server/logging.go diff --git a/cmd/server/main.go b/cmd/server/main.go index 0437a6202..3186800e2 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -71,7 +71,6 @@ func main() { // Setup underlying ach service r := server.NewRepositoryInMemory() svc = server.NewService(r) - svc = server.LoggingMiddleware(logger)(svc) // Create HTTP server handler = server.MakeHTTPHandler(svc, r, log.With(logger, "component", "HTTP")) diff --git a/server/batches.go b/server/batches.go index c61ca98fb..1bba33cdc 100644 --- a/server/batches.go +++ b/server/batches.go @@ -11,14 +11,18 @@ import ( "net/http" "github.com/moov-io/ach" + moovhttp "github.com/moov-io/base/http" "github.com/go-kit/kit/endpoint" + "github.com/go-kit/kit/log" "github.com/gorilla/mux" ) type createBatchRequest struct { FileID string Batch *ach.Batch + + requestId string } type createBatchResponse struct { @@ -28,19 +32,26 @@ type createBatchResponse struct { func (r createBatchResponse) error() error { return r.Err } -func createBatchEndpoint(s Service) endpoint.Endpoint { +func createBatchEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(createBatchRequest) - id, e := s.CreateBatch(req.FileID, req.Batch) + id, err := s.CreateBatch(req.FileID, req.Batch) + + if req.requestId != "" && logger != nil { + logger.Log("batches", "createBatch", "file", req.FileID, "requestId", req.requestId, "error", err) + } + return createBatchResponse{ ID: id, - Err: e, + Err: err, }, nil } } func decodeCreateBatchRequest(_ context.Context, r *http.Request) (interface{}, error) { var req createBatchRequest + req.requestId = moovhttp.GetRequestId(r) + vars := mux.Vars(r) id, ok := vars["fileID"] if !ok { @@ -58,6 +69,8 @@ func decodeCreateBatchRequest(_ context.Context, r *http.Request) (interface{}, type getBatchesRequest struct { fileID string + + requestId string } type getBatchesResponse struct { @@ -73,6 +86,8 @@ func (r getBatchesResponse) error() error { return r.Err } func decodeGetBatchesRequest(_ context.Context, r *http.Request) (interface{}, error) { var req getBatchesRequest + req.requestId = moovhttp.GetRequestId(r) + vars := mux.Vars(r) id, ok := vars["fileID"] if !ok { @@ -82,9 +97,12 @@ func decodeGetBatchesRequest(_ context.Context, r *http.Request) (interface{}, e return req, nil } -func getBatchesEndpoint(s Service) endpoint.Endpoint { +func getBatchesEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(getBatchesRequest) + if req.requestId != "" && logger != nil { + logger.Log("batches", "getBatches", "file", req.fileID, "requestId", req.requestId) + } return getBatchesResponse{ Batches: s.GetBatches(req.fileID), Err: nil, @@ -95,6 +113,8 @@ func getBatchesEndpoint(s Service) endpoint.Endpoint { type getBatchRequest struct { fileID string batchID string + + requestId string } type getBatchResponse struct { @@ -106,6 +126,8 @@ func (r getBatchResponse) error() error { return r.Err } func decodeGetBatchRequest(_ context.Context, r *http.Request) (interface{}, error) { var req getBatchRequest + req.requestId = moovhttp.GetRequestId(r) + vars := mux.Vars(r) fileID, ok := vars["fileID"] if !ok { @@ -121,13 +143,18 @@ func decodeGetBatchRequest(_ context.Context, r *http.Request) (interface{}, err return req, nil } -func getBatchEndpoint(s Service) endpoint.Endpoint { +func getBatchEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(getBatchRequest) - batch, e := s.GetBatch(req.fileID, req.batchID) + batch, err := s.GetBatch(req.fileID, req.batchID) + + if req.requestId != "" && logger != nil { + logger.Log("batches", "getBatche", "file", req.fileID, "requestId", req.requestId, "error", err) + } + return getBatchResponse{ Batch: batch, - Err: e, + Err: err, }, nil } } @@ -135,6 +162,8 @@ func getBatchEndpoint(s Service) endpoint.Endpoint { type deleteBatchRequest struct { fileID string batchID string + + requestId string } type deleteBatchResponse struct { @@ -145,6 +174,8 @@ func (r deleteBatchResponse) error() error { return r.Err } func decodeDeleteBatchRequest(_ context.Context, r *http.Request) (interface{}, error) { var req deleteBatchRequest + req.requestId = moovhttp.GetRequestId(r) + vars := mux.Vars(r) fileID, ok := vars["fileID"] if !ok { @@ -160,11 +191,17 @@ func decodeDeleteBatchRequest(_ context.Context, r *http.Request) (interface{}, return req, nil } -func deleteBatchEndpoint(s Service) endpoint.Endpoint { +func deleteBatchEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(deleteBatchRequest) + err := s.DeleteBatch(req.fileID, req.batchID) + + if req.requestId != "" && logger != nil { + logger.Log("batches", "deleteBatch", "file", req.fileID, "requestId", req.requestId, "error", err) + } + return deleteBatchResponse{ - Err: s.DeleteBatch(req.fileID, req.batchID), + Err: err, }, nil } } diff --git a/server/files.go b/server/files.go index cdd09bc87..449a5c520 100644 --- a/server/files.go +++ b/server/files.go @@ -13,8 +13,10 @@ import ( "strings" "github.com/moov-io/ach" + moovhttp "github.com/moov-io/base/http" "github.com/go-kit/kit/endpoint" + "github.com/go-kit/kit/log" "github.com/go-kit/kit/metrics/prometheus" "github.com/gorilla/mux" stdprometheus "github.com/prometheus/client_golang/prometheus" @@ -29,6 +31,8 @@ var ( type createFileRequest struct { File *ach.File + + requestId string } type createFileResponse struct { @@ -38,7 +42,7 @@ type createFileResponse struct { func (r createFileResponse) error() error { return r.Err } -func createFileEndpoint(s Service, r Repository) endpoint.Endpoint { +func createFileEndpoint(s Service, r Repository, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(createFileRequest) @@ -52,9 +56,14 @@ func createFileEndpoint(s Service, r Repository) endpoint.Endpoint { req.File.ID = NextID() } + err := r.StoreFile(req.File) + if req.requestId != "" && logger != nil { + logger.Log("files", "createFile", "requestId", req.requestId, "error", err) + } + return createFileResponse{ ID: req.File.ID, - Err: r.StoreFile(req.File), + Err: err, }, nil } } @@ -63,6 +72,8 @@ func decodeCreateFileRequest(_ context.Context, request *http.Request) (interfac var r io.Reader var req createFileRequest + req.requestId = moovhttp.GetRequestId(request) + // Sets default values req.File = ach.NewFile() bs, err := ioutil.ReadAll(request.Body) @@ -90,7 +101,9 @@ func decodeCreateFileRequest(_ context.Context, request *http.Request) (interfac return req, nil } -type getFilesRequest struct{} +type getFilesRequest struct { + requestId string +} type getFilesResponse struct { Files []*ach.File `json:"files"` @@ -111,11 +124,15 @@ func getFilesEndpoint(s Service) endpoint.Endpoint { } func decodeGetFilesRequest(_ context.Context, r *http.Request) (interface{}, error) { - return getFilesRequest{}, nil + return getFilesRequest{ + requestId: moovhttp.GetRequestId(r), + }, nil } type getFileRequest struct { ID string + + requestId string } type getFileResponse struct { @@ -125,13 +142,18 @@ type getFileResponse struct { func (r getFileResponse) error() error { return r.Err } -func getFileEndpoint(s Service) endpoint.Endpoint { +func getFileEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(getFileRequest) - f, e := s.GetFile(req.ID) + f, err := s.GetFile(req.ID) + + if req.requestId != "" && logger != nil { + logger.Log("files", "getFile", "requestId", req.requestId, "error", err) + } + return getFileResponse{ File: f, - Err: e, + Err: err, }, nil } } @@ -142,11 +164,16 @@ func decodeGetFileRequest(_ context.Context, r *http.Request) (interface{}, erro if !ok { return nil, ErrBadRouting } - return getFileRequest{ID: id}, nil + return getFileRequest{ + ID: id, + requestId: moovhttp.GetRequestId(r), + }, nil } type deleteFileRequest struct { ID string + + requestId string } type deleteFileResponse struct { @@ -155,11 +182,17 @@ type deleteFileResponse struct { func (r deleteFileResponse) error() error { return r.Err } -func deleteFileEndpoint(s Service) endpoint.Endpoint { +func deleteFileEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(deleteFileRequest) + err := s.DeleteFile(req.ID) + + if req.requestId != "" && logger != nil { + logger.Log("files", "deleteFile", "requestId", req.requestId, "error", err) + } + return deleteFileResponse{ - Err: s.DeleteFile(req.ID), + Err: err, }, nil } } @@ -170,11 +203,16 @@ func decodeDeleteFileRequest(_ context.Context, r *http.Request) (interface{}, e if !ok { return nil, ErrBadRouting } - return deleteFileRequest{ID: id}, nil + return deleteFileRequest{ + ID: id, + requestId: moovhttp.GetRequestId(r), + }, nil } type getFileContentsRequest struct { ID string + + requestId string } type getFileContentsResponse struct { @@ -183,14 +221,18 @@ type getFileContentsResponse struct { func (v getFileContentsResponse) error() error { return v.Err } -func getFileContentsEndpoint(s Service) endpoint.Endpoint { +func getFileContentsEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(getFileContentsRequest) r, err := s.GetFileContents(req.ID) + + if req.requestId != "" && logger != nil { + logger.Log("files", "getFileContents", "requestId", req.requestId, "error", err) + } if err != nil { - // TODO(adam): log? if requestId != "" return getFileContentsResponse{Err: err}, nil } + return r, nil } } @@ -201,11 +243,16 @@ func decodeGetFileContentsRequest(_ context.Context, r *http.Request) (interface if !ok { return nil, ErrBadRouting } - return getFileContentsRequest{ID: id}, nil + return getFileContentsRequest{ + ID: id, + requestId: moovhttp.GetRequestId(r), + }, nil } type validateFileRequest struct { ID string + + requestId string } type validateFileResponse struct { @@ -214,11 +261,17 @@ type validateFileResponse struct { func (v validateFileResponse) error() error { return v.Err } -func validateFileEndpoint(s Service) endpoint.Endpoint { +func validateFileEndpoint(s Service, logger log.Logger) endpoint.Endpoint { return func(_ context.Context, request interface{}) (interface{}, error) { req := request.(validateFileRequest) + err := s.ValidateFile(req.ID) + + if req.requestId != "" && logger != nil { + logger.Log("files", "validateFile", "requestId", req.requestId, "error", err) + } + return validateFileResponse{ - Err: s.ValidateFile(req.ID), + Err: err, }, nil } } @@ -229,5 +282,8 @@ func decodeValidateFileRequest(_ context.Context, r *http.Request) (interface{}, if !ok { return nil, ErrBadRouting } - return validateFileRequest{ID: id}, nil + return validateFileRequest{ + ID: id, + requestId: moovhttp.GetRequestId(r), + }, nil } diff --git a/server/logging.go b/server/logging.go deleted file mode 100644 index fa5d8d088..000000000 --- a/server/logging.go +++ /dev/null @@ -1,143 +0,0 @@ -// Copyright 2018 The Moov Authors -// Use of this source code is governed by an Apache License -// license that can be found in the LICENSE file. - -package server - -import ( - "fmt" - "io" - "time" - - "github.com/moov-io/ach" - - "github.com/go-kit/kit/log" -) - -// Middleware describes a service (as opposed to endpoint) middleware. -type Middleware func(Service) Service - -func LoggingMiddleware(logger log.Logger) Middleware { - return func(next Service) Service { - return &loggingMiddleware{ - next: next, - logger: logger, - } - } -} - -type loggingMiddleware struct { - next Service - logger log.Logger -} - -// timer represents a one-time stoppable time tracker -// it's assumed startTimer() is called to initialize a timer -type timer struct { - start, end time.Time -} - -func startTimer() *timer { - return &timer{ - start: time.Now(), - } -} - -// stop returns the number of milliseconds for the given timer -// and stops the timer. -func (t *timer) stop() int64 { - when := time.Now() - if t.end.IsZero() { - t.end = when - } - return t.end.Sub(t.start).Nanoseconds() / 1e6 -} -func (t *timer) String() string { - return fmt.Sprintf("%dms", t.stop()) -} - -// Middleware endpoints - -func (mw loggingMiddleware) CreateFile(f *ach.FileHeader) (id string, err error) { - t := startTimer() - defer func() { - // f.ID can be empty here if the request does not specify it, do we care? - // The ID is properly generated and stored, so there's no "issue", just flakey logs. - mw.logger.Log("method", "CreateFile", "id", f.ID, "took", t, "err", err) - }() - return mw.next.CreateFile(f) -} - -func (mw loggingMiddleware) GetFile(id string) (f *ach.File, err error) { - t := startTimer() - defer func() { - mw.logger.Log("method", "GetFile", "id", id, "took", t, "err", err) - }() - return mw.next.GetFile(id) -} - -func (mw loggingMiddleware) GetFiles() []*ach.File { - t := startTimer() - defer func() { - mw.logger.Log("method", "GetFiles", "took", t) - }() - return mw.next.GetFiles() -} - -func (mw loggingMiddleware) DeleteFile(id string) (err error) { - t := startTimer() - defer func() { - mw.logger.Log("method", "DeleteFile", "id", id, "took", t) - }() - return mw.next.DeleteFile(id) -} - -func (mw loggingMiddleware) GetFileContents(id string) (io.Reader, error) { - t := startTimer() - defer func() { - mw.logger.Log("method", "GetFileContents", "id", id, "took", t) - }() - return mw.next.GetFileContents(id) -} - -func (mw loggingMiddleware) ValidateFile(id string) error { - t := startTimer() - defer func() { - mw.logger.Log("method", "ValidateFile", "id", id, "took", t) - }() - return mw.next.ValidateFile(id) -} - -//** BATCHES ** // - -func (mw loggingMiddleware) CreateBatch(fileID string, batch ach.Batcher) (id string, err error) { - t := startTimer() - defer func() { - mw.logger.Log("method", "CreateBatch", "FileID", fileID, "batchID", batch.ID, "took", t, "err", err) - }() - return mw.next.CreateBatch(fileID, batch) -} - -func (mw loggingMiddleware) GetBatch(fileID string, batchID string) (b ach.Batcher, err error) { - t := startTimer() - defer func() { - mw.logger.Log("method", "GetBatch", "fileID", fileID, "batchID", batchID, "took", t, "err", err) - }() - return mw.next.GetBatch(fileID, batchID) -} - -func (mw loggingMiddleware) GetBatches(fileID string) []ach.Batcher { - t := startTimer() - defer func() { - mw.logger.Log("method", "GetBatches", "fileID", fileID, "took", t) - }() - return mw.next.GetBatches(fileID) -} - -func (mw loggingMiddleware) DeleteBatch(fileID string, batchID string) (err error) { - t := startTimer() - defer func() { - mw.logger.Log("method", "DeleteBatch", "fileID", fileID, "batchID", batchID, "took", t, "err", err) - }() - return mw.next.DeleteBatch(fileID, batchID) -} diff --git a/server/routing.go b/server/routing.go index aea497ad0..348902208 100644 --- a/server/routing.go +++ b/server/routing.go @@ -99,55 +99,55 @@ func MakeHTTPHandler(s Service, repo Repository, logger log.Logger) http.Handler options..., )) r.Methods("POST").Path("/files/create").Handler(httptransport.NewServer( - createFileEndpoint(s, repo), + createFileEndpoint(s, repo, logger), decodeCreateFileRequest, encodeResponse, options..., )) r.Methods("GET").Path("/files/{id}").Handler(httptransport.NewServer( - getFileEndpoint(s), + getFileEndpoint(s, logger), decodeGetFileRequest, encodeResponse, options..., )) r.Methods("GET").Path("/files/{id}/contents").Handler(httptransport.NewServer( - getFileContentsEndpoint(s), + getFileContentsEndpoint(s, logger), decodeGetFileContentsRequest, encodeTextResponse, options..., )) r.Methods("GET").Path("/files/{id}/validate").Handler(httptransport.NewServer( - validateFileEndpoint(s), + validateFileEndpoint(s, logger), decodeValidateFileRequest, encodeResponse, options..., )) r.Methods("DELETE").Path("/files/{id}").Handler(httptransport.NewServer( - deleteFileEndpoint(s), + deleteFileEndpoint(s, logger), decodeDeleteFileRequest, encodeResponse, options..., )) r.Methods("POST").Path("/files/{fileID}/batches").Handler(httptransport.NewServer( - createBatchEndpoint(s), + createBatchEndpoint(s, logger), decodeCreateBatchRequest, encodeResponse, options..., )) r.Methods("GET").Path("/files/{fileID}/batches").Handler(httptransport.NewServer( - getBatchesEndpoint(s), + getBatchesEndpoint(s, logger), decodeGetBatchesRequest, encodeResponse, options..., )) r.Methods("GET").Path("/files/{fileID}/batches/{batchID}").Handler(httptransport.NewServer( - getBatchEndpoint(s), + getBatchEndpoint(s, logger), decodeGetBatchRequest, encodeResponse, options..., )) r.Methods("DELETE").Path("/files/{fileID}/batches/{batchID}").Handler(httptransport.NewServer( - deleteBatchEndpoint(s), + deleteBatchEndpoint(s, logger), decodeDeleteBatchRequest, encodeResponse, options...,