Enhance access log (#901)

* enhance access log

* fix test

* apply suggestions

* keep origin format

* simplify size formating

* improve formatting performance & fix test

* refactor variable delimiter

doc/reference/controllers.md

@@ -114,6 +114,25 @@ rules:
 | clientMaxBodySize | int64 | Max size of request body. the default value is 4MB. Requests with a body larger than this option are discarded. When this option is set to `-1`, Easegress takes the request body as a stream and the body can be any size, but some features are not possible in this case, please refer [Stream](./stream.md) for more information. | No |
 | caCertBase64 | string | Define the root certificate authorities that servers use if required to verify a client certificate by the policy in TLS Client Authentication. | No |
 | globalFilter | string | Name of [GlobalFilter](#globalfilter) for all backends | No |
+| accessLogFormat | string | Format of access log, default is `[{{Time}}] [{{RemoteAddr}} {{RealIP}} {{Method}} {{URI}} {{Proto}} {{StatusCode}}] [{{Duration}} rx:{{ReqSize}}B tx:{{RespSize}}B] [{{Tags}}]`, variable is delimited by "{{" and "}}", please refer [Access Log Variable](#accesslogvariable) for all built-in variables | No |
+
+### AccessLogVariable
+
+| Name | Description | 
+| ---------------- | ----------------------------------------------------------------- | 
+| Time | Start time for handling the request
+| RemoteAddr | Network address that sent the request
+| RealIP | Real IP of the request
+| Method | HTTP method (GET, POST, PUT, etc.) for the request
+| URI | Unmodified request-target of the Request-Line
+| Proto | Protocol version for the request
+| StatusCode | HTTP status code for the response
+| Duration | Duration time for handing the request
+| ReqSize | Size read from the request
+| RespSize | Size write to the response
+| ReqHeaders | Request HTTP headers
+| RespHeaders | Response HTTP headers
+| Tags | Tags for handing the request
 
 #### Pipeline
 

pkg/object/httpserver/mux.go

@@ -18,12 +18,16 @@
 package httpserver
 
 import (
+ "bytes"
  "fmt"
  "io"
  "net/http"
  "reflect"
+ "regexp"
  "strings"
  "sync/atomic"
+ "text/template"
+ "time"
 
  "github.com/megaease/easegress/pkg/object/httpserver/routers"
 
@@ -44,6 +48,10 @@ import (
  "github.com/prometheus/client_golang/prometheus"
 )
 
+const (
+ defaultAccessLogFormat = "[{{Time}}] [{{RemoteAddr}} {{RealIP}} {{Method}} {{URI}} {{Proto}} {{StatusCode}}] [{{Duration}} rx:{{ReqSize}}B tx:{{RespSize}}B] [{{Tags}}]"
+)
+
 type (
  mux struct {
  httpStat *httpstat.HTTPStat
@@ -53,11 +61,12 @@ type (
  }
 
  muxInstance struct {
- superSpec *supervisor.Spec
- spec *Spec
- httpStat *httpstat.HTTPStat
- topN *httpstat.TopN
- metrics *metrics
+ superSpec *supervisor.Spec
+ spec *Spec
+ httpStat *httpstat.HTTPStat
+ topN *httpstat.TopN
+ metrics *metrics
+ accessLogFormatter *accessLogFormatter
 
  muxMapper context.MuxMapper
 
@@ -73,6 +82,26 @@ type (
  code int
  route routers.Route
  }
+
+ accessLogFormatter struct {
+ template *template.Template
+ }
+
+ accessLog struct {
+ Time string
+ RemoteAddr string
+ RealIP string
+ Method string
+ URI string
+ Proto string
+ StatusCode int
+ Duration time.Duration
+ ReqSize uint64
+ RespSize uint64
+ ReqHeaders string
+ RespHeaders string
+ Tags string
+ }
 )
 
 var (
@@ -146,14 +175,15 @@ func (m *mux) reload(superSpec *supervisor.Spec, muxMapper context.MuxMapper) {
  }
 
  inst := &muxInstance{
- superSpec: superSpec,
- spec: spec,
- muxMapper: muxMapper,
- httpStat: m.httpStat,
- topN: m.topN,
- metrics: oldInst.metrics,
- ipFilter: ipfilter.New(spec.IPFilterSpec),
- tracer: tracer,
+ superSpec: superSpec,
+ spec: spec,
+ muxMapper: muxMapper,
+ httpStat: m.httpStat,
+ topN: m.topN,
+ metrics: oldInst.metrics,
+ ipFilter: ipfilter.New(spec.IPFilterSpec),
+ tracer: tracer,
+ accessLogFormatter: newAccessLogFormatter(spec.AccessLogFormat),
  }
  spec.Rules.Init()
  inst.router = routers.Create(routerKind, spec.Rules)
@@ -189,7 +219,7 @@ func buildFailureResponse(ctx *context.Context, statusCode int) *httpprot.Respon
  return resp
 }
 
-func (mi *muxInstance) sendResponse(ctx *context.Context, stdw http.ResponseWriter) (int, uint64) {
+func (mi *muxInstance) sendResponse(ctx *context.Context, stdw http.ResponseWriter) (int, uint64, http.Header) {
  var resp *httpprot.Response
  if v := ctx.GetResponse(context.DefaultNamespace); v == nil {
  logger.Errorf("%s: response is nil", mi.superSpec.Name())
@@ -209,7 +239,7 @@ func (mi *muxInstance) sendResponse(ctx *context.Context, stdw http.ResponseWrit
  stdw.WriteHeader(resp.StatusCode())
  respBodySize, _ := io.Copy(stdw, resp.GetPayload())
 
- return resp.StatusCode(), uint64(respBodySize) + uint64(resp.MetaSize())
+ return resp.StatusCode(), uint64(respBodySize) + uint64(resp.MetaSize()), header
 }
 
 func (mi *muxInstance) serveHTTP(stdw http.ResponseWriter, stdr *http.Request) {
@@ -237,12 +267,13 @@ func (mi *muxInstance) serveHTTP(stdw http.ResponseWriter, stdr *http.Request) {
 
  routeCtx := routers.NewContext(req)
  route := mi.search(routeCtx)
+ var respHeader http.Header
 
  defer func() {
  metric, _ := ctx.GetData("HTTP_METRIC").(*httpstat.Metric)
 
  if metric == nil {
- statusCode, respSize := mi.sendResponse(ctx, stdw)
+ statusCode, respSize, header := mi.sendResponse(ctx, stdw)
  ctx.Finish()
 
  // Drain off the body if it has not been, so that we can get the
@@ -254,6 +285,7 @@ func (mi *muxInstance) serveHTTP(stdw http.ResponseWriter, stdr *http.Request) {
  ReqSize: uint64(reqMetaSize) + uint64(body.BytesRead()),
  RespSize: respSize,
  }
+ respHeader = header
  } else { // hijacked, websocket and etc.
  ctx.Finish()
  }
@@ -269,18 +301,22 @@ func (mi *muxInstance) serveHTTP(stdw http.ResponseWriter, stdr *http.Request) {
 
  // Write access log.
  logger.LazyHTTPAccess(func() string {
- // log format:
- //
- // [$startTime]
- // [$remoteAddr $realIP $method $requestURL $proto $statusCode]
- // [$contextDuration $readBytes $writeBytes]
- // [$tags]
- const logFmt = "[%s] [%s %s %s %s %s %d] [%v rx:%dB tx:%dB] [%s]"
- return fmt.Sprintf(logFmt,
- fasttime.Format(startAt, fasttime.RFC3339Milli),
- stdr.RemoteAddr, req.RealIP(), stdr.Method, stdr.RequestURI,
- stdr.Proto, metric.StatusCode, metric.Duration, metric.ReqSize,
- metric.RespSize, ctx.Tags())
+ log := &accessLog{
+ Time: fasttime.Format(startAt, fasttime.RFC3339Milli),
+ RemoteAddr: stdr.RemoteAddr,
+ RealIP: req.RealIP(),
+ Method: stdr.Method,
+ URI: stdr.RequestURI,
+ Proto: stdr.Proto,
+ StatusCode: metric.StatusCode,
+ Duration: metric.Duration,
+ ReqSize: metric.ReqSize,
+ RespSize: metric.RespSize,
+ Tags: ctx.Tags(),
+ ReqHeaders: printHeader(stdr.Header),
+ RespHeaders: printHeader(respHeader),
+ }
+ return mi.accessLogFormatter.format(log)
  })
  }()
 
@@ -431,3 +467,36 @@ func (mi *muxInstance) exportPrometheusMetrics(stat *httpstat.Metric, backend st
  mi.metrics.RequestSizeBytesPercentage.With(labels).Observe(float64(stat.ReqSize))
  mi.metrics.ResponseSizeBytesPercentage.With(labels).Observe(float64(stat.RespSize))
 }
+
+func newAccessLogFormatter(format string) *accessLogFormatter {
+ if format == "" {
+ format = defaultAccessLogFormat
+ }
+ varReg := regexp.MustCompile(`\{\{([a-zA-z]*)\}\}`)
+ expr := varReg.ReplaceAllString(format, "{{.$1}}")
+ escapeReg := regexp.MustCompile(`(\[|\])`)
+ expr = escapeReg.ReplaceAllString(expr, "{{`$1`}}")
+ tpl := template.Must(template.New("").Parse(expr))
+ return &accessLogFormatter{template: tpl}
+}
+
+func (formatter *accessLogFormatter) format(log *accessLog) string {
+ var buf bytes.Buffer
+ if err := formatter.template.Execute(&buf, log); err != nil {
+ logger.Errorf("format access log failed: %v", err)
+ }
+ return buf.String()
+}
+
+func printHeader(header http.Header) string {
+ buf := bytes.Buffer{}
+ i := 0
+ for key, values := range header {
+ if i > 0 {
+ buf.WriteString(", ")
+ }
+ buf.WriteString(fmt.Sprintf("%v: %v", key, values))
+ i++
+ }
+ return buf.String()
+}

pkg/object/httpserver/mux_test.go

@@ -19,15 +19,16 @@ package httpserver
 
 import (
  "fmt"
- "github.com/megaease/easegress/pkg/logger"
- "github.com/megaease/easegress/pkg/object/httpserver/routers"
  "net/http"
  "net/http/httptest"
  "net/url"
  "strings"
  "testing"
  "testing/iotest"
 
+ "github.com/megaease/easegress/pkg/logger"
+ "github.com/megaease/easegress/pkg/object/httpserver/routers"
+
  "github.com/megaease/easegress/pkg/context"
  "github.com/megaease/easegress/pkg/context/contexttest"
  _ "github.com/megaease/easegress/pkg/object/httpserver/routers/ordered"
@@ -631,3 +632,14 @@ rules:
  assert.Equal(403, mi.search(routers.NewContext(req)).code)
 
 }
+
+func TestAccessLog(t *testing.T) {
+ log := &accessLog{
+ Method: "GET",
+ URI: "127.0.0.1",
+ ReqSize: 100,
+ }
+ formatter := newAccessLogFormatter("{{Method}} {{URI}} [{{ReqSize}}]")
+ s := formatter.format(log)
+ assert.Equal(t, "GET 127.0.0.1 [100]", s)
+}

pkg/object/httpserver/spec.go

@@ -61,6 +61,8 @@ type (
  Rules routers.Rules `json:"rules" jsonschema:"omitempty"`
 
  GlobalFilter string `json:"globalFilter,omitempty" jsonschema:"omitempty"`
+
+ AccessLogFormat string `json:"accessLogFormat" jsonshema:"omitempty"`
  }
 )