From adc0b9233fa4a0b2b449e27336d9ae39c75819ba Mon Sep 17 00:00:00 2001 From: Vladimir Shushlin Date: Fri, 28 Jan 2022 15:47:48 +0300 Subject: fix: fix metrics and logs not including domain resolution time Currently we do logging and metrics capturing after we did the domain information lookup. It allows us to add more information to access logs. But it also distorts metrics because domain information lookup takes time. This logic was originally introduced in https://gitlab.com/gitlab-org/gitlab-pages/-/merge_requests/157/diffs It didn't matter back than because we didn't lookup domain via API as we do now. Now it does matter. So this commits moves metrics and logging middlewares almost to the top of pipeline. Changelog: fixed --- internal/domain/logging.go | 31 -------------- internal/domain/logging_test.go | 71 -------------------------------- internal/logging/logging.go | 24 ++++------- internal/logging/logging_test.go | 87 ---------------------------------------- 4 files changed, 7 insertions(+), 206 deletions(-) delete mode 100644 internal/domain/logging.go delete mode 100644 internal/domain/logging_test.go delete mode 100644 internal/logging/logging_test.go (limited to 'internal') diff --git a/internal/domain/logging.go b/internal/domain/logging.go deleted file mode 100644 index 2ecddf6c..00000000 --- a/internal/domain/logging.go +++ /dev/null @@ -1,31 +0,0 @@ -package domain - -import ( - "net/http" - - "gitlab.com/gitlab-org/labkit/log" -) - -func LogFields(r *http.Request) log.Fields { - logFields := log.Fields{ - "pages_https": r.URL.Scheme == "https", - "pages_host": GetHost(r), - } - - d := FromRequest(r) - if d == nil { - return logFields - } - - lp, err := d.GetLookupPath(r) - if err != nil { - logFields["error"] = err.Error() - return logFields - } - - logFields["pages_project_serving_type"] = lp.ServingType - logFields["pages_project_prefix"] = lp.Prefix - logFields["pages_project_id"] = lp.ProjectID - - return logFields -} diff --git a/internal/domain/logging_test.go b/internal/domain/logging_test.go deleted file mode 100644 index b736758c..00000000 --- a/internal/domain/logging_test.go +++ /dev/null @@ -1,71 +0,0 @@ -package domain - -import ( - "net/http" - "testing" - - log "github.com/sirupsen/logrus" - "github.com/stretchr/testify/require" - - "gitlab.com/gitlab-org/gitlab-pages/internal/serving" -) - -type resolver struct { - err error - f func(*http.Request) *serving.LookupPath -} - -func (r *resolver) Resolve(req *http.Request) (*serving.Request, error) { - if r.f != nil { - return &serving.Request{LookupPath: r.f(req)}, nil - } - - return nil, r.err -} - -func TestDomainLogFields(t *testing.T) { - domainWithResolver := New("", "", "", &resolver{f: func(*http.Request) *serving.LookupPath { - return &serving.LookupPath{ - ServingType: "file", - ProjectID: 100, - Prefix: "/prefix", - } - }}) - - tests := map[string]struct { - domain *Domain - host string - expectedFields log.Fields - }{ - "nil_domain_returns_empty_fields": { - domain: nil, - host: "gitlab.io", - expectedFields: log.Fields{"pages_https": false, "pages_host": "gitlab.io"}, - }, - "unresolved_domain_returns_error": { - domain: New("githost.io", "", "", &resolver{err: ErrDomainDoesNotExist}), - host: "gitlab.io", - expectedFields: log.Fields{"error": ErrDomainDoesNotExist.Error(), "pages_https": false, "pages_host": "gitlab.io"}, - }, - "domain_with_fields": { - domain: domainWithResolver, - host: "gitlab.io", - expectedFields: log.Fields{ - "pages_https": false, - "pages_host": "gitlab.io", - "pages_project_id": uint64(100), - "pages_project_prefix": "/prefix", - "pages_project_serving_type": "file", - }, - }, - } - for name, tt := range tests { - t.Run(name, func(t *testing.T) { - r, err := http.NewRequest("GET", "/", nil) - require.NoError(t, err) - - r = ReqWithHostAndDomain(r, tt.host, tt.domain) - require.Equal(t, tt.expectedFields, LogFields(r)) - }) - } -} diff --git a/internal/logging/logging.go b/internal/logging/logging.go index edc670d6..6e8533d8 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -52,34 +52,24 @@ func getAccessLogger(format string) (*logrus.Logger, error) { } // BasicAccessLogger configures the GitLab pages basic HTTP access logger middleware -func BasicAccessLogger(handler http.Handler, format string, extraFields log.ExtraFieldsGeneratorFunc) (http.Handler, error) { +func BasicAccessLogger(handler http.Handler, format string) (http.Handler, error) { accessLogger, err := getAccessLogger(format) if err != nil { return nil, err } return log.AccessLogger(handler, - log.WithExtraFields(enrichExtraFields(extraFields)), + log.WithExtraFields(extraFields), log.WithAccessLogger(accessLogger), log.WithXFFAllowed(func(sip string) bool { return false }), ), nil } -func enrichExtraFields(extraFields log.ExtraFieldsGeneratorFunc) log.ExtraFieldsGeneratorFunc { - return func(r *http.Request) log.Fields { - enrichedFields := log.Fields{ - "correlation_id": correlation.ExtractFromContext(r.Context()), - "pages_https": request.IsHTTPS(r), - "pages_host": r.Host, - } - - if extraFields != nil { - for field, value := range extraFields(r) { - enrichedFields[field] = value - } - } - - return enrichedFields +func extraFields(r *http.Request) log.Fields { + return log.Fields{ + "correlation_id": correlation.ExtractFromContext(r.Context()), + "pages_https": request.IsHTTPS(r), + "pages_host": r.Host, } } diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go deleted file mode 100644 index d56f6777..00000000 --- a/internal/logging/logging_test.go +++ /dev/null @@ -1,87 +0,0 @@ -package logging - -import ( - "net/http" - "testing" - - "github.com/stretchr/testify/require" - - "gitlab.com/gitlab-org/gitlab-pages/internal/domain" - "gitlab.com/gitlab-org/gitlab-pages/internal/request" - "gitlab.com/gitlab-org/gitlab-pages/internal/serving" -) - -type resolver struct { - err error - f func(*http.Request) *serving.LookupPath -} - -func (r *resolver) Resolve(req *http.Request) (*serving.Request, error) { - if r.f != nil { - return &serving.Request{LookupPath: r.f(req)}, nil - } - - return nil, r.err -} - -func TestGetExtraLogFields(t *testing.T) { - domainWithResolver := domain.New("", "", "", &resolver{f: func(*http.Request) *serving.LookupPath { - return &serving.LookupPath{ - ServingType: "file", - ProjectID: 100, - Prefix: "/prefix", - SHA256: "foo", - } - }}) - - tests := []struct { - name string - scheme string - host string - expectedHTTPS interface{} - expectedHost interface{} - expectedProjectID interface{} - expectedProjectPrefix interface{} - expectedServingType interface{} - expectedErrMsg interface{} - }{ - { - name: "https", - scheme: request.SchemeHTTPS, - host: "githost.io", - expectedHTTPS: true, - expectedHost: "githost.io", - expectedProjectID: uint64(100), - expectedProjectPrefix: "/prefix", - expectedServingType: "file", - }, - { - name: "http", - scheme: request.SchemeHTTP, - host: "githost.io", - expectedHTTPS: false, - expectedHost: "githost.io", - expectedProjectID: uint64(100), - expectedProjectPrefix: "/prefix", - expectedServingType: "file", - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - req, err := http.NewRequest("GET", "/", nil) - require.NoError(t, err) - - req.URL.Scheme = tt.scheme - req = domain.ReqWithHostAndDomain(req, tt.host, domainWithResolver) - - got := domain.LogFields(req) - require.Equal(t, tt.expectedHTTPS, got["pages_https"]) - require.Equal(t, tt.expectedHost, got["pages_host"]) - require.Equal(t, tt.expectedProjectID, got["pages_project_id"]) - require.Equal(t, tt.expectedProjectPrefix, got["pages_project_prefix"]) - require.Equal(t, tt.expectedServingType, got["pages_project_serving_type"]) - require.Equal(t, tt.expectedErrMsg, got["error"]) - }) - } -} -- cgit v1.2.3