Merge pull request '日志优化' (#125) from log-enhance into develop

Reviewed-on: https://git.openi.org.cn/OpenI/aiforge/pulls/125
Reviewed-by: avadesian <xuchx@pcl.ac.cn>

modules/log/logger.go

@@ -67,19 +67,43 @@ func (l *Logger) Log(skip int, level Level, format string, v ...interface{}) err
 			caller = fn.Name() + "()"
 		}
 	}
-	msg := format
-	if len(v) > 0 {
-		msg = ColorSprintf(format, v...)
-	}
+
 	stack := ""
 	if l.GetStacktraceLevel() <= level {
 		stack = Stack(skip + 1)
 	}
-	return l.SendLog(level, caller, strings.TrimPrefix(filename, prefix), line, msg, stack)
+
+	msg := format
+	if len(v) > 0 {
+		switch v[len(v)-1].(type) {
+		case string:
+			if !strings.Contains(v[len(v)-1].(string), "-") {
+				//has no msgID
+				msg = ColorSprintf(format, v...)
+				return l.SendLog(level, caller, strings.TrimPrefix(filename, prefix), line, msg, "", stack)
+			} else {
+				if len(v) > 1 {
+					args := make([]interface{}, len(v)-1)
+					for i := 0; i < len(v)-1; i++ {
+						args[i] = v[i]
+					}
+					msg = ColorSprintf(format, args...)
+				}
+				return l.SendLog(level, caller, strings.TrimPrefix(filename, prefix), line, msg, v[len(v)-1].(string), stack)
+			}
+		default:
+			//has no msgID
+			msg = ColorSprintf(format, v...)
+			return l.SendLog(level, caller, strings.TrimPrefix(filename, prefix), line, msg, "", stack)
+		}
+	} else {
+		//has no msgID
+		return l.SendLog(level, caller, strings.TrimPrefix(filename, prefix), line, msg, "", stack)
+	}
 }
 
 // SendLog sends a log event at the provided level with the information given
-func (l *Logger) SendLog(level Level, caller, filename string, line int, msg string, stack string) error {
+func (l *Logger) SendLog(level Level, caller, filename string, line int, msg, msgID, stack string) error {
 	if l.GetLevel() > level {
 		return nil
 	}
@@ -88,7 +112,7 @@ func (l *Logger) SendLog(level Level, caller, filename string, line int, msg str
 		caller:     caller,
 		filename:   filename,
 		line:       line,
-		msg:        msg,
+		msg:        msg + "[" + msgID + "]",
 		time:       time.Now(),
 		stacktrace: stack,
 	}

routers/repo/blockchain.go

@@ -28,14 +28,14 @@ const (
 func BlockChainIndex(ctx *context.Context) {
 	repo := ctx.Repo.Repository
 	if repo.ContractAddress == "" || ctx.User.PublicKey == "" {
-		log.Error("the repo(%d) or the user(%d) has not been initialized in block_chain", repo.RepoID, ctx.User.ID)
+		log.Error("the repo(%d) or the user(%d) has not been initialized in block_chain", repo.RepoID, ctx.User.ID, ctx.Data["msgID"])
 		ctx.HTML(http.StatusInternalServerError, tplBlockChainIndex)
 		return
 	}
 
 	res, err := blockchain.GetBalance(repo.ContractAddress, ctx.User.PublicKey)
 	if err != nil {
-		log.Error("GetBalance(%s) failed:%v", ctx.User.PublicKey, err)
+		log.Error("GetBalance(%s) failed:%s", ctx.User.PublicKey, err, ctx.Data["msgID"])
 		ctx.HTML(http.StatusInternalServerError, tplBlockChainIndex)
 		return
 	}
@@ -52,7 +52,7 @@ func HandleBlockChainInitNotify(ctx *context.Context) {
 
 	repo, err := models.GetRepositoryByID(req.RepoId)
 	if err != nil {
-		log.Error("GetRepositoryByID failed:", err.Error())
+		log.Error("GetRepositoryByID failed:%v", err.Error(), ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"code":    "-1",
 			"message": "internal error",
@@ -61,7 +61,7 @@ func HandleBlockChainInitNotify(ctx *context.Context) {
 	}
 
 	if repo.BlockChainStatus == models.RepoBlockChainSuccess && len(repo.ContractAddress) != 0 {
-		log.Error("the repo has been RepoBlockChainSuccess:", req.RepoId)
+		log.Error("the repo has been RepoBlockChainSuccess:%d", req.RepoId, ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"code":    "-1",
 			"message": "the repo has been RepoBlockChainSuccess",
@@ -73,7 +73,7 @@ func HandleBlockChainInitNotify(ctx *context.Context) {
 	repo.ContractAddress = req.ContractAddress
 
 	if err = models.UpdateRepositoryCols(repo, "block_chain_status", "contract_address"); err != nil {
-		log.Error("UpdateRepositoryCols failed:", err.Error())
+		log.Error("UpdateRepositoryCols failed:%v", err.Error(), ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"code":    "-1",
 			"message": "internal error",
@@ -91,7 +91,7 @@ func HandleBlockChainCommitNotify(ctx *context.Context) {
 	var req BlockChainCommitNotify
 	data, _ := ctx.Req.Body().Bytes()
 	if err := json.Unmarshal(data, &req); err != nil {
-		log.Error("json.Unmarshal failed:", err.Error())
+		log.Error("json.Unmarshal failed:%v", err.Error(), ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"code":    "-1",
 			"message": "response data error",
@@ -101,7 +101,7 @@ func HandleBlockChainCommitNotify(ctx *context.Context) {
 
 	blockChain, err := models.GetBlockChainByCommitID(req.CommitID)
 	if err != nil {
-		log.Error("GetRepositoryByID failed:", err.Error())
+		log.Error("GetRepositoryByID failed:%v", err.Error(), ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"code":    "-1",
 			"message": "internal error",
@@ -110,7 +110,7 @@ func HandleBlockChainCommitNotify(ctx *context.Context) {
 	}
 
 	if blockChain.Status == models.BlockChainCommitSuccess {
-		log.Error("the commit has been BlockChainCommitReady:", blockChain.RepoID)
+		log.Error("the commit has been BlockChainCommitReady:%s", blockChain.RepoID, ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"code":    "-1",
 			"message": "the commit has been BlockChainCommitReady",
@@ -122,7 +122,7 @@ func HandleBlockChainCommitNotify(ctx *context.Context) {
 	blockChain.TransactionHash = req.TransactionHash
 
 	if err = models.UpdateBlockChainCols(blockChain, "status", "transaction_hash"); err != nil {
-		log.Error("UpdateBlockChainCols failed:", err.Error())
+		log.Error("UpdateBlockChainCols failed:%v", err.Error(), ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"code":    "-1",
 			"message": "internal error",

routers/repo/cloudbrain.go

@@ -96,7 +96,7 @@ func CloudBrainNew(ctx *context.Context) {
 	result, err := cloudbrain.GetImages()
 	if err != nil {
 		ctx.Data["error"] = err.Error()
-		log.Error("cloudbrain.GetImages failed:", err.Error())
+		log.Error("cloudbrain.GetImages failed:", err.Error(), ctx.Data["msgID"])
 	}
 
 	for i, payload := range result.Payload.ImageInfo {
@@ -112,7 +112,7 @@ func CloudBrainNew(ctx *context.Context) {
 	resultPublic, err := cloudbrain.GetPublicImages()
 	if err != nil {
 		ctx.Data["error"] = err.Error()
-		log.Error("cloudbrain.GetPublicImages failed:", err.Error())
+		log.Error("cloudbrain.GetPublicImages failed:", err.Error(), ctx.Data["msgID"])
 	}
 
 	for i, payload := range resultPublic.Payload.ImageInfo {
@@ -164,7 +164,7 @@ func CloudBrainCreate(ctx *context.Context, form auth.CreateCloudBrainForm) {
 	codePath := setting.JobPath + jobName + cloudbrain.CodeMountPath
 
 	if jobType != string(models.JobTypeBenchmark) && jobType != string(models.JobTypeDebug) && jobType != string(models.JobTypeSnn4imagenet) {
-		log.Error("jobtype error:", jobType)
+		log.Error("jobtype error:", jobType, ctx.Data["msgID"])
 		ctx.RenderWithErr("jobtype error", tplCloudBrainNew, &form)
 		return
 	}
@@ -267,7 +267,7 @@ func CloudBrainCommitImage(ctx *context.Context, form auth.CommitImageCloudBrain
 		ImageTag:         form.Tag,
 	})
 	if err != nil {
-		log.Error("CommitImage(%s) failed:", task.JobName, err.Error())
+		log.Error("CommitImage(%s) failed:%v", task.JobName, err.Error(), ctx.Data["msgID"])
 		ctx.JSON(200, map[string]string{
 			"result_code": "-1",
 			"error_msg":   "CommitImage failed",
@@ -290,14 +290,14 @@ func CloudBrainStop(ctx *context.Context) {
 	}
 
 	if task.Status == string(models.JobStopped) {
-		log.Error("the job(%s) has been stopped", task.JobName)
+		log.Error("the job(%s) has been stopped", task.JobName, ctx.Data["msgID"])
 		ctx.ServerError("the job has been stopped", errors.New("the job has been stopped"))
 		return
 	}
 
 	err = cloudbrain.StopJob(jobID)
 	if err != nil {
-		log.Error("StopJob(%s) failed:%v", task.JobName, err.Error())
+		log.Error("StopJob(%s) failed:%v", task.JobName, err.Error(), ctx.Data["msgID"])
 		ctx.ServerError("StopJob failed", err)
 		return
 	}
@@ -321,7 +321,7 @@ func CloudBrainDel(ctx *context.Context) {
 	}
 
 	if task.Status != string(models.JobStopped) {
-		log.Error("the job(%s) has not been stopped", task.JobName)
+		log.Error("the job(%s) has not been stopped", task.JobName, ctx.Data["msgID"])
 		ctx.ServerError("the job has not been stopped", errors.New("the job has not been stopped"))
 		return
 	}
@@ -343,7 +343,7 @@ func CloudBrainShowModels(ctx *context.Context) {
 	dirArray := strings.Split(parentDir, "/")
 	task, err := models.GetCloudbrainByJobID(jobID)
 	if err != nil {
-		log.Error("no such job!")
+		log.Error("no such job!", ctx.Data["msgID"])
 		ctx.ServerError("no such job:", err)
 		return
 	}
@@ -351,7 +351,7 @@ func CloudBrainShowModels(ctx *context.Context) {
 	//get dirs
 	dirs, err := getModelDirs(task.JobName, parentDir)
 	if err != nil {
-		log.Error("getModelDirs failed:", err.Error())
+		log.Error("getModelDirs failed:%v", err.Error(), ctx.Data["msgID"])
 		ctx.ServerError("getModelDirs failed:", err)
 		return
 	}
@@ -359,7 +359,7 @@ func CloudBrainShowModels(ctx *context.Context) {
 	var fileInfos []FileInfo
 	err = json.Unmarshal([]byte(dirs), &fileInfos)
 	if err != nil {
-		log.Error("json.Unmarshal failed:", err.Error())
+		log.Error("json.Unmarshal failed:%v", err.Error(), ctx.Data["msgID"])
 		ctx.ServerError("json.Unmarshal failed:", err)
 		return
 	}
@@ -390,7 +390,7 @@ func CloudBrainDownloadModel(ctx *context.Context) {
 	filePath := "jobs/" +jobName + "/model/" + parentDir
 	url, err := storage.Attachments.PresignedGetURL(filePath, fileName)
 	if err != nil {
-		log.Error("PresignedGetURL failed: %v", err.Error())
+		log.Error("PresignedGetURL failed: %v", err.Error(), ctx.Data["msgID"])
 		ctx.ServerError("PresignedGetURL", err)
 		return
 	}
@@ -411,7 +411,7 @@ func GetRate(ctx *context.Context) {
 	} else if job.JobType == string(models.JobTypeSnn4imagenet) {
 		ctx.Redirect(setting.Snn4imagenetServerHost)
 	} else {
-		log.Error("JobType error:", job.JobType)
+		log.Error("JobType error:%s", job.JobType, ctx.Data["msgID"])
 	}
 }
 

routers/routes/routes.go

@@ -49,6 +49,7 @@ import (
 	"gitea.com/macaron/session"
 	"gitea.com/macaron/toolbox"
 	"github.com/prometheus/client_golang/prometheus"
+	gouuid "github.com/satori/go.uuid"
 	"github.com/tstranex/u2f"
 )
 
@@ -85,7 +86,7 @@ func setupAccessLogger(m *macaron.Macaron) {
 			log.Error("Could not set up macaron access logger: %v", err.Error())
 		}
 
-		err = logger.SendLog(log.INFO, "", "", 0, buf.String(), "")
+		err = logger.SendLog(log.INFO, "", "", 0, buf.String(), ctx.Data["msgID"].(string), "")
 		if err != nil {
 			log.Error("Could not set up macaron access logger: %v", err.Error())
 		}
@@ -107,6 +108,24 @@ func RouterHandler(level log.Level) func(ctx *macaron.Context) {
 	}
 }
 
+// SetLogMsgID set msgID in Context
+func SetLogMsgID() func(ctx *macaron.Context) {
+	return func(ctx *macaron.Context) {
+		start := time.Now()
+
+		uuid := gouuid.NewV4().String()
+		ctx.Data["MsgID"] = uuid
+
+		log.Info("Started %s %s for %s", log.ColoredMethod(ctx.Req.Method), ctx.Req.URL.RequestURI(), ctx.RemoteAddr(), ctx.Data["MsgID"])
+
+		rw := ctx.Resp.(macaron.ResponseWriter)
+		ctx.Next()
+
+		status := rw.Status()
+		log.Info("Completed %s %s %v %s in %v", log.ColoredMethod(ctx.Req.Method), ctx.Req.URL.RequestURI(), log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(rw.Status())), log.ColoredTime(time.Since(start)), ctx.Data["MsgID"])
+	}
+}
+
 // NewMacaron initializes Macaron instance.
 func NewMacaron() *macaron.Macaron {
 	gob.Register(&u2f.Challenge{})
@@ -125,6 +144,7 @@ func NewMacaron() *macaron.Macaron {
 			m.Use(macaron.Logger())
 		}
 	}
+	m.Use(SetLogMsgID())
 	// Access Logger is similar to Router Log but more configurable and by default is more like the NCSA Common Log format
 	if setting.EnableAccessLog {
 		setupAccessLogger(m)