Repository: caicloud/nirvana
Pull request #313 (2020-04-28 10:07:18)

feat(middleware): implemented two reqlog middlewares
<!--  Thanks for sending a pull request! See below for tips! -->

**What this PR does / why we need it**:

Added two middleware that mimick the functionality of the `reqlog` plugin. Unlike a plugin, with these middlewares, the user would be able to enable request log only for a subset of their descriptors.

**Which issue(s) this PR is related to** *(optional, link to 3rd issue(s))*:

Fixes #

Reference to #
<!-- 填在 Fixes，PR 合并就会关 issue。填在 Reference to 会关联 issue，不会联动关闭。-->

**Special notes for your reviewer**:

/cc @iawia002 @supereagle 

<!-- Please answer the following questions during the code freeze, and delete this line.
**Code freeze questions**

1. What causes this PR to not be merged before code freeze?
2. Why this PR is absolutely necessary for this version? Paste a screenshot of smoke testing docs if you could.
3. What's the effects after merging it?
4. Is there anyway we can skip this to not affect the overall process?
-->

**Release note**:
<!--  Write your release note:
1. Enter your extended release note in the below block. If the PR requires additional action from users switching to the new release, include the string "action required".
2. If no release note is required, just write "NONE".
-->

```release-note
NONE
```

<!--  Thanks for sending a pull request! Here are some tips:

1. https://github.com/caicloud/engineering/blob/master/guidelines/review_conventions.md      <-- what is the review process looks like
2. https://github.com/caicloud/engineering/blob/master/guidelines/git_commit_conventions.md  <-- how to structure your git commit
3. https://github.com/caicloud/engineering/blob/master/guidelines/caicloud_bot.md            <-- how to work with caicloud bot

Other tips:

If this is your first contribution, read our Getting Started guide https://github.com/caicloud/engineering/blob/master/guidelines/README.md
-->


caicloud-bot: [APPROVALNOTIFIER] This PR is **NOT APPROVED**

This pull-request has been approved by: 
To fully approve this pull request, please assign additional approvers.
We suggest the following additional approver: **iawia002**

Assign the PR to them by writing `/assign @iawia002` in a comment when ready.

The full list of commands accepted by this bot can be found [here](https://github.com/caicloud/engineering/blob/master/guidelines/caicloud_bot.md#bot-commands).

The pull request process is described [here](https://github.com/caicloud/engineering/blob/master/guidelines/caicloud_bot.md#typical-workflow)

<details open>
Needs approval from an approver in each of these files:

- **[OWNERS](https://github.com/caicloud/nirvana/blob/master/OWNERS)**

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":["iawia002"]} -->
lichuan0620: Moved from go-common.

I plan to also implement a metric middleware after #309 is merged.

Patch:
diff --git a/middlewares/reqlog/reqlog.go b/middlewares/reqlog/reqlog.go
new file mode 100644
index 0000000..48d0079
--- /dev/null
+++ b/middlewares/reqlog/reqlog.go
@@ -0,0 +1,70 @@
+/*
+Copyright 2017 Caicloud Authors
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package reqlog
+
+import (
+	"context"
+	"time"
+
+	"github.com/caicloud/nirvana/definition"
+	"github.com/caicloud/nirvana/log"
+	"github.com/caicloud/nirvana/service"
+)
+
+// Default returns a reqlog middleware that uses the default Nirvana logger.
+func Default() definition.Middleware {
+	return func(ctx context.Context, chain definition.Chain) error {
+		start := time.Now()
+		httpCtx := service.HTTPContextFrom(ctx)
+
+		err := chain.Continue(ctx)
+
+		request := httpCtx.Request()
+		response := httpCtx.ResponseWriter()
+		log.Infoln(
+			request.Method,
+			response.StatusCode(),
+			response.ContentLength(),
+			time.Since(start).String(),
+			request.URL.String(),
+		)
+
+		return err
+	}
+}
+
+// Custom returns a reqlog middleware with a custom logger and designated logging level.
+func Custom(logger log.Logger, level log.Level) definition.Middleware {
+	return func(ctx context.Context, chain definition.Chain) error {
+		start := time.Now()
+		httpCtx := service.HTTPContextFrom(ctx)
+
+		err := chain.Continue(ctx)
+
+		request := httpCtx.Request()
+		response := httpCtx.ResponseWriter()
+		logger.V(level).Infoln(
+			request.Method,
+			response.StatusCode(),
+			response.ContentLength(),
+			time.Since(start).String(),
+			request.URL.String(),
+		)
+
+		return err
+	}
+}
diff --git a/plugins/metrics/metrics.go b/plugins/metrics/metrics.go
index 9b5ca22..e1565ba 100644
--- a/plugins/metrics/metrics.go
+++ b/plugins/metrics/metrics.go
@@ -18,7 +18,6 @@ package metrics
 
 import (
 	"context"
-	"net/http"
 	"strconv"
 	"time"
 
@@ -45,36 +44,29 @@ type config struct {
 type metricsInstaller struct{}
 
 func newMetricsMiddleware(namespace string) definition.Middleware {
+	constLabel := prometheus.Labels{"component": namespace}
 	requestCounter := prometheus.NewCounterVec(
 		prometheus.CounterOpts{
-			Namespace: namespace,
-			Name:      "request_count",
-			Help:      "Counter of server requests broken out for each verb, API resource, client, and HTTP response contentType and code.",
+			Namespace:   namespace,
+			Name:        "request_total",
+			Help:        "Counter of server requests broken out for each verb, API resource, and HTTP response code.",
+			ConstLabels: constLabel,
 		},
-		[]string{"method", "path", "client", "contentType", "code"},
+		[]string{"method", "path", "code"},
 	)
 	requestLatencies := prometheus.NewHistogramVec(
 		prometheus.HistogramOpts{
-			Namespace: namespace,
-			Name:      "request_latencies",
-			Help:      "Response latency distribution in milliseconds for each verb, resource and client.",
-			Buckets:   prometheus.ExponentialBuckets(0.1, 2.0, 20),
-		},
-		[]string{"method", "path"},
-	)
-	requestLatenciesSummary := prometheus.NewSummaryVec(
-		prometheus.SummaryOpts{
-			Namespace: namespace,
-			Name:      "request_latencies_summary",
-			Help:      "Response latency summary in milliseconds for each verb and resource.",
-			MaxAge:    time.Hour,
+			Namespace:   namespace,
+			Name:        "request_duration_seconds",
+			Help:        "Response latency distribution in seconds for each verb, resource and client.",
+			ConstLabels: constLabel,
+			Buckets:     prometheus.DefBuckets,
 		},
 		[]string{"method", "path"},
 	)
 
 	prometheus.MustRegister(requestCounter)
 	prometheus.MustRegister(requestLatencies)
-	prometheus.MustRegister(requestLatenciesSummary)
 
 	return func(ctx context.Context, next definition.Chain) error {
 		startTime := time.Now()
@@ -84,25 +76,14 @@ func newMetricsMiddleware(namespace string) definition.Middleware {
 		req := httpCtx.Request()
 		resp := httpCtx.ResponseWriter()
 		path := httpCtx.RoutePath()
-		elapsed := float64((time.Since(startTime)) / time.Millisecond)
 
-		requestCounter.WithLabelValues(req.Method, path, getHTTPClient(req), req.Header.Get("Content-Type"), strconv.Itoa(resp.StatusCode())).Inc()
-		requestLatencies.WithLabelValues(req.Method, path).Observe(elapsed)
-		requestLatenciesSummary.WithLabelValues(req.Method, path).Observe(elapsed)
+		requestCounter.WithLabelValues(req.Method, path, strconv.Itoa(resp.StatusCode())).Inc()
+		requestLatencies.WithLabelValues(req.Method, path).Observe(float64((time.Since(startTime)) / time.Second))
 
 		return err
 	}
 }
 
-func getHTTPClient(req *http.Request) string {
-	if userAgent, ok := req.Header["User-Agent"]; ok {
-		if len(userAgent) > 0 {
-			return userAgent[0]
-		}
-	}
-	return "unknown"
-}
-
 // Name is the external config name.
 func (i *metricsInstaller) Name() string {
 	return ExternalConfigName
diff --git a/service/filter.go b/service/filter.go
index 88b22e6..9f2247a 100644
--- a/service/filter.go
+++ b/service/filter.go
@@ -64,10 +64,10 @@ func FillLeadingSlash() Filter {
 	}
 }
 
-// ParseRequestForm returns a filter to parse request form when content
+// ParseRequestFormWithMaxMemory returns a filter to parse request form when content
 // type is "application/x-www-form-urlencoded" or "multipart/form-data".
 // The filter won't filter anything unless some error occurs in parsing.
-func ParseRequestForm() Filter {
+func ParseRequestFormWithMaxMemory(maxMemory int64) Filter {
 	return func(resp http.ResponseWriter, req *http.Request) bool {
 		ct, err := ContentType(req)
 		if err == nil {
@@ -75,7 +75,7 @@ func ParseRequestForm() Filter {
 			case definition.MIMEURLEncoded:
 				err = req.ParseForm()
 			case definition.MIMEFormData:
-				err = req.ParseMultipartForm(32 << 20)
+				err = req.ParseMultipartForm(maxMemory)
 			default:
 				req.Form = req.URL.Query()
 			}
@@ -88,6 +88,12 @@ func ParseRequestForm() Filter {
 	}
 }
 
+// ParseRequestForm returns a filter to parse request form.
+// Same as ParseRequestFormWithMaxMemory, except that maxMemory is set to 32MB by default.
+func ParseRequestForm() Filter {
+	return ParseRequestFormWithMaxMemory(32 << 20)
+}
+
 // isGTZero returns a boolean result indicating if the content length is greater than 0.
 func isGTZero(length string) bool {
 	if length == "" {


Test patch:
diff --git a/middlewares/reqlog/reqlog_test.go b/middlewares/reqlog/reqlog_test.go
new file mode 100644
index 0000000..21d28ab
--- /dev/null
+++ b/middlewares/reqlog/reqlog_test.go
@@ -0,0 +1,231 @@
+/*
+Copyright 2017 Caicloud Authors
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package reqlog
+
+import (
+	"bytes"
+	"context"
+	"fmt"
+	"io"
+	"io/ioutil"
+	"net/http"
+	"net/url"
+	"os"
+	"regexp"
+	"strings"
+	"testing"
+
+	"github.com/caicloud/nirvana/definition"
+	"github.com/caicloud/nirvana/log"
+	"github.com/caicloud/nirvana/service"
+)
+
+const tenantHeader = "X-Tenant"
+
+type responseWriter struct {
+	code   int
+	header http.Header
+	buf    *bytes.Buffer
+}
+
+func newRW() *responseWriter {
+	return &responseWriter{0, http.Header{}, bytes.NewBuffer(nil)}
+}
+
+func (r *responseWriter) Header() http.Header {
+	return r.header
+}
+
+func (r *responseWriter) Write(d []byte) (int, error) {
+	return r.buf.Write(d)
+}
+
+func (r *responseWriter) WriteHeader(code int) {
+	r.code = code
+}
+
+func mustURL(rawURL string) *url.URL {
+	u, _ := url.Parse(rawURL)
+	return u
+}
+
+func buildService(middleware definition.Middleware) (service.Service, error) {
+	builder := service.NewBuilder()
+	builder.SetModifier(service.FirstContextParameter())
+	if err := builder.AddDescriptor(
+		definition.Descriptor{
+			Path:        "/api/v1/foo",
+			Consumes:    []string{"*/*"},
+			Produces:    []string{"application/json"},
+			Middlewares: []definition.Middleware{middleware},
+			Definitions: []definition.Definition{
+				{
+					Method: definition.Create,
+					Parameters: []definition.Parameter{
+						definition.HeaderParameterFor(tenantHeader, ""),
+						definition.QueryParameterFor("query", ""),
+						definition.BodyParameterFor(""),
+					},
+					Function: func(ctx context.Context, tenant, query string, body []byte) (string, error) {
+						request := service.HTTPContextFrom(ctx).Request()
+						return fmt.Sprintf(
+							"%s %s %s %s %s",
+							request.Method, request.URL.String(),
+							tenant, query, string(body),
+						), nil
+					},
+					Results: definition.DataErrorResults(""),
+				},
+				{
+					Method: definition.Get,
+					Parameters: []definition.Parameter{
+						definition.HeaderParameterFor(tenantHeader, ""),
+						definition.QueryParameterFor("query", ""),
+					},
+					Function: func(ctx context.Context, tenant, query string) (string, error) {
+						request := service.HTTPContextFrom(ctx).Request()
+						return fmt.Sprintf(
+							"%s %s %s %s",
+							request.Method, request.URL.String(), tenant, query,
+						), nil
+					},
+					Results: definition.DataErrorResults(""),
+				},
+			},
+		},
+	); err != nil {
+		return nil, err
+	}
+	return builder.Build()
+}
+
+type testCase struct {
+	name      string
+	req       http.Request
+	wantRegex string
+	respStr   string
+	respCode  int
+}
+
+func buildTestCases() []testCase {
+	return []testCase{
+		{
+			name: "POST",
+			req: http.Request{
+				Method: http.MethodPost,
+				URL:    mustURL("/api/v1/foo?query=bar"),
+				Header: http.Header{
+					"Content-Type": []string{"application/json"},
+					"Accept":       []string{"application/json"},
+					"X-Tenant":     []string{"system-tenant"},
+				},
+				Body: ioutil.NopCloser(strings.NewReader("{\"key\": \"value\"}")),
+			},
+			wantRegex: `^INFO\s(.+) | POST 201 61 [-+]?([0-9]*(\.[0-9]*)?[a-z]+)+ /api/v1/foo?query=bar$`,
+			respStr:   `POST /api/v1/foo?query=bar system-tenant bar {"key": "value"}`,
+			respCode:  201,
+		},
+		{
+			name: "GET",
+			req: http.Request{
+				Method: http.MethodGet,
+				URL:    mustURL("/api/v1/foo?query=bar"),
+				Header: http.Header{
+					"X-Tenant": []string{"system-tenant"},
+				},
+			},
+			wantRegex: `^INFO\s(.+) | GET 200 43 [-+]?([0-9]*(\.[0-9]*)?[a-z]+)+ /api/v1/foo?query=bar$`,
+			respStr:   `GET /api/v1/foo?query=bar system-tenant bar`,
+			respCode:  200,
+		},
+	}
+}
+
+func TestDefault(t *testing.T) {
+	for _, tc := range buildTestCases() {
+		t.Run(tc.name, func(t *testing.T) {
+			old := os.Stderr
+			r, w, _ := os.Pipe()
+			os.Stderr = w
+			outC := make(chan string)
+			go func() {
+				var buf bytes.Buffer
+				io.Copy(&buf, r)
+				outC <- buf.String()
+			}()
+
+			log.SetDefaultLogger(log.NewStdLogger(log.LevelDebug))
+			svc, err := buildService(Default())
+			if err != nil {
+				t.Fatal(err)
+			}
+			rw := newRW()
+			svc.ServeHTTP(rw, &tc.req)
+
+			w.Close()
+			out := <-outC
+			os.Stderr = old
+
+			if rw.buf.String() != tc.respStr {
+				t.Fatalf("%s != %s", rw.buf.String(), tc.respStr)
+			}
+			if rw.code != tc.respCode {
+				t.Fatal("unexpected response code, the middleware might have altered the request/response")
+			}
+			if !regexp.MustCompile(tc.wantRegex).MatchString(out) {
+				t.Fatal("unexpected log content")
+			}
+		})
+	}
+}
+
+func TestCustom(t *testing.T) {
+	for _, tc := range buildTestCases() {
+		t.Run(tc.name, func(t *testing.T) {
+			old := os.Stderr
+			r, w, _ := os.Pipe()
+			os.Stderr = w
+			outC := make(chan string)
+			go func() {
+				var buf bytes.Buffer
+				io.Copy(&buf, r)
+				outC <- buf.String()
+			}()
+
+			svc, err := buildService(Custom(log.NewStdLogger(0), 0))
+			if err != nil {
+				t.Fatal(err)
+			}
+			rw := newRW()
+			svc.ServeHTTP(rw, &tc.req)
+
+			w.Close()
+			out := <-outC
+			os.Stderr = old
+
+			if rw.buf.String() != tc.respStr {
+				t.Fatalf("%s != %s", rw.buf.String(), tc.respStr)
+			}
+			if rw.code != tc.respCode {
+				t.Fatal("unexpected response code, the middleware might have altered the request/response")
+			}
+			if !regexp.MustCompile(tc.wantRegex).MatchString(out) {
+				t.Fatal("unexpected log content")
+			}
+		})
+	}
+}