chore: enrich error log (#977)

* chore: enrich error log

* test: add test case for log caller

* fix: test error

* test

* fix: use invalid ip

* fix: cli test error

* fix: typo

api/filter/authentication.go

@@ -24,6 +24,7 @@ import (
 	"github.com/gin-gonic/gin"
 
 	"github.com/apisix/manager-api/conf"
+	"github.com/apisix/manager-api/log"
 )
 
 func Authentication() gin.HandlerFunc {
@@ -42,27 +43,32 @@ func Authentication() gin.HandlerFunc {
 			}
 
 			if err != nil || !token.Valid {
+				log.Warnf("token validate failed: %s, %v", err, token.Valid)
 				c.AbortWithStatusJSON(http.StatusUnauthorized, errResp)
 				return
 			}
 
 			claims, ok := token.Claims.(*jwt.StandardClaims)
 			if !ok {
+				log.Warnf("token validate failed: %s, %v", err, token.Valid)
 				c.AbortWithStatusJSON(http.StatusUnauthorized, errResp)
 				return
 			}
 
 			if err := token.Claims.Valid(); err != nil {
+				log.Warnf("token claims validate failed: %s", err)
 				c.AbortWithStatusJSON(http.StatusUnauthorized, errResp)
 				return
 			}
 
 			if claims.Subject == "" {
+				log.Warn("token claims subject empty")
 				c.AbortWithStatusJSON(http.StatusUnauthorized, errResp)
 				return
 			}
 
 			if _, ok := conf.UserList[claims.Subject]; !ok {
+				log.Warnf("user not exists by token claims subject %s", claims.Subject)
 				c.AbortWithStatusJSON(http.StatusUnauthorized, errResp)
 				return
 			}

api/internal/core/entity/format.go

@@ -26,7 +26,7 @@ import (
 func mapKV2Node(key string, val float64) (*Node, error) {
 	host, port, err := net.SplitHostPort(key)
 	if err != nil {
-		log.Warn("split host port fail: %s", err)
+		log.Errorf("split host port fail: %s", err)
 		return nil, err
 	}
 

api/internal/core/storage/etcd.go

@@ -21,9 +21,11 @@ import (
 	"fmt"
 	"time"
 
+	"go.etcd.io/etcd/clientv3"
+
 	"github.com/apisix/manager-api/conf"
 	"github.com/apisix/manager-api/internal/utils"
-	"go.etcd.io/etcd/clientv3"
+	"github.com/apisix/manager-api/log"
 )
 
 var (
@@ -41,7 +43,8 @@ func InitETCDClient(etcdConf *conf.Etcd) error {
 		Password:    etcdConf.Password,
 	})
 	if err != nil {
-		return fmt.Errorf("init etcd failed: %w", err)
+		log.Errorf("init etcd failed: %s", err)
+		return fmt.Errorf("init etcd failed: %s", err)
 	}
 	Client = cli
 	utils.AppendToClosers(Close)
@@ -50,6 +53,7 @@ func InitETCDClient(etcdConf *conf.Etcd) error {
 
 func Close() error {
 	if err := Client.Close(); err != nil {
+		log.Errorf("etcd client close failed: %s", err)
 		return err
 	}
 	return nil
@@ -58,9 +62,11 @@ func Close() error {
 func (s *EtcdV3Storage) Get(ctx context.Context, key string) (string, error) {
 	resp, err := Client.Get(ctx, key)
 	if err != nil {
-		return "", fmt.Errorf("etcd get failed: %w", err)
+		log.Errorf("etcd get failed: %s", err)
+		return "", fmt.Errorf("etcd get failed: %s", err)
 	}
 	if resp.Count == 0 {
+		log.Warnf("key: %s is not found", key)
 		return "", fmt.Errorf("key: %s is not found", key)
 	}
 
@@ -70,7 +76,8 @@ func (s *EtcdV3Storage) Get(ctx context.Context, key string) (string, error) {
 func (s *EtcdV3Storage) List(ctx context.Context, key string) ([]string, error) {
 	resp, err := Client.Get(ctx, key, clientv3.WithPrefix())
 	if err != nil {
-		return nil, fmt.Errorf("etcd get failed: %w", err)
+		log.Errorf("etcd get failed: %s", err)
+		return nil, fmt.Errorf("etcd get failed: %s", err)
 	}
 	var ret []string
 	for i := range resp.Kvs {
@@ -83,15 +90,17 @@ func (s *EtcdV3Storage) List(ctx context.Context, key string) ([]string, error)
 func (s *EtcdV3Storage) Create(ctx context.Context, key, val string) error {
 	_, err := Client.Put(ctx, key, val)
 	if err != nil {
-		return fmt.Errorf("etcd put failed: %w", err)
+		log.Errorf("etcd put failed: %s", err)
+		return fmt.Errorf("etcd put failed: %s", err)
 	}
 	return nil
 }
 
 func (s *EtcdV3Storage) Update(ctx context.Context, key, val string) error {
 	_, err := Client.Put(ctx, key, val)
 	if err != nil {
-		return fmt.Errorf("etcd put failed: %w", err)
+		log.Errorf("etcd put failed: %s", err)
+		return fmt.Errorf("etcd put failed: %s", err)
 	}
 	return nil
 }
@@ -100,9 +109,11 @@ func (s *EtcdV3Storage) BatchDelete(ctx context.Context, keys []string) error {
 	for i := range keys {
 		resp, err := Client.Delete(ctx, keys[i])
 		if err != nil {
-			return fmt.Errorf("delete etcd key[%s] failed: %w", keys[i], err)
+			log.Errorf("delete etcd key[%s] failed: %s", keys[i], err)
+			return fmt.Errorf("delete etcd key[%s] failed: %s", keys[i], err)
 		}
 		if resp.Deleted == 0 {
+			log.Warnf("key: %s is not found", keys[i])
 			return fmt.Errorf("key: %s is not found", keys[i])
 		}
 	}
@@ -132,6 +143,7 @@ func (s *EtcdV3Storage) Watch(ctx context.Context, key string) <-chan WatchRespo
 				output.Events = append(output.Events, e)
 			}
 			if output.Canceled {
+				log.Error("channel canceled")
 				output.Error = fmt.Errorf("channel canceled")
 			}
 			ch <- output

api/internal/core/store/store.go

@@ -61,23 +61,23 @@ type GenericStoreOption struct {
 
 func NewGenericStore(opt GenericStoreOption) (*GenericStore, error) {
 	if opt.BasePath == "" {
-		log.Warn("base path empty")
+		log.Error("base path empty")
 		return nil, fmt.Errorf("base path can not be empty")
 	}
 	if opt.ObjType == nil {
-		log.Warn("object type is nil")
+		log.Errorf("object type is nil")
 		return nil, fmt.Errorf("object type can not be nil")
 	}
 	if opt.KeyFunc == nil {
-		log.Warn("key func is nil")
+		log.Error("key func is nil")
 		return nil, fmt.Errorf("key func can not be nil")
 	}
 
 	if opt.ObjType.Kind() == reflect.Ptr {
 		opt.ObjType = opt.ObjType.Elem()
 	}
 	if opt.ObjType.Kind() != reflect.Struct {
-		log.Warn("obj type is invalid")
+		log.Error("obj type is invalid")
 		return nil, fmt.Errorf("obj type is invalid")
 	}
 	s := &GenericStore{
@@ -111,15 +111,15 @@ func (s *GenericStore) Init() error {
 	go func() {
 		for event := range ch {
 			if event.Canceled {
-				log.Warnf("watch failed: %w", event.Error)
+				log.Warnf("watch failed: %s", event.Error)
 			}
 
 			for i := range event.Events {
 				switch event.Events[i].Type {
 				case storage.EventTypePut:
 					objPtr, err := s.StringToObjPtr(event.Events[i].Value)
 					if err != nil {
-						log.Warnf("value convert to obj failed: %w", err)
+						log.Warnf("value convert to obj failed: %s", err)
 						continue
 					}
 					s.cache.Store(event.Events[i].Key[len(s.opt.BasePath)+1:], objPtr)
@@ -221,7 +221,7 @@ func (s *GenericStore) List(input ListInput) (*ListOutput, error) {
 func (s *GenericStore) ingestValidate(obj interface{}) (err error) {
 	if s.opt.Validator != nil {
 		if err := s.opt.Validator.Validate(obj); err != nil {
-			log.Infof("data validate fail: %w", err)
+			log.Errorf("data validate failed: %s", err)
 			return err
 		}
 	}
@@ -259,7 +259,7 @@ func (s *GenericStore) Create(ctx context.Context, obj interface{}) error {
 
 	bs, err := json.Marshal(obj)
 	if err != nil {
-		log.Warnf("json marshal failed: %s", err)
+		log.Errorf("json marshal failed: %s", err)
 		return fmt.Errorf("json marshal failed: %s", err)
 	}
 	if err := s.Stg.Create(ctx, s.GetObjStorageKey(obj), string(bs)); err != nil {
@@ -296,7 +296,7 @@ func (s *GenericStore) Update(ctx context.Context, obj interface{}, createIfNotE
 
 	bs, err := json.Marshal(obj)
 	if err != nil {
-		log.Warnf("json marshal failed: %s", err)
+		log.Errorf("json marshal failed: %s", err)
 		return fmt.Errorf("json marshal failed: %s", err)
 	}
 	if err := s.Stg.Update(ctx, s.GetObjStorageKey(obj), string(bs)); err != nil {
@@ -324,8 +324,8 @@ func (s *GenericStore) StringToObjPtr(str string) (interface{}, error) {
 	objPtr := reflect.New(s.opt.ObjType)
 	err := json.Unmarshal([]byte(str), objPtr.Interface())
 	if err != nil {
-		log.Warnf("json marshal failed: %s", err)
-		return nil, fmt.Errorf("json unmarshal failed: %w", err)
+		log.Errorf("json marshal failed: %s", err)
+		return nil, fmt.Errorf("json unmarshal failed: %s", err)
 	}
 
 	return objPtr.Interface(), nil

api/internal/core/store/storehub.go

@@ -51,11 +51,11 @@ func InitStore(key HubKey, opt GenericStoreOption) error {
 	}
 	s, err := NewGenericStore(opt)
 	if err != nil {
-		log.Warnf("NewGenericStore error: %w", err)
+		log.Errorf("NewGenericStore error: %s", err)
 		return err
 	}
 	if err := s.Init(); err != nil {
-		log.Warnf("GenericStore init error: %w", err)
+		log.Errorf("GenericStore init error: %s", err)
 		return err
 	}
 

api/internal/core/store/validate.go

@@ -40,11 +40,11 @@ type JsonSchemaValidator struct {
 func NewJsonSchemaValidator(jsonPath string) (Validator, error) {
 	bs, err := ioutil.ReadFile(jsonPath)
 	if err != nil {
-		return nil, fmt.Errorf("get abs path failed: %w", err)
+		return nil, fmt.Errorf("get abs path failed: %s", err)
 	}
 	s, err := gojsonschema.NewSchema(gojsonschema.NewStringLoader(string(bs)))
 	if err != nil {
-		return nil, fmt.Errorf("new schema failed: %w", err)
+		return nil, fmt.Errorf("new schema failed: %s", err)
 	}
 	return &JsonSchemaValidator{
 		schema: s,
@@ -54,7 +54,7 @@ func NewJsonSchemaValidator(jsonPath string) (Validator, error) {
 func (v *JsonSchemaValidator) Validate(obj interface{}) error {
 	ret, err := v.schema.Validate(gojsonschema.NewGoLoader(obj))
 	if err != nil {
-		return fmt.Errorf("validate failed: %w", err)
+		return fmt.Errorf("validate failed: %s", err)
 	}
 
 	if !ret.Valid() {
@@ -77,14 +77,14 @@ type APISIXJsonSchemaValidator struct {
 func NewAPISIXJsonSchemaValidator(jsonPath string) (Validator, error) {
 	schemaDef := conf.Schema.Get(jsonPath).String()
 	if schemaDef == "" {
-		log.Warnf("schema validate failed: schema not found, path: %s", jsonPath)
+		log.Errorf("schema validate failed: schema not found, path: %s", jsonPath)
 		return nil, fmt.Errorf("schema validate failed: schema not found, path: %s", jsonPath)
 	}
 
 	s, err := gojsonschema.NewSchema(gojsonschema.NewStringLoader(schemaDef))
 	if err != nil {
-		log.Warnf("new schema failed: %w", err)
-		return nil, fmt.Errorf("new schema failed: %w", err)
+		log.Errorf("new schema failed: %s", err)
+		return nil, fmt.Errorf("new schema failed: %s", err)
 	}
 	return &APISIXJsonSchemaValidator{
 		schema: s,
@@ -136,12 +136,12 @@ func cHashKeySchemaCheck(upstream *entity.UpstreamDef) error {
 
 	s, err := gojsonschema.NewSchema(gojsonschema.NewStringLoader(schemaDef))
 	if err != nil {
-		return fmt.Errorf("schema validate failed: %w", err)
+		return fmt.Errorf("schema validate failed: %s", err)
 	}
 
 	ret, err := s.Validate(gojsonschema.NewGoLoader(upstream.Key))
 	if err != nil {
-		return fmt.Errorf("schema validate failed: %w", err)
+		return fmt.Errorf("schema validate failed: %s", err)
 	}
 
 	if !ret.Valid() {
@@ -231,8 +231,8 @@ func checkConf(reqBody interface{}) error {
 func (v *APISIXJsonSchemaValidator) Validate(obj interface{}) error {
 	ret, err := v.schema.Validate(gojsonschema.NewGoLoader(obj))
 	if err != nil {
-		log.Warnf("schema validate failed: %w", err)
-		return fmt.Errorf("schema validate failed: %w", err)
+		log.Errorf("schema validate failed: %s", err)
+		return fmt.Errorf("schema validate failed: %s", err)
 	}
 
 	if !ret.Valid() {
@@ -257,8 +257,9 @@ func (v *APISIXJsonSchemaValidator) Validate(obj interface{}) error {
 		if schemaValue == nil && schemaType == "consumer_schema" {
 			schemaValue = conf.Schema.Get("plugins." + pluginName + ".schema").Value()
 		}
+
 		if schemaValue == nil {
-			log.Warnf("schema validate failed: schema not found,  %s, %s", "plugins."+pluginName, schemaType)
+			log.Errorf("schema validate failed: schema not found,  %s, %s", "plugins."+pluginName, schemaType)
 			return fmt.Errorf("schema validate failed: schema not found, path: %s", "plugins."+pluginName)
 		}
 		schemaMap := schemaValue.(map[string]interface{})
@@ -270,8 +271,8 @@ func (v *APISIXJsonSchemaValidator) Validate(obj interface{}) error {
 
 		s, err := gojsonschema.NewSchema(gojsonschema.NewBytesLoader(schemaByte))
 		if err != nil {
-			log.Warnf("init schema validate failed: %w", err)
-			return fmt.Errorf("schema validate failed: %w", err)
+			log.Errorf("init schema validate failed: %s", err)
+			return fmt.Errorf("schema validate failed: %s", err)
 		}
 
 		// check property disable, if is bool, remove from json schema checking
@@ -288,7 +289,8 @@ func (v *APISIXJsonSchemaValidator) Validate(obj interface{}) error {
 		// check schema
 		ret, err := s.Validate(gojsonschema.NewGoLoader(conf))
 		if err != nil {
-			return fmt.Errorf("schema validate failed: %w", err)
+			log.Errorf("schema validate failed: %s", err)
+			return fmt.Errorf("schema validate failed: %s", err)
 		}
 
 		// put the value back to the property disable

api/log/zap.go

@@ -33,7 +33,7 @@ func init() {
 	logLevel := getLogLevel()
 	core := zapcore.NewCore(encoder, writeSyncer, logLevel)
 
-	zapLogger := zap.New(core, zap.AddCaller())
+	zapLogger := zap.New(core, zap.AddCaller(), zap.AddCallerSkip(2))
 
 	logger = zapLogger.Sugar()
 }

api/main.go

@@ -45,6 +45,7 @@ func main() {
 		newMws = append(newMws, mws[1:]...)
 		return newMws
 	}
+
 	if err := storage.InitETCDClient(conf.ETCDConfig); err != nil {
 		log.Errorf("init etcd client fail: %w", err)
 		panic(err)
@@ -63,15 +64,15 @@ func main() {
 		WriteTimeout: time.Duration(5000) * time.Millisecond,
 	}
 
-	log.Infof("The Manager API is listening on %s ", addr)
+	log.Infof("The Manager API is listening on %s", addr)
 
 	quit := make(chan os.Signal, 1)
 	signal.Notify(quit, syscall.SIGINT, syscall.SIGTERM)
 
 	go func() {
 		if err := s.ListenAndServe(); err != nil && err != http.ErrServerClosed {
 			utils.CloseAll()
-			log.Fatalf("listen and serv fail: %w", err)
+			log.Fatalf("listen and serv fail: %s", err)
 		}
 	}()
 
@@ -82,7 +83,7 @@ func main() {
 	defer cancel()
 
 	if err := s.Shutdown(ctx); err != nil {
-		log.Errorf("Shutting down server error: %w", err)
+		log.Errorf("Shutting down server error: %s", err)
 	}
 
 	log.Infof("The Manager API server exited")