feat: add access log for Manager API (apache#994)

* feat: access log

* feat: access log

* chore: access log format

* chore: access log format

* test: add test case for access log

* chore: add access log example

* fix: according to review

* test: add unit test for `logging` middleware

* fix: license checker CI failed

api/conf/conf.go

@@ -48,6 +48,7 @@ var (
 	ETCDConfig       *Etcd
 	ErrorLogLevel    = "warn"
 	ErrorLogPath     = "logs/error.log"
+	AccessLogPath    = "logs/access.log"
 	UserList         = make(map[string]User, 2)
 	AuthConf         Authentication
 	SSLDefaultStatus = 1 //enable ssl by default
@@ -69,8 +70,13 @@ type ErrorLog struct {
 	FilePath string `yaml:"file_path"`
 }
 
+type AccessLog struct {
+	FilePath string `yaml:"file_path"`
+}
+
 type Log struct {
-	ErrorLog ErrorLog `yaml:"error_log"`
+	ErrorLog  ErrorLog  `yaml:"error_log"`
+	AccessLog AccessLog `yaml:"access_log"`
 }
 
 type Conf struct {
@@ -143,7 +149,18 @@ func setConf() {
 			ErrorLogPath = config.Conf.Log.ErrorLog.FilePath
 		}
 		if !filepath.IsAbs(ErrorLogPath) {
-			ErrorLogPath, err = filepath.Abs(WorkDir + "/" + ErrorLogPath)
+			ErrorLogPath, err = filepath.Abs(filepath.Join(WorkDir, ErrorLogPath))
+			if err != nil {
+				panic(err)
+			}
+		}
+
+		// access log
+		if config.Conf.Log.AccessLog.FilePath != "" {
+			AccessLogPath = config.Conf.Log.AccessLog.FilePath
+		}
+		if !filepath.IsAbs(AccessLogPath) {
+			AccessLogPath, err = filepath.Abs(filepath.Join(WorkDir, AccessLogPath))
 			if err != nil {
 				panic(err)
 			}

api/conf/conf.yaml

@@ -32,6 +32,11 @@ conf:
       file_path:
         logs/error.log  # supports relative path, absolute path, standard output
                         # such as: logs/error.log, /tmp/logs/error.log, /dev/stdout, /dev/stderr
+    access_log:
+      file_path:
+        logs/access.log  # supports relative path, absolute path, standard output
+                         # such as: logs/access.log, /tmp/logs/access.log, /dev/stdout, /dev/stderr
+                         # log example: 2020-12-09T16:38:09.039+0800	INFO	filter/logging.go:46	/apisix/admin/routes/r1	{"status": 401, "host": "127.0.0.1:9000", "query": "asdfsafd=adf&a=a", "requestId": "3d50ecb8-758c-46d1-af5b-cd9d1c820156", "latency": 0, "remoteIP": "127.0.0.1", "method": "PUT", "errs": []}
 authentication:
   secret:
     secret              # secret for jwt token generation.

api/filter/logging.go

@@ -16,4 +16,53 @@
  */
 package filter
 
-//for logging access log, will refactor it in a new pr.
+import (
+	"bytes"
+	"time"
+
+	"github.com/gin-gonic/gin"
+	"go.uber.org/zap"
+)
+
+func RequestLogHandler(logger *zap.SugaredLogger) gin.HandlerFunc {
+	return func(c *gin.Context) {
+		start, host, remoteIP, path, method := time.Now(), c.Request.Host, c.ClientIP(), c.Request.URL.Path, c.Request.Method
+		query := c.Request.URL.RawQuery
+		requestId := c.Writer.Header().Get("X-Request-Id")
+
+		blw := &bodyLogWriter{body: bytes.NewBuffer(nil), ResponseWriter: c.Writer}
+		c.Writer = blw
+		c.Next()
+		latency := time.Since(start) / 1000000
+		statusCode := c.Writer.Status()
+		//respBody := blw.body.String()
+
+		var errs []string
+		for _, err := range c.Errors {
+			errs = append(errs, err.Error())
+		}
+
+		logger.Desugar().Info(path,
+			//zap.String("path", path),
+			zap.Int("status", statusCode),
+			zap.String("host", host),
+			zap.String("query", query),
+			zap.String("requestId", requestId),
+			zap.Duration("latency", latency),
+			zap.String("remoteIP", remoteIP),
+			zap.String("method", method),
+			//zap.String("respBody", respBody),
+			zap.Strings("errs", errs),
+		)
+	}
+}
+
+type bodyLogWriter struct {
+	gin.ResponseWriter
+	body *bytes.Buffer
+}
+
+func (w bodyLogWriter) Write(b []byte) (int, error) {
+	w.body.Write(b)
+	return w.ResponseWriter.Write(b)
+}

api/filter/logging_test.go

@@ -0,0 +1,46 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You 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 filter
+
+import (
+        "net/http"
+        "net/http/httptest"
+        "testing"
+
+        "github.com/gin-gonic/gin"
+        "github.com/stretchr/testify/assert"
+
+        "github.com/apisix/manager-api/log"
+)
+
+func performRequest(r http.Handler, method, path string) *httptest.ResponseRecorder {
+        req := httptest.NewRequest(method, path, nil)
+        w := httptest.NewRecorder()
+        r.ServeHTTP(w, req)
+        return w
+}
+
+func TestRequestLogHandler(t *testing.T) {
+        r := gin.New()
+        logger := log.GetLogger(log.AccessLog)
+        r.Use(RequestLogHandler(logger))
+        r.GET("/", func(c *gin.Context) {
+        })
+
+        w := performRequest(r, "GET", "/")
+        assert.Equal(t, 200, w.Code)
+}

api/internal/route.go

@@ -35,6 +35,7 @@ import (
 	"github.com/apisix/manager-api/internal/handler/service"
 	"github.com/apisix/manager-api/internal/handler/ssl"
 	"github.com/apisix/manager-api/internal/handler/upstream"
+	"github.com/apisix/manager-api/log"
 )
 
 func SetUpRouter() *gin.Engine {
@@ -44,9 +45,10 @@ func SetUpRouter() *gin.Engine {
 		gin.SetMode(gin.ReleaseMode)
 	}
 	r := gin.New()
+	logger := log.GetLogger(log.AccessLog)
 	store := cookie.NewStore([]byte("secret"))
 	r.Use(sessions.Sessions("session", store))
-	r.Use(filter.CORS(), filter.Authentication(), filter.RequestId(), filter.RecoverHandler())
+	r.Use(filter.CORS(), filter.RequestId(), filter.RequestLogHandler(logger), filter.Authentication(), filter.RecoverHandler())
 	r.Use(static.Serve("/", static.LocalFile(conf.WebDir, false)))
 	r.NoRoute(func(c *gin.Context) {
 		c.File(fmt.Sprintf("%s/index.html", conf.WebDir))

api/log/log.go

@@ -20,6 +20,13 @@ var (
 	DefLogger Interface = emptyLog{}
 )
 
+type Type int8
+
+const (
+	AccessLog Type = iota - 1
+	ErrorLog
+)
+
 type emptyLog struct {
 }
 

api/log/zap.go

@@ -28,14 +28,22 @@ import (
 var logger *zap.SugaredLogger
 
 func init() {
-	writeSyncer := fileWriter()
-	encoder := getEncoder()
+	logger = GetLogger(ErrorLog)
+}
+
+func GetLogger(logType Type) *zap.SugaredLogger {
+	writeSyncer := fileWriter(logType)
+	encoder := getEncoder(logType)
 	logLevel := getLogLevel()
+	if logType == AccessLog {
+		logLevel = zapcore.InfoLevel
+	}
+
 	core := zapcore.NewCore(encoder, writeSyncer, logLevel)
 
 	zapLogger := zap.New(core, zap.AddCaller(), zap.AddCallerSkip(2))
 
-	logger = zapLogger.Sugar()
+	return zapLogger.Sugar()
 }
 
 func getLogLevel() zapcore.LevelEnabler {
@@ -57,23 +65,32 @@ func getLogLevel() zapcore.LevelEnabler {
 	return level
 }
 
-func getEncoder() zapcore.Encoder {
+func getEncoder(logType Type) zapcore.Encoder {
 	encoderConfig := zap.NewProductionEncoderConfig()
 	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
 	encoderConfig.EncodeLevel = zapcore.CapitalLevelEncoder
+
+	if logType == AccessLog {
+		encoderConfig.LevelKey = zapcore.OmitKey
+	}
+
 	return zapcore.NewConsoleEncoder(encoderConfig)
 }
 
-func fileWriter() zapcore.WriteSyncer {
+func fileWriter(logType Type) zapcore.WriteSyncer {
+	logPath := conf.ErrorLogPath
+	if logType == AccessLog {
+		logPath = conf.AccessLogPath
+	}
 	//standard output
-	if conf.ErrorLogPath == "/dev/stdout" {
+	if logPath == "/dev/stdout" {
 		return zapcore.Lock(os.Stdout)
 	}
-	if conf.ErrorLogPath == "/dev/stderr" {
+	if logPath == "/dev/stderr" {
 		return zapcore.Lock(os.Stderr)
 	}
 
-	writer, _, err := zap.Open(conf.ErrorLogPath)
+	writer, _, err := zap.Open(logPath)
 	if err != nil {
 		panic(err)
 	}

api/main.go

@@ -25,13 +25,13 @@ import (
 	"syscall"
 	"time"
 
-	"github.com/apisix/manager-api/internal/handler"
 	"github.com/shiningrush/droplet"
 
 	"github.com/apisix/manager-api/conf"
 	"github.com/apisix/manager-api/internal"
 	"github.com/apisix/manager-api/internal/core/storage"
 	"github.com/apisix/manager-api/internal/core/store"
+	"github.com/apisix/manager-api/internal/handler"
 	"github.com/apisix/manager-api/internal/utils"
 	"github.com/apisix/manager-api/log"
 )

api/test/shell/cli_test.sh

@@ -41,7 +41,7 @@ trap clean_up EXIT
 export GO111MODULE=on
 go build -o ./manager-api .
 
-#default level: warn, path: logs/error.log
+# default level: warn, path: logs/error.log
 
 ./manager-api &
 sleep 3
@@ -79,7 +79,7 @@ fi
 
 clean_logfile
 
-#change path
+# change path
 
 sed -i 's/logs\/error.log/.\/error.log/' conf/conf.yaml
 
@@ -113,6 +113,20 @@ fi
 # clean config
 clean_up
 
+# access log test
+./manager-api &
+sleep 3
+
+curl http://127.0.0.1:9000/apisix/admin/user/login -d '{"username":"admin", "password": "admin"}'
+
+pkill -f manager-api
+
+if [[ `grep -c "/apisix/admin/user/login" ./logs/access.log` -eq '0' ]]; then
+    echo "failed: failed to write access log"
+    exit 1
+fi
+
+
 # etcd basic auth
 # add root user
 curl -L http://localhost:2379/v3/auth/user/add -d '{"name": "root", "password": "root"}'